From 5de9071b5cae8742579f5e307df6ba6f8888234e Mon Sep 17 00:00:00 2001 From: Daniel Smith Date: Fri, 20 Jun 2014 12:56:30 -0700 Subject: [PATCH 1/3] Add improved logging: record latency & call stack on error --- pkg/apiserver/apiserver.go | 11 +++-- pkg/apiserver/logger.go | 84 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 91 insertions(+), 4 deletions(-) create mode 100644 pkg/apiserver/logger.go diff --git a/pkg/apiserver/apiserver.go b/pkg/apiserver/apiserver.go index 5059b46e46f..74b019f60d5 100644 --- a/pkg/apiserver/apiserver.go +++ b/pkg/apiserver/apiserver.go @@ -89,10 +89,12 @@ func (server *ApiServer) ServeHTTP(w http.ResponseWriter, req *http.Request) { if x := recover(); x != nil { w.WriteHeader(http.StatusInternalServerError) fmt.Fprint(w, "apiserver panic. Look in log for details.") - log.Printf("ApiServer panic'd: %#v\n%s\n", x, debug.Stack()) + log.Printf("ApiServer panic'd on %v %v: %#v\n%s\n", req.Method, req.RequestURI, x, debug.Stack()) } }() - log.Printf("%s %s", req.Method, req.RequestURI) + logger := MakeLogged(req, w) + w = logger + defer logger.Log() url, err := url.ParseRequestURI(req.RequestURI) if err != nil { server.error(err, w) @@ -113,6 +115,7 @@ func (server *ApiServer) ServeHTTP(w http.ResponseWriter, req *http.Request) { } storage := server.storage[requestParts[0]] if storage == nil { + logger.Addf("'%v' has no storage object", requestParts[0]) server.notFound(req, w) return } else { @@ -121,7 +124,7 @@ func (server *ApiServer) ServeHTTP(w http.ResponseWriter, req *http.Request) { } func (server *ApiServer) notFound(req *http.Request, w http.ResponseWriter) { - w.WriteHeader(404) + w.WriteHeader(http.StatusNotFound) fmt.Fprintf(w, "Not Found: %#v", req) } @@ -202,7 +205,7 @@ func (server *ApiServer) handleREST(parts []string, requestUrl *url.URL, req *ht server.notFound(req, w) return } - server.write(200, item, w) + server.write(http.StatusOK, item, w) default: server.notFound(req, w) } diff --git a/pkg/apiserver/logger.go b/pkg/apiserver/logger.go new file mode 100644 index 00000000000..7ac893ceeee --- /dev/null +++ b/pkg/apiserver/logger.go @@ -0,0 +1,84 @@ +/* +Copyright 2014 Google Inc. All rights reserved. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package apiserver + +import ( + "fmt" + "log" + "net/http" + "runtime" + "time" +) + +// Add a layer on top of ResponseWriter, so we can track latency and error +// message sources. +type respLogger struct { + status int + statusStack string + addedInfo string + startTime time.Time + + req *http.Request + w http.ResponseWriter +} + +// Usage: +// logger := MakeLogged(req, w) +// w = logger // Route response writing actions through w +// defer logger.Log() +func MakeLogged(req *http.Request, w http.ResponseWriter) *respLogger { + return &respLogger{ + startTime: time.Now(), + req: req, + w: w, + } +} + +// Add additional data to be logged with this request. +func (rl *respLogger) Addf(format string, data ...interface{}) { + rl.addedInfo += "\n" + fmt.Sprintf(format, data...) +} + +// Log is intended to be called once at the end of your request handler, via defer +func (rl *respLogger) Log() { + latency := time.Since(rl.startTime) + log.Printf("%s %s: (%v) %v%v%v", rl.req.Method, rl.req.RequestURI, latency, rl.status, rl.statusStack, rl.addedInfo) +} + +// Implement http.ResponseWriter +func (rl *respLogger) Header() http.Header { + return rl.w.Header() +} + +// Implement http.ResponseWriter +func (rl *respLogger) Write(b []byte) (int, error) { + return rl.w.Write(b) +} + +// Implement http.ResponseWriter +func (rl *respLogger) WriteHeader(status int) { + rl.status = status + if status != http.StatusOK && status != http.StatusAccepted { + // Only log stacks for errors + stack := make([]byte, 2048) + stack = stack[:runtime.Stack(stack, false)] + rl.statusStack = "\n" + string(stack) + } else { + rl.statusStack = "" + } + rl.w.WriteHeader(status) +} From d57531d924da0473bfc98bc2a59b38b56c9aa234 Mon Sep 17 00:00:00 2001 From: Daniel Smith Date: Fri, 20 Jun 2014 12:57:22 -0700 Subject: [PATCH 2/3] Cleanup: no need for stacked timing loops --- pkg/master/pod_cache.go | 9 +-------- 1 file changed, 1 insertion(+), 8 deletions(-) diff --git a/pkg/master/pod_cache.go b/pkg/master/pod_cache.go index d0355b360d2..0e7cecb1435 100644 --- a/pkg/master/pod_cache.go +++ b/pkg/master/pod_cache.go @@ -85,14 +85,7 @@ func (p *PodCache) UpdateAllContainers() { } } -func (p *PodCache) synchronizeContainers() { - ticker := time.Tick(p.period) - for _ = range ticker { - p.UpdateAllContainers() - } -} - // Loop runs forever, it is expected to be placed in a go routine. func (p *PodCache) Loop() { - util.Forever(func() { p.synchronizeContainers() }, 0) + util.Forever(func() { p.UpdateAllContainers() }, p.period) } From a718f6fdb899008290f5b21f7a0734558c818cc2 Mon Sep 17 00:00:00 2001 From: Daniel Smith Date: Fri, 20 Jun 2014 14:03:24 -0700 Subject: [PATCH 3/3] minor fixes to scheduler_test --- pkg/registry/scheduler_test.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/pkg/registry/scheduler_test.go b/pkg/registry/scheduler_test.go index 61edb4c3fc1..82da7b42685 100644 --- a/pkg/registry/scheduler_test.go +++ b/pkg/registry/scheduler_test.go @@ -13,6 +13,7 @@ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. */ + package registry import ( @@ -26,7 +27,7 @@ func expectSchedule(scheduler Scheduler, pod api.Pod, expected string, t *testin actual, err := scheduler.Schedule(pod) expectNoError(t, err) if actual != expected { - t.Errorf("Unexpected scheduling value: %d, expected %d", actual, expected) + t.Errorf("Unexpected scheduling value: %v, expected %v", actual, expected) } }