Gin logging (#165)

* start messing around with logger

* more messing about

* fix error with instance not created on startup (#156)

* set logger

* log user agent

* finalize logging

* go fmt

* start messing around with logger

* more messing about

* set logger

* log user agent

* finalize logging

* go fmt

internal/log/log.go

@@ -46,6 +46,7 @@ func New(level string) (*logrus.Logger, error) {
 
 	log.SetFormatter(&logrus.TextFormatter{
 		DisableColors: true,
+		ForceQuote:    true,
 		FullTimestamp: true,
 	})
 

internal/router/logger.go

@@ -0,0 +1,73 @@
+/*
+   GoToSocial
+   Copyright (C) 2021 GoToSocial Authors admin@gotosocial.org
+
+   This program is free software: you can redistribute it and/or modify
+   it under the terms of the GNU Affero General Public License as published by
+   the Free Software Foundation, either version 3 of the License, or
+   (at your option) any later version.
+
+   This program is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+   GNU Affero General Public License for more details.
+
+   You should have received a copy of the GNU Affero General Public License
+   along with this program.  If not, see <http://www.gnu.org/licenses/>.
+*/
+
+package router
+
+import (
+	"net/http"
+	"time"
+
+	"github.com/gin-gonic/gin"
+	"github.com/sirupsen/logrus"
+)
+
+var skipPaths = map[string]interface{}{
+	"/api/v1/streaming": nil,
+}
+
+func loggerWithConfig(log *logrus.Logger) gin.HandlerFunc {
+	logHandler := func(c *gin.Context) {
+		start := time.Now()
+		path := c.Request.URL.Path
+		raw := c.Request.URL.RawQuery
+
+		// Process request
+		c.Next()
+
+		// Log only when path is not being skipped
+		if _, ok := skipPaths[path]; !ok {
+			latency := time.Since(start)
+			clientIP := c.ClientIP()
+			userAgent := c.Request.UserAgent()
+			method := c.Request.Method
+			statusCode := c.Writer.Status()
+			errorMessage := c.Errors.ByType(gin.ErrorTypePrivate).String()
+			bodySize := c.Writer.Size()
+			if raw != "" {
+				path = path + "?" + raw
+			}
+
+			l := log.WithFields(logrus.Fields{
+				"latency":    latency,
+				"clientIP":   clientIP,
+				"userAgent":  userAgent,
+				"method":     method,
+				"statusCode": statusCode,
+				"path":       path,
+			})
+
+			if errorMessage == "" {
+				l.Infof("%s: wrote %d bytes in %v", http.StatusText(statusCode), bodySize, latency)
+			} else {
+				l.Errorf("%s: %s", http.StatusText(statusCode), errorMessage)
+			}
+		}
+	}
+
+	return logHandler
+}

internal/router/router.go

@@ -104,23 +104,16 @@ func (r *router) Stop(ctx context.Context) error {
 // The given DB is only used in the New function for parsing config values, and is not otherwise
 // pinned to the router.
 func New(ctx context.Context, cfg *config.Config, db db.DB, logger *logrus.Logger) (Router, error) {
-
-	// gin has different log modes; for convenience, we match the gin log mode to
-	// whatever log mode has been set for logrus
-	lvl, err := logrus.ParseLevel(cfg.LogLevel)
-	if err != nil {
-		return nil, fmt.Errorf("couldn't parse log level %s to set router level: %s", cfg.LogLevel, err)
-	}
-	switch lvl {
-	case logrus.TraceLevel, logrus.DebugLevel:
-		gin.SetMode(gin.DebugMode)
-	default:
 	gin.SetMode(gin.ReleaseMode)
-	}
 
 	// create the actual engine here -- this is the core request routing handler for gts
-	engine := gin.Default()
-	engine.MaxMultipartMemory = 8 << 20 // 8 MiB
+	engine := gin.New()
+
+	engine.Use(gin.RecoveryWithWriter(logger.Writer()))
+	engine.Use(loggerWithConfig(logger))
+
+	// 8 MiB
+	engine.MaxMultipartMemory = 8 << 20
 
 	// set up IP forwarding via x-forward-* headers.
 	if err := engine.SetTrustedProxies(cfg.TrustedProxies); err != nil {

testrig/db.go

@@ -66,9 +66,7 @@ func NewTestDB() db.DB {
 		config.DBConfig.Address = alternateAddress
 	}
 
-	l := logrus.New()
-	l.SetLevel(logrus.TraceLevel)
-	testDB, err := bundb.NewBunDBService(context.Background(), config, l)
+	testDB, err := bundb.NewBunDBService(context.Background(), config, NewTestLog())
 	if err != nil {
 		logrus.Panic(err)
 	}

testrig/log.go

@@ -18,11 +18,17 @@
 
 package testrig
 
-import "github.com/sirupsen/logrus"
+import (
+	"github.com/superseriousbusiness/gotosocial/internal/log"
+
+	"github.com/sirupsen/logrus"
+)
 
 // NewTestLog returns a trace level logger for testing
 func NewTestLog() *logrus.Logger {
-	log := logrus.New()
-	log.SetLevel(logrus.TraceLevel)
-	return log
+	logger, err := log.New("trace")
+	if err != nil {
+		panic(err)
+	}
+	return logger
 }