Backend: Improve http log messages #194

Signed-off-by: Michael Mayer <michael@liquidbytes.net>

internal/api/album.go

@@ -416,7 +416,7 @@ func AlbumThumbnail(router *gin.RouterGroup, conf *config.Config) {
 		thumbType, ok := thumb.Types[typeName]
 
 		if !ok {
-			log.Errorf("invalid type: %s", typeName)
+			log.Errorf("thumbs: invalid type \"%s\"", typeName)
 			c.Data(http.StatusBadRequest, "image/svg+xml", photoIconSvg)
 			return
 		}

internal/api/label.go

@@ -127,7 +127,7 @@ func LabelThumbnail(router *gin.RouterGroup, conf *config.Config) {
 		thumbType, ok := thumb.Types[typeName]
 
 		if !ok {
-			log.Errorf("invalid type: %s", typeName)
+			log.Errorf("thumbs: invalid type \"%s\"", typeName)
 			c.Data(http.StatusOK, "image/svg+xml", labelIconSvg)
 			return
 		}

internal/api/photo_thumbnail.go

@@ -25,7 +25,7 @@ func GetThumbnail(router *gin.RouterGroup, conf *config.Config) {
 		thumbType, ok := thumb.Types[typeName]
 
 		if !ok {
-			log.Errorf("invalid type: %s", typeName)
+			log.Errorf("thumbs: invalid type \"%s\"", typeName)
 			c.Data(http.StatusBadRequest, "image/svg+xml", photoIconSvg)
 			return
 		}

internal/server/logger.go

@@ -0,0 +1,50 @@
+package server
+
+import (
+	"time"
+
+	"github.com/gin-gonic/gin"
+)
+
+// Logger instances a Logger middleware for Gin.
+func Logger() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		// Start timer
+		start := time.Now()
+		path := c.Request.URL.Path
+		raw := c.Request.URL.RawQuery
+
+		// Process request
+		c.Next()
+
+		// Stop timer
+		end := time.Now()
+		latency := end.Sub(start)
+
+		clientIP := c.ClientIP()
+		method := c.Request.Method
+		statusCode := c.Writer.Status()
+
+		if raw != "" {
+			path = path + "?" + raw
+		}
+
+		if statusCode >= 400 {
+			log.Errorf("%s %s: %s (%3d) [%v]",
+				method,
+				path,
+				clientIP,
+				statusCode,
+				latency,
+			)
+		} else {
+			log.Debugf("%s %s: %s (%3d) [%v]",
+				method,
+				path,
+				clientIP,
+				statusCode,
+				latency,
+			)
+		}
+	}
+}

internal/server/recovery.go

@@ -0,0 +1,102 @@
+package server
+
+import (
+	"bytes"
+	"fmt"
+	"io/ioutil"
+	"net/http"
+	"net/http/httputil"
+	"runtime"
+	"time"
+
+	"github.com/gin-gonic/gin"
+)
+
+var (
+	dunno     = []byte("???")
+	centerDot = []byte("·")
+	dot       = []byte(".")
+	slash     = []byte("/")
+)
+
+// Recovery returns a middleware that recovers from any panics and writes a 500 if there was one.
+func Recovery() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		defer func() {
+			if err := recover(); err != nil {
+				stack := stack(3)
+				req, _ := httputil.DumpRequest(c.Request, false)
+				log.Errorf("http: %s (%s)\n%s", err, string(req), stack)
+				c.AbortWithStatus(http.StatusInternalServerError)
+			}
+		}()
+		c.Next()
+	}
+}
+
+// stack returns a nicely formatted 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
+}
+
+func timeFormat(t time.Time) string {
+	var timeString = t.Format("2006/01/02 - 15:04:05")
+	return timeString
+}

internal/server/server.go

@@ -14,6 +14,12 @@ var log = event.Log
 
 // Start the REST API server using the configuration provided
 func Start(ctx context.Context, conf *config.Config) {
+	defer func() {
+		if err := recover(); err != nil {
+			log.Error(err)
+		}
+	}()
+
 	if conf.HttpServerMode() != "" {
 		gin.SetMode(conf.HttpServerMode())
 	} else if conf.Debug() == false {
@@ -21,7 +27,7 @@ func Start(ctx context.Context, conf *config.Config) {
 	}
 
 	router := gin.New()
-	router.Use(gin.Logger(), gin.Recovery())
+	router.Use(Logger(), Recovery())
 
 	// Set template directory
 	router.LoadHTMLGlob(conf.HttpTemplatesPath() + "/*")