feat(loggin): improved http request panic handling

pkg/api/api.go

@@ -240,6 +240,9 @@ func Register(r *macaron.Macaron) {
 		// metrics
 		r.Get("/metrics", wrap(GetInternalMetrics))
 
+		// error test
+		r.Get("/metrics/error", wrap(GenerateError))
+
 	}, reqSignedIn)
 
 	// admin api

pkg/api/metrics.go

@@ -87,3 +87,9 @@ func GetInternalMetrics(c *middleware.Context) Response {
 		},
 	}
 }
+
+// Genereates a index out of range error
+func GenerateError(c *middleware.Context) Response {
+	var array []string
+	return Json(200, array[20])
+}

pkg/cmd/grafana-server/web.go

@@ -26,7 +26,7 @@ func newMacaron() *macaron.Macaron {
 	m := macaron.New()
 
 	m.Use(middleware.Logger())
-	m.Use(macaron.Recovery())
+	m.Use(middleware.Recovery())
 
 	if setting.EnableGzip {
 		m.Use(middleware.Gziper())
@@ -34,7 +34,7 @@ func newMacaron() *macaron.Macaron {
 
 	for _, route := range plugins.StaticRoutes {
 		pluginRoute := path.Join("/public/plugins/", route.PluginId)
-		log.Debug("Plugins: Adding route %s -> %s", pluginRoute, route.Directory)
+		logger.Debug("Plugins: Adding route", "route", pluginRoute, "dir", route.Directory)
 		mapStatic(m, route.Directory, "", pluginRoute)
 	}
 

pkg/log/log.go

@@ -15,61 +15,61 @@ import (
 	"github.com/inconshreveable/log15"
 )
 
-var rootLogger log15.Logger
+var Root log15.Logger
 var loggersToClose []DisposableHandler
 
 func init() {
 	loggersToClose = make([]DisposableHandler, 0)
-	rootLogger = log15.Root()
+	Root = log15.Root()
 }
 
 func New(logger string, ctx ...interface{}) Logger {
 	params := append([]interface{}{"logger", logger}, ctx...)
-	return rootLogger.New(params...)
+	return Root.New(params...)
 }
 
 func Trace(format string, v ...interface{}) {
-	rootLogger.Debug(fmt.Sprintf(format, v))
+	Root.Debug(fmt.Sprintf(format, v))
 }
 
 func Debug(format string, v ...interface{}) {
-	rootLogger.Debug(fmt.Sprintf(format, v))
+	Root.Debug(fmt.Sprintf(format, v))
 }
 
 func Debug2(message string, v ...interface{}) {
-	rootLogger.Debug(message, v...)
+	Root.Debug(message, v...)
 }
 
 func Info(format string, v ...interface{}) {
-	rootLogger.Info(fmt.Sprintf(format, v))
+	Root.Info(fmt.Sprintf(format, v))
 }
 
 func Info2(message string, v ...interface{}) {
-	rootLogger.Info(message, v...)
+	Root.Info(message, v...)
 }
 
 func Warn(format string, v ...interface{}) {
-	rootLogger.Warn(fmt.Sprintf(format, v))
+	Root.Warn(fmt.Sprintf(format, v))
 }
 
 func Warn2(message string, v ...interface{}) {
-	rootLogger.Warn(message, v...)
+	Root.Warn(message, v...)
 }
 
 func Error(skip int, format string, v ...interface{}) {
-	rootLogger.Error(fmt.Sprintf(format, v))
+	Root.Error(fmt.Sprintf(format, v))
 }
 
 func Error2(message string, v ...interface{}) {
-	rootLogger.Error(message, v...)
+	Root.Error(message, v...)
 }
 
 func Critical(skip int, format string, v ...interface{}) {
-	rootLogger.Crit(fmt.Sprintf(format, v))
+	Root.Crit(fmt.Sprintf(format, v))
 }
 
 func Fatal(skip int, format string, v ...interface{}) {
-	rootLogger.Crit(fmt.Sprintf(format, v))
+	Root.Crit(fmt.Sprintf(format, v))
 	Close()
 	os.Exit(1)
 }
@@ -95,7 +95,7 @@ func getLogLevel(key string, defaultName string, cfg *ini.File) (string, log15.L
 
 	level, ok := logLevels[levelName]
 	if !ok {
-		rootLogger.Error("Unknown log level", "level", levelName)
+		Root.Error("Unknown log level", "level", levelName)
 	}
 
 	return levelName, level
@@ -111,7 +111,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
 		mode = strings.TrimSpace(mode)
 		sec, err := cfg.GetSection("log." + mode)
 		if err != nil {
-			rootLogger.Error("Unknown log mode", "mode", mode)
+			Root.Error("Unknown log mode", "mode", mode)
 		}
 
 		// Log level.
@@ -134,7 +134,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
 			fileHandler.Init()
 
 			loggersToClose = append(loggersToClose, fileHandler)
-			handlers = append(handlers, log15.LazyHandler(fileHandler))
+			handlers = append(handlers, log15.LvlFilterHandler(level, fileHandler))
 
 			// case "conn":
 			// 	LogConfigs[i] = util.DynMap{
@@ -170,5 +170,5 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
 		}
 	}
 
-	rootLogger.SetHandler(log15.MultiHandler(handlers...))
+	Root.SetHandler(log15.MultiHandler(handlers...))
 }

pkg/middleware/recovery.go

+// Copyright 2013 Martini Authors
+// Copyright 2014 The Macaron Authors
+//
+// 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 middleware
+
+import (
+	"bytes"
+	"fmt"
+	"io/ioutil"
+	"net/http"
+	"runtime"
+
+	"gopkg.in/macaron.v1"
+
+	"github.com/go-macaron/inject"
+	"github.com/grafana/grafana/pkg/log"
+	"github.com/grafana/grafana/pkg/setting"
+)
+
+const (
+	panicHtml = `<html>
+<head><title>PANIC: %s</title>
+<meta charset="utf-8" />
+<style type="text/css">
+html, body {
+	font-family: "Roboto", sans-serif;
+	color: #333333;
+	background-color: #ea5343;
+	margin: 0px;
+}
+h1 {
+	color: #d04526;
+	background-color: #ffffff;
+	padding: 20px;
+	border-bottom: 1px dashed #2b3848;
+}
+pre {
+	margin: 20px;
+	padding: 20px;
+	border: 2px solid #2b3848;
+	background-color: #ffffff;
+	white-space: pre-wrap;       /* css-3 */
+	white-space: -moz-pre-wrap;  /* Mozilla, since 1999 */
+	white-space: -pre-wrap;      /* Opera 4-6 */
+	white-space: -o-pre-wrap;    /* Opera 7 */
+	word-wrap: break-word;       /* Internet Explorer 5.5+ */
+}
+</style>
+</head><body>
+<h1>PANIC</h1>
+<pre style="font-weight: bold;">%s</pre>
+<pre>%s</pre>
+</body>
+</html>`
+)
+
+var (
+	dunno     = []byte("???")
+	centerDot = []byte("·")
+	dot       = []byte(".")
+	slash     = []byte("/")
+)
+
+// stack returns a nicely formated stack frame, skipping skip frames
+func stack(skip int) []byte {
+	buf := new(bytes.Buffer) // the returned data
+	// As we loop, we open files and read them. These variables record the currently
+	// loaded file.
+	var lines [][]byte
+	var lastFile string
+	for i := skip; ; i++ { // Skip the expected number of frames
+		pc, file, line, ok := runtime.Caller(i)
+		if !ok {
+			break
+		}
+		// Print this much at least.  If we can't find the source, it won't show.
+		fmt.Fprintf(buf, "%s:%d (0x%x)\n", file, line, pc)
+		if file != lastFile {
+			data, err := ioutil.ReadFile(file)
+			if err != nil {
+				continue
+			}
+			lines = bytes.Split(data, []byte{'\n'})
+			lastFile = file
+		}
+		fmt.Fprintf(buf, "\t%s: %s\n", function(pc), source(lines, line))
+	}
+	return buf.Bytes()
+}
+
+// source returns a space-trimmed slice of the n'th line.
+func source(lines [][]byte, n int) []byte {
+	n-- // in stack trace, lines are 1-indexed but our array is 0-indexed
+	if n < 0 || n >= len(lines) {
+		return dunno
+	}
+	return bytes.TrimSpace(lines[n])
+}
+
+// function returns, if possible, the name of the function containing the PC.
+func function(pc uintptr) []byte {
+	fn := runtime.FuncForPC(pc)
+	if fn == nil {
+		return dunno
+	}
+	name := []byte(fn.Name())
+	// The name includes the path name to the package, which is unnecessary
+	// since the file name is already included.  Plus, it has center dots.
+	// That is, we see
+	//	runtime/debug.*T·ptrmethod
+	// and want
+	//	*T.ptrmethod
+	// Also the package path might contains dot (e.g. code.google.com/...),
+	// so first eliminate the path prefix
+	if lastslash := bytes.LastIndex(name, slash); lastslash >= 0 {
+		name = name[lastslash+1:]
+	}
+	if period := bytes.Index(name, dot); period >= 0 {
+		name = name[period+1:]
+	}
+	name = bytes.Replace(name, centerDot, dot, -1)
+	return name
+}
+
+// Recovery returns a middleware that recovers from any panics and writes a 500 if there was one.
+// While Martini is in development mode, Recovery will also output the panic as HTML.
+func Recovery() macaron.Handler {
+	return func(c *macaron.Context) {
+		defer func() {
+			if err := recover(); err != nil {
+				stack := stack(3)
+
+				panicLogger := log.Root
+				// try to get request logger
+				if ctx, ok := c.Data["ctx"]; ok {
+					ctxTyped := ctx.(*Context)
+					panicLogger = ctxTyped.Logger
+				}
+
+				panicLogger.Error("Request error", "error", err, "stack", string(stack))
+
+				// Lookup the current responsewriter
+				val := c.GetVal(inject.InterfaceOf((*http.ResponseWriter)(nil)))
+				res := val.Interface().(http.ResponseWriter)
+
+				// respond with panic message while in development mode
+				var body []byte
+				if setting.Env == setting.DEV {
+					res.Header().Set("Content-Type", "text/html")
+					body = []byte(fmt.Sprintf(panicHtml, err, err, stack))
+				}
+
+				res.WriteHeader(http.StatusInternalServerError)
+				if nil != body {
+					res.Write(body)
+				}
+			}
+		}()
+
+		c.Next()
+	}
+}