Merge pull request 'Improve logging' (#9) from logging into trunk

Reviewed-on: #9

.gitignore

@@ -5,3 +5,4 @@ client/calls/
 /gordio
 /calls
 Session.vim
+*.log

Makefile

@@ -1,5 +1,8 @@
+VER!=git describe --tags --always
+HASH!=git describe --always
+LDFLAGS=-ldflags="-X 'main.Version=${VER}' -X 'main.Commit=${HASH}'"
 all: checkcalls
-	go build -o gordio ./cmd/gordio/
+	go build -o gordio ${LDFLAGS} ./cmd/gordio/
 	go build -o calls ./cmd/calls/
 
 clean:

cmd/gordio/main.go

@@ -1,7 +1,9 @@
 package main
 
 import (
+	"fmt"
 	"os"
+	"runtime"
 
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
@@ -13,15 +15,30 @@ import (
 	"github.com/spf13/cobra"
 )
 
+var (
+	Version = "unset"
+	Commit  = "unset"
+)
+
+func version() {
+	fmt.Printf("gordio %s (%s)\nbuilt for %s-%s\n",
+		Version, Commit, runtime.GOOS, runtime.GOARCH)
+}
+
 func main() {
 	log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr})
 
 	rootCmd := &cobra.Command{
 		Use: gordio.AppName,
 	}
+	rootCmd.PersistentFlags().BoolP("version", "V", false, "show version")
 	cfg := config.New(rootCmd)
-	rootCmd.PersistentPreRunE = func(cmd *cobra.Command, args []string) error {
-		return cfg.ReadConfig()
+	rootCmd.Run = func(cmd *cobra.Command, args []string) {
+		v, _ := rootCmd.PersistentFlags().GetBool("version")
+		if v {
+			version()
+			os.Exit(0)
+		}
 	}
 
 	cmds := append([]*cobra.Command{gordio.Command(cfg)}, admin.Command(cfg)...)

config.sample.yaml

@@ -14,3 +14,10 @@ auth:
     "localhost": true
 listen: ':3050'
 public: true
+log:
+  # level logs at or above the specified level
+  # levels are trace, debug, info, warn, error, fatal, panic
+  # an entry without a file: property indicates stderr
+  - level: debug
+  - level: error
+    file: error.log

pkg/gordio/admin/admin.go

@@ -120,6 +120,7 @@ func Command(cfg *config.Config) []*cobra.Command {
 		Use:               "users",
 		Aliases:           []string{"u"},
 		Short:             "administers the server",
+		PersistentPreRunE: cfg.PreRunE(),
 	}
 	userCmd.AddCommand(addUserCommand(cfg), passwdCommand(cfg))
 

pkg/gordio/config/config.go

@@ -12,6 +12,7 @@ type Config struct {
 	DB     DB       `yaml:"db"`
 	CORS   CORS     `yaml:"cors"`
 	Auth   Auth     `yaml:"auth"`
+	Log    []Logger `yaml:"log"`
 	Listen string   `yaml:"listen"`
 	Public bool     `yaml:"public"`
 
@@ -33,9 +34,22 @@ type DB struct {
 	Driver  string `yaml:"driver"`
 }
 
-func New(cmd *cobra.Command) *Config {
+type Logger struct {
+	File  *string `yaml:"file"`
+	Level *string `yaml:"level"`
+}
+
+func (c *Config) PreRunE() func(*cobra.Command, []string) error {
+	return func(cmd *cobra.Command, args []string) error {
+		return c.ReadConfig()
+	}
+}
+
+func New(rootCommand *cobra.Command) *Config {
 	c := &Config{}
-	cmd.PersistentFlags().StringVarP(&c.configPath, "config", "c", "config.yaml", "configuration file")
+
+	rootCommand.PersistentFlags().StringVarP(&c.configPath, "config", "c", "config.yaml", "configuration file")
+
 	return c
 }
 

pkg/gordio/gordio.go

@@ -19,6 +19,7 @@ func Command(cfg *config.Config) *cobra.Command {
 	serveCmd := &cobra.Command{
 		Use:               "serve",
 		Short:             "starts the" + AppName + " server",
+		PersistentPreRunE: cfg.PreRunE(),
 		RunE:              common.RunE(opts),
 	}
 

pkg/gordio/server/logging.go

@@ -0,0 +1,207 @@
+package server
+
+import (
+	"fmt"
+	"io"
+	"io/fs"
+	"net/http"
+	"os"
+	"os/signal"
+	"runtime/debug"
+	"syscall"
+	"time"
+
+	"dynatron.me/x/stillbox/pkg/gordio/config"
+
+	"github.com/go-chi/chi/v5/middleware"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+)
+
+const (
+	LOGPERM fs.FileMode = 0600
+)
+
+type Logger struct {
+	console io.Writer
+	writers []io.Writer
+	hup     chan os.Signal
+
+	lastFieldName string
+	noColor       bool
+}
+
+func NewLogger(cfg *config.Config) (*Logger, error) {
+	l := &Logger{}
+	cw := &zerolog.ConsoleWriter{
+		Out:              os.Stderr,
+		TimeFormat:       "Jan 2 15:04:05",
+		FormatFieldName:  l.fieldNameFormat,
+		FormatFieldValue: l.fieldValueFormat,
+	}
+
+	l.console = cw
+
+	l.hup = make(chan os.Signal, 1)
+	go func() {
+		for sig := range l.hup {
+			log.Logger = log.Output(l.console)
+			log.Info().Msgf("received %s, closing and reopening logfiles", sig)
+			l.Close()
+			err := l.OpenLogs(cfg)
+			if err != nil {
+				log.Error().Err(err).Msg("error reopening logs")
+				continue
+			}
+
+			l.Install()
+		}
+	}()
+
+	signal.Notify(l.hup, syscall.SIGHUP)
+
+	err := l.OpenLogs(cfg)
+	if err != nil {
+		return nil, err
+	}
+
+	l.Install()
+
+	return l, nil
+}
+
+func (l *Logger) Install() {
+	log.Logger = log.Output(zerolog.MultiLevelWriter(l.writers...))
+}
+
+func (l *Logger) Close() {
+	for _, lg := range l.writers {
+		if _, isConsole := lg.(*zerolog.ConsoleWriter); isConsole {
+			continue
+		}
+
+		if cl, isCloser := lg.(io.Closer); isCloser {
+			err := cl.Close()
+			if err != nil {
+				log.Error().Err(err).Msg("closing writer")
+			}
+		}
+	}
+
+	l.writers = nil
+}
+
+func (l *Logger) OpenLogs(cfg *config.Config) error {
+	l.writers = make([]io.Writer, 0, len(cfg.Log))
+	for _, lc := range cfg.Log {
+		level := zerolog.TraceLevel
+		if lc.Level != nil {
+			var err error
+
+			level, err = zerolog.ParseLevel(*lc.Level)
+			if err != nil {
+				return err
+			}
+		}
+
+		w := &zerolog.FilteredLevelWriter{
+			Level: level,
+		}
+
+		switch lc.File {
+		case nil:
+			w.Writer = &zerolog.LevelWriterAdapter{Writer: l.console}
+		default:
+			f, err := os.OpenFile(*lc.File, os.O_APPEND|os.O_WRONLY|os.O_CREATE, LOGPERM)
+			if err != nil {
+				return err
+			}
+
+			w.Writer = &zerolog.LevelWriterAdapter{
+				Writer: f,
+			}
+		}
+
+		l.writers = append(l.writers, w)
+	}
+
+	return nil
+}
+
+func RequestLogger() func(next http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		fn := func(w http.ResponseWriter, r *http.Request) {
+			t1 := time.Now()
+			ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+			defer func() {
+				if r := recover(); r != nil && r != http.ErrAbortHandler {
+					log.Error().Interface("recover", r).Bytes("stack", debug.Stack()).Msg("incoming_request_panic")
+					ww.WriteHeader(http.StatusInternalServerError)
+				}
+				log.Info().Fields(map[string]interface{}{
+					"remote_addr": r.RemoteAddr,
+					"path":        r.URL.Path,
+					"proto":       r.Proto,
+					"method":      r.Method,
+					"user_agent":  r.UserAgent(),
+					"status":      http.StatusText(ww.Status()),
+					"status_code": ww.Status(),
+					"bytes_in":    r.ContentLength,
+					"bytes_out":   ww.BytesWritten(),
+					"duration":    time.Since(t1).String(),
+					"reqID":       middleware.GetReqID(r.Context()),
+				}).Msg("incoming_request")
+			}()
+			next.ServeHTTP(ww, r)
+		}
+		return http.HandlerFunc(fn)
+	}
+}
+
+const (
+	colorBlack = iota + 30
+	colorRed
+	colorGreen
+	colorYellow
+	colorBlue
+	colorMagenta
+	colorCyan
+	colorWhite
+	colorNone
+
+	colorBold     = 1
+	colorDarkGray = 90
+)
+
+func (l *Logger) fieldNameFormat(i interface{}) string {
+	l.lastFieldName = fmt.Sprint(i)
+	return l.colorize(l.lastFieldName+"=", colorCyan)
+}
+
+func (l *Logger) fieldValueFormat(i interface{}) string {
+	color := colorNone
+	switch l.lastFieldName {
+	case "method":
+		color = colorMagenta
+	case "reqID":
+		color = colorYellow
+	case "duration":
+		color = colorBlue
+	}
+
+	l.lastFieldName = ""
+
+	if color == colorNone {
+		return fmt.Sprint(i)
+	}
+
+	return l.colorize(i, color)
+}
+
+// colorize returns the string s wrapped in ANSI code c, unless disabled is true or c is 0.
+func (l *Logger) colorize(s interface{}, c int) string {
+	if l.noColor {
+		return fmt.Sprintf("%v", s)
+	}
+	return fmt.Sprintf("\x1b[%dm%v\x1b[0m", c, s)
+}

pkg/gordio/server/server.go

@@ -10,8 +10,8 @@ import (
 	"dynatron.me/x/stillbox/pkg/gordio/nexus"
 	"dynatron.me/x/stillbox/pkg/gordio/sinks"
 	"dynatron.me/x/stillbox/pkg/gordio/sources"
-	"github.com/go-chi/chi/middleware"
 	"github.com/go-chi/chi/v5"
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/go-chi/cors"
 )
 
@@ -23,9 +23,15 @@ type Server struct {
 	sources sources.Sources
 	sinks   sinks.Sinks
 	nex     *nexus.Nexus
+	logger  *Logger
 }
 
 func New(cfg *config.Config) (*Server, error) {
+	logger, err := NewLogger(cfg)
+	if err != nil {
+		return nil, err
+	}
+
 	db, err := database.NewClient(cfg.DB)
 	if err != nil {
 		return nil, err
@@ -39,6 +45,7 @@ func New(cfg *config.Config) (*Server, error) {
 		db:     db,
 		r:      r,
 		nex:    nexus.New(),
+		logger: logger,
 	}
 
 	srv.sinks.Register("database", sinks.NewDatabaseSink(srv.db), true)
@@ -47,8 +54,7 @@ func New(cfg *config.Config) (*Server, error) {
 
 	r.Use(middleware.RequestID)
 	r.Use(middleware.RealIP)
-	r.Use(middleware.Logger)
-	r.Use(middleware.Recoverer)
+	r.Use(RequestLogger())
 	r.Use(cors.Handler(cors.Options{
 		AllowedOrigins:   srv.conf.CORS.AllowedOrigins,
 		AllowedMethods:   []string{"GET", "POST", "PUT", "DELETE", "OPTIONS"},