Merge pull request #41 from AnalogJ/ext_logging

adding new environmental variables for added debugging: COLLECTOR_LOG…

collector/cmd/collector-metrics/collector-metrics.go

@@ -117,15 +117,16 @@ OPTIONS:
 					},
 
 					&cli.StringFlag{
-						Name:  "log-file",
+						Name:    "log-file",
-						Usage: "Path to file for logging. Leave empty to use STDOUT",
+						Usage:   "Path to file for logging. Leave empty to use STDOUT",
-						Value: "",
+						Value:   "",
+						EnvVars: []string{"COLLECTOR_LOG_FILE"},
 					},
 
 					&cli.BoolFlag{
 						Name:    "debug",
 						Usage:   "Enable debug logging",
-						EnvVars: []string{"DEBUG"},
+						EnvVars: []string{"COLLECTOR_DEBUG", "DEBUG"},
 					},
 				},
 			},

collector/cmd/collector-selftest/collector-selftest.go

@@ -117,15 +117,16 @@ OPTIONS:
 					},
 
 					&cli.StringFlag{
-						Name:  "log-file",
+						Name:    "log-file",
-						Usage: "Path to file for logging. Leave empty to use STDOUT",
+						Usage:   "Path to file for logging. Leave empty to use STDOUT",
-						Value: "",
+						Value:   "",
+						EnvVars: []string{"COLLECTOR_LOG_FILE"},
 					},
 
 					&cli.BoolFlag{
 						Name:    "debug",
 						Usage:   "Enable debug logging",
-						EnvVars: []string{"DEBUG"},
+						EnvVars: []string{"COLLECTOR_DEBUG", "DEBUG"},
 					},
 				},
 			},

example.scrutiny.yaml

@@ -27,52 +27,59 @@ web:
     frontend:
       path: ./dist
 
-disks:
-  include:
-    # - /dev/sda
-  exclude:
-    # - /dev/sdb
 
-notify:
+log:
-  urls:
+  file: '' #absolute or relative paths allowed, eg. web.log
-    - "discord://token@channel"
+  level: INFO
-    - "telegram://token@telegram?channels=channel-1[,channel-2,...]"
-    - "pushover://shoutrrr:apiToken@userKey/?devices=device1[,device2, ...]"
-    - "slack://[botname@]token-a/token-b/token-c"
-    - "smtp://username:password@host:port/?fromAddress=fromAddress&toAddresses=recipient1[,recipient2,...]"
-    - "teams://token-a/token-b/token-c"
-    - "gotify://gotify-host/token"
-    - "pushbullet://api-token[/device/#channel/email]"
-    - "ifttt://key/?events=event1[,event2,...]&value1=value1&value2=value2&value3=value3"
-    - "mattermost://[username@]mattermost-host/token[/channel]"
-    - "hangouts://chat.googleapis.com/v1/spaces/FOO/messages?key=bar&token=baz"
-    - "zulip://bot-mail:bot-key@zulip-domain/?stream=name-or-id&topic=name"
-    - "join://shoutrrr:api-key@join/?devices=device1[,device2, ...][&icon=icon][&title=title]"
-    - "script:///file/path/on/disk"
-    - "https://www.example.com/path"
 
-limits:
+# The following commented out sections are a preview of additional configuration options that will be available soon.
-  ata:
+
-    critical:
+#disks:
-      error: 10
+#  include:
-    standard:
+#    # - /dev/sda
-      error: 20
+#  exclude:
-      warn: 10
+#    # - /dev/sdb
-  scsi:
+
-    critical: true
+#notify:
-    standard: true
+#  urls:
-  nvme:
+#    - "discord://token@channel"
-    critical: true
+#    - "telegram://token@telegram?channels=channel-1[,channel-2,...]"
-    standard: true
+#    - "pushover://shoutrrr:apiToken@userKey/?devices=device1[,device2, ...]"
+#    - "slack://[botname@]token-a/token-b/token-c"
+#    - "smtp://username:password@host:port/?fromAddress=fromAddress&toAddresses=recipient1[,recipient2,...]"
+#    - "teams://token-a/token-b/token-c"
+#    - "gotify://gotify-host/token"
+#    - "pushbullet://api-token[/device/#channel/email]"
+#    - "ifttt://key/?events=event1[,event2,...]&value1=value1&value2=value2&value3=value3"
+#    - "mattermost://[username@]mattermost-host/token[/channel]"
+#    - "hangouts://chat.googleapis.com/v1/spaces/FOO/messages?key=bar&token=baz"
+#    - "zulip://bot-mail:bot-key@zulip-domain/?stream=name-or-id&topic=name"
+#    - "join://shoutrrr:api-key@join/?devices=device1[,device2, ...][&icon=icon][&title=title]"
+#    - "script:///file/path/on/disk"
+#    - "https://www.example.com/path"
+
+#limits:
+#  ata:
+#    critical:
+#      error: 10
+#    standard:
+#      error: 20
+#      warn: 10
+#  scsi:
+#    critical: true
+#    standard: true
+#  nvme:
+#    critical: true
+#    standard: true
 
 
-collect:
+#collect:
-  metric:
+#  metric:
-    enable: true
+#    enable: true
-    command: '-a -o on -S on'
+#    command: '-a -o on -S on'
-  long:
+#  long:
-    enable: false
+#    enable: false
-    command: ''
+#    command: ''
-  short:
+#  short:
-    enable: false
+#    enable: false
-    command: ''
+#    command: ''

webapp/backend/cmd/scrutiny/scrutiny.go

@@ -95,10 +95,18 @@ OPTIONS:
 						if err != nil {                             // Handle errors reading the config file
 							//ignore "could not find config file"
 							fmt.Printf("Could not find config file at specified path: %s", c.String("config"))
-							os.Exit(1)
+							return err
 						}
 					}
 
+					if c.Bool("debug") {
+						config.Set("log.level", "DEBUG")
+					}
+
+					if c.IsSet("log-file") {
+						config.Set("log.file", c.String("log-file"))
+					}
+
 					webServer := web.AppEngine{Config: config}
 
 					return webServer.Start()
@@ -109,6 +117,18 @@ OPTIONS:
 						Name:  "config",
 						Usage: "Specify the path to the config file",
 					},
+					&cli.StringFlag{
+						Name:    "log-file",
+						Usage:   "Path to file for logging. Leave empty to use STDOUT",
+						Value:   "",
+						EnvVars: []string{"SCRUTINY_LOG_FILE"},
+					},
+
+					&cli.BoolFlag{
+						Name:    "debug",
+						Usage:   "Enable debug logging",
+						EnvVars: []string{"SCRUTINY_DEBUG", "DEBUG"},
+					},
 				},
 			},
 		},

webapp/backend/pkg/config/config.go

@@ -30,22 +30,24 @@ func (c *configuration) Init() error {
 	c.SetDefault("web.listen.port", "8080")
 	c.SetDefault("web.listen.host", "0.0.0.0")
 	c.SetDefault("web.src.frontend.path", "/scrutiny/web")
-
 	c.SetDefault("web.database.location", "/scrutiny/config/scrutiny.db")
 
-	c.SetDefault("disks.include", []string{})
+	c.SetDefault("log.level", "INFO")
-	c.SetDefault("disks.exclude", []string{})
+	c.SetDefault("log.file", "")
 
-	c.SetDefault("notify.metric.script", "/scrutiny/config/notify-metrics.sh")
+	//c.SetDefault("disks.include", []string{})
-	c.SetDefault("notify.long.script", "/scrutiny/config/notify-long-test.sh")
+	//c.SetDefault("disks.exclude", []string{})
-	c.SetDefault("notify.short.script", "/scrutiny/config/notify-short-test.sh")
 
-	c.SetDefault("collect.metric.enable", true)
+	//c.SetDefault("notify.metric.script", "/scrutiny/config/notify-metrics.sh")
-	c.SetDefault("collect.metric.command", "-a -o on -S on")
+	//c.SetDefault("notify.long.script", "/scrutiny/config/notify-long-test.sh")
-	c.SetDefault("collect.long.enable", true)
+	//c.SetDefault("notify.short.script", "/scrutiny/config/notify-short-test.sh")
-	c.SetDefault("collect.long.command", "-a -o on -S on")
+
-	c.SetDefault("collect.short.enable", true)
+	//c.SetDefault("collect.metric.enable", true)
-	c.SetDefault("collect.short.command", "-a -o on -S on")
+	//c.SetDefault("collect.metric.command", "-a -o on -S on")
+	//c.SetDefault("collect.long.enable", true)
+	//c.SetDefault("collect.long.command", "-a -o on -S on")
+	//c.SetDefault("collect.short.enable", true)
+	//c.SetDefault("collect.short.command", "-a -o on -S on")
 
 	//if you want to load a non-standard location system config file (~/drawbridge.yml), use ReadConfig
 	c.SetConfigType("yaml")

webapp/backend/pkg/web/middleware/logger.go

@@ -0,0 +1,93 @@
+package middleware
+
+import (
+	"bytes"
+	"fmt"
+	"github.com/gin-gonic/gin"
+	"github.com/sirupsen/logrus"
+	"math"
+	"net/http"
+	"os"
+	"strings"
+	"time"
+)
+
+// Middleware based on https://github.com/toorop/gin-logrus/blob/master/logger.go
+// Body recording based on
+// - https://github.com/gin-gonic/gin/issues/1363
+// - https://stackoverflow.com/questions/38501325/how-to-log-response-body-in-gin
+
+// 2016-09-27 09:38:21.541541811 +0200 CEST
+// 127.0.0.1 - frank [10/Oct/2000:13:55:36 -0700]
+// "GET /apache_pb.gif HTTP/1.0" 200 2326
+// "http://www.example.com/start.html"
+// "Mozilla/4.08 [en] (Win98; I ;Nav)"
+
+var timeFormat = "02/Jan/2006:15:04:05 -0700"
+
+// Logger is the logrus logger handler
+func LoggerMiddleware(logger logrus.FieldLogger) gin.HandlerFunc {
+
+	hostname, err := os.Hostname()
+	if err != nil {
+		hostname = "unknow"
+	}
+
+	return func(c *gin.Context) {
+		// other handler can change c.Path so:
+		path := c.Request.URL.Path
+		blw := &bodyLogWriter{body: &bytes.Buffer{}, ResponseWriter: c.Writer}
+		c.Writer = blw
+		start := time.Now()
+		c.Next()
+		stop := time.Since(start)
+		latency := int(math.Ceil(float64(stop.Nanoseconds()) / 1000000.0))
+		statusCode := c.Writer.Status()
+		clientIP := c.ClientIP()
+		clientUserAgent := c.Request.UserAgent()
+		referer := c.Request.Referer()
+		dataLength := c.Writer.Size()
+		if dataLength < 0 {
+			dataLength = 0
+		}
+
+		entry := logger.WithFields(logrus.Fields{
+			"hostname":   hostname,
+			"statusCode": statusCode,
+			"latency":    latency, // time to process
+			"clientIP":   clientIP,
+			"method":     c.Request.Method,
+			"path":       path,
+			"referer":    referer,
+			"dataLength": dataLength,
+			"userAgent":  clientUserAgent,
+		})
+
+		if len(c.Errors) > 0 {
+			entry.Error(c.Errors.ByType(gin.ErrorTypePrivate).String())
+		} else {
+			msg := fmt.Sprintf("%s - %s [%s] \"%s %s\" %d %d \"%s\" \"%s\" (%dms)", clientIP, hostname, time.Now().Format(timeFormat), c.Request.Method, path, statusCode, dataLength, referer, clientUserAgent, latency)
+			if statusCode >= http.StatusInternalServerError {
+				entry.Error(msg)
+			} else if statusCode >= http.StatusBadRequest {
+				entry.Warn(msg)
+			} else {
+				entry.Info(msg)
+			}
+		}
+		if strings.HasPrefix(path, "/api/") {
+			//only debug log request/response from api endpoint.
+			entry.Debugln(blw.body.String())
+		}
+	}
+}
+
+type bodyLogWriter struct {
+	gin.ResponseWriter
+	body *bytes.Buffer
+}
+
+func (w bodyLogWriter) Write(b []byte) (int, error) {
+	w.body.Write(b)
+	return w.ResponseWriter.Write(b)
+}

webapp/backend/pkg/web/middleware/sqlite3.go

@@ -2,21 +2,23 @@ package middleware
 
 import (
 	"fmt"
+	"github.com/analogj/scrutiny/webapp/backend/pkg/config"
 	"github.com/analogj/scrutiny/webapp/backend/pkg/models/db"
 	"github.com/gin-gonic/gin"
 	"github.com/jinzhu/gorm"
 	_ "github.com/jinzhu/gorm/dialects/sqlite"
+	"github.com/sirupsen/logrus"
 )
 
-func DatabaseMiddleware(dbPath string) gin.HandlerFunc {
+func DatabaseMiddleware(appConfig config.Interface, logger logrus.FieldLogger) gin.HandlerFunc {
 	//var database *gorm.DB
-	fmt.Printf("Trying to connect to database stored: %s", dbPath)
+	fmt.Printf("Trying to connect to database stored: %s\n", appConfig.GetString("web.database.location"))
-	database, err := gorm.Open("sqlite3", dbPath)
+	database, err := gorm.Open("sqlite3", appConfig.GetString("web.database.location"))
-
 	if err != nil {
 		panic("Failed to connect to database!")
 	}
 
+	database.SetLogger(&GormLogger{Logger: logger})
 	database.AutoMigrate(&db.Device{})
 	database.AutoMigrate(&db.SelfTest{})
 	database.AutoMigrate(&db.Smart{})
@@ -30,3 +32,24 @@ func DatabaseMiddleware(dbPath string) gin.HandlerFunc {
 		c.Next()
 	}
 }
+
+// GormLogger is a custom logger for Gorm, making it use logrus.
+type GormLogger struct{ Logger logrus.FieldLogger }
+
+// Print handles log events from Gorm for the custom logger.
+func (gl *GormLogger) Print(v ...interface{}) {
+	switch v[0] {
+	case "sql":
+		gl.Logger.WithFields(
+			logrus.Fields{
+				"module":  "gorm",
+				"type":    "sql",
+				"rows":    v[5],
+				"src_ref": v[1],
+				"values":  v[4],
+			},
+		).Debug(v[3])
+	case "log":
+		gl.Logger.WithFields(logrus.Fields{"module": "gorm", "type": "log"}).Print(v[2])
+	}
+}

webapp/backend/pkg/web/server.go

@@ -6,18 +6,23 @@ import (
 	"github.com/analogj/scrutiny/webapp/backend/pkg/web/handler"
 	"github.com/analogj/scrutiny/webapp/backend/pkg/web/middleware"
 	"github.com/gin-gonic/gin"
+	"github.com/sirupsen/logrus"
+	"io"
 	"net/http"
+	"os"
 )
 
 type AppEngine struct {
 	Config config.Interface
 }
 
-func (ae *AppEngine) Setup() *gin.Engine {
+func (ae *AppEngine) Setup(logger logrus.FieldLogger) *gin.Engine {
-	r := gin.Default()
+	r := gin.New()
 
-	r.Use(middleware.DatabaseMiddleware(ae.Config.GetString("web.database.location")))
+	r.Use(middleware.LoggerMiddleware(logger))
+	r.Use(middleware.DatabaseMiddleware(ae.Config, logger))
 	r.Use(middleware.ConfigMiddleware(ae.Config))
+	r.Use(gin.Recovery())
 
 	api := r.Group("/api")
 	{
@@ -51,7 +56,28 @@ func (ae *AppEngine) Setup() *gin.Engine {
 }
 
 func (ae *AppEngine) Start() error {
-	r := ae.Setup()
+
+	logger := logrus.New()
+	//set default log level
+	logLevel, err := logrus.ParseLevel(ae.Config.GetString("log.level"))
+	if err != nil {
+		return err
+	}
+	logger.SetLevel(logLevel)
+	//set the log file if present
+	if len(ae.Config.GetString("log.file")) != 0 {
+		logFile, err := os.OpenFile(ae.Config.GetString("log.file"), os.O_CREATE|os.O_WRONLY, 0644)
+		defer logFile.Close()
+		if err != nil {
+			logrus.Errorf("Failed to open log file %s for output: %s", ae.Config.GetString("log.file"), err)
+			return err
+		}
+
+		//configure the logrus default
+		logger.SetOutput(io.MultiWriter(os.Stderr, logFile))
+	}
+
+	r := ae.Setup(logger)
 
 	return r.Run(fmt.Sprintf("%s:%s", ae.Config.GetString("web.listen.host"), ae.Config.GetString("web.listen.port")))
 }

webapp/backend/pkg/web/server_test.go

@@ -6,6 +6,7 @@ import (
 	dbModels "github.com/analogj/scrutiny/webapp/backend/pkg/models/db"
 	"github.com/analogj/scrutiny/webapp/backend/pkg/web"
 	"github.com/golang/mock/gomock"
+	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 	"io/ioutil"
 	"net/http"
@@ -30,7 +31,7 @@ func TestHealthRoute(t *testing.T) {
 		Config: fakeConfig,
 	}
 
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 
 	//test
 	w := httptest.NewRecorder()
@@ -54,7 +55,7 @@ func TestRegisterDevicesRoute(t *testing.T) {
 	ae := web.AppEngine{
 		Config: fakeConfig,
 	}
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 	file, err := os.Open("testdata/register-devices-req.json")
 	require.NoError(t, err)
 
@@ -79,7 +80,7 @@ func TestUploadDeviceMetricsRoute(t *testing.T) {
 	ae := web.AppEngine{
 		Config: fakeConfig,
 	}
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 	devicesfile, err := os.Open("testdata/register-devices-single-req.json")
 	require.NoError(t, err)
 
@@ -113,7 +114,7 @@ func TestPopulateMultiple(t *testing.T) {
 	ae := web.AppEngine{
 		Config: fakeConfig,
 	}
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 	devicesfile, err := os.Open("testdata/register-devices-req.json")
 	require.NoError(t, err)
 
@@ -175,7 +176,7 @@ func TestSendTestNotificationRoute(t *testing.T) {
 	ae := web.AppEngine{
 		Config: fakeConfig,
 	}
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 
 	//test
 	wr := httptest.NewRecorder()
@@ -198,7 +199,7 @@ func TestGetDevicesSummaryRoute_Nvme(t *testing.T) {
 	ae := web.AppEngine{
 		Config: fakeConfig,
 	}
-	router := ae.Setup()
+	router := ae.Setup(logrus.New())
 	devicesfile, err := os.Open("testdata/register-devices-req-2.json")
 	require.NoError(t, err)