From 0407672a23b72ea9bab9b89d92014c2db286b18d Mon Sep 17 00:00:00 2001 From: Daniel Ponte Date: Thu, 17 Oct 2024 10:00:23 -0400 Subject: [PATCH 1/3] Improve logging. TODO: Switch to slog. --- .gitignore | 1 + config.sample.yaml | 7 +++ pkg/gordio/config/config.go | 16 +++-- pkg/gordio/server/logging.go | 110 +++++++++++++++++++++++++++++++++++ pkg/gordio/server/server.go | 7 +++ 5 files changed, 136 insertions(+), 5 deletions(-) create mode 100644 pkg/gordio/server/logging.go diff --git a/.gitignore b/.gitignore index 9115ebc..a37f180 100644 --- a/.gitignore +++ b/.gitignore @@ -5,3 +5,4 @@ client/calls/ /gordio /calls Session.vim +*.log diff --git a/config.sample.yaml b/config.sample.yaml index b98b24a..dc4b2b1 100644 --- a/config.sample.yaml +++ b/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 diff --git a/pkg/gordio/config/config.go b/pkg/gordio/config/config.go index c8f0a8b..a33c4ef 100644 --- a/pkg/gordio/config/config.go +++ b/pkg/gordio/config/config.go @@ -9,11 +9,12 @@ import ( ) type Config struct { - DB DB `yaml:"db"` - CORS CORS `yaml:"cors"` - Auth Auth `yaml:"auth"` - Listen string `yaml:"listen"` - Public bool `yaml:"public"` + DB DB `yaml:"db"` + CORS CORS `yaml:"cors"` + Auth Auth `yaml:"auth"` + Log []Logger `yaml:"log"` + Listen string `yaml:"listen"` + Public bool `yaml:"public"` configPath string } @@ -33,6 +34,11 @@ type DB struct { Driver string `yaml:"driver"` } +type Logger struct { + File *string `yaml:"file"` + Level *string `yaml:"level"` +} + func New(cmd *cobra.Command) *Config { c := &Config{} cmd.PersistentFlags().StringVarP(&c.configPath, "config", "c", "config.yaml", "configuration file") diff --git a/pkg/gordio/server/logging.go b/pkg/gordio/server/logging.go new file mode 100644 index 0000000..03d9930 --- /dev/null +++ b/pkg/gordio/server/logging.go @@ -0,0 +1,110 @@ +package server + +import ( + "io" + "io/fs" + "os" + "os/signal" + "syscall" + + "dynatron.me/x/stillbox/pkg/gordio/config" + + "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 +} + +func NewLogger(cfg *config.Config) (*Logger, error) { + l := &Logger{ + console: &zerolog.ConsoleWriter{Out: os.Stderr}, + } + 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 + } + + log.Logger = log.Output(zerolog.MultiLevelWriter(l.writers...)) + } + }() + + signal.Notify(l.hup, syscall.SIGHUP) + + err := l.OpenLogs(cfg) + if err != nil { + return nil, err + } + + log.Logger = log.Output(zerolog.MultiLevelWriter(l.writers...)) + + return l, nil +} + +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_WRONLY|os.O_CREATE, LOGPERM) + if err != nil { + return err + } + + w.Writer = &zerolog.LevelWriterAdapter{ + Writer: f, + } + } + + l.writers = append(l.writers, w) + } + + return nil +} diff --git a/pkg/gordio/server/server.go b/pkg/gordio/server/server.go index e51fa6c..aace9c0 100644 --- a/pkg/gordio/server/server.go +++ b/pkg/gordio/server/server.go @@ -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) -- 2.48.1 From c1e3eece4d80aa0d35365c29ad4619a7cff9c2a4 Mon Sep 17 00:00:00 2001 From: Daniel Ponte Date: Thu, 17 Oct 2024 11:28:43 -0400 Subject: [PATCH 2/3] Add version flag --- Makefile | 5 ++++- cmd/gordio/main.go | 21 +++++++++++++++++++-- pkg/gordio/admin/admin.go | 7 ++++--- pkg/gordio/config/config.go | 16 ++++++++++++---- pkg/gordio/gordio.go | 7 ++++--- pkg/gordio/server/logging.go | 3 ++- pkg/gordio/server/server.go | 10 +++++----- 7 files changed, 50 insertions(+), 19 deletions(-) diff --git a/Makefile b/Makefile index a0ff802..9bb10ab 100644 --- a/Makefile +++ b/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: diff --git a/cmd/gordio/main.go b/cmd/gordio/main.go index 7521331..bcb2758 100644 --- a/cmd/gordio/main.go +++ b/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)...) diff --git a/pkg/gordio/admin/admin.go b/pkg/gordio/admin/admin.go index f81f7e4..04255cb 100644 --- a/pkg/gordio/admin/admin.go +++ b/pkg/gordio/admin/admin.go @@ -117,9 +117,10 @@ func readPassword(prompt string) (string, error) { // Command is the users command. func Command(cfg *config.Config) []*cobra.Command { userCmd := &cobra.Command{ - Use: "users", - Aliases: []string{"u"}, - Short: "administers the server", + Use: "users", + Aliases: []string{"u"}, + Short: "administers the server", + PersistentPreRunE: cfg.PreRunE(), } userCmd.AddCommand(addUserCommand(cfg), passwdCommand(cfg)) diff --git a/pkg/gordio/config/config.go b/pkg/gordio/config/config.go index a33c4ef..e7c758e 100644 --- a/pkg/gordio/config/config.go +++ b/pkg/gordio/config/config.go @@ -35,13 +35,21 @@ type DB struct { } type Logger struct { - File *string `yaml:"file"` - Level *string `yaml:"level"` + File *string `yaml:"file"` + Level *string `yaml:"level"` } -func New(cmd *cobra.Command) *Config { +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 } diff --git a/pkg/gordio/gordio.go b/pkg/gordio/gordio.go index 693c395..de7837d 100644 --- a/pkg/gordio/gordio.go +++ b/pkg/gordio/gordio.go @@ -17,9 +17,10 @@ type ServeOptions struct { func Command(cfg *config.Config) *cobra.Command { opts := makeOptions(cfg) serveCmd := &cobra.Command{ - Use: "serve", - Short: "starts the" + AppName + " server", - RunE: common.RunE(opts), + Use: "serve", + Short: "starts the" + AppName + " server", + PersistentPreRunE: cfg.PreRunE(), + RunE: common.RunE(opts), } return serveCmd diff --git a/pkg/gordio/server/logging.go b/pkg/gordio/server/logging.go index 03d9930..9ff4c4f 100644 --- a/pkg/gordio/server/logging.go +++ b/pkg/gordio/server/logging.go @@ -20,13 +20,14 @@ const ( type Logger struct { console io.Writer writers []io.Writer - hup chan os.Signal + hup chan os.Signal } func NewLogger(cfg *config.Config) (*Logger, error) { l := &Logger{ console: &zerolog.ConsoleWriter{Out: os.Stderr}, } + l.hup = make(chan os.Signal, 1) go func() { for sig := range l.hup { diff --git a/pkg/gordio/server/server.go b/pkg/gordio/server/server.go index aace9c0..0b870b0 100644 --- a/pkg/gordio/server/server.go +++ b/pkg/gordio/server/server.go @@ -40,11 +40,11 @@ func New(cfg *config.Config) (*Server, error) { r := chi.NewRouter() authenticator := auth.NewAuthenticator(cfg.Auth) srv := &Server{ - auth: authenticator, - conf: cfg, - db: db, - r: r, - nex: nexus.New(), + auth: authenticator, + conf: cfg, + db: db, + r: r, + nex: nexus.New(), logger: logger, } -- 2.48.1 From b84cfcc0257d0b66fab5928ee5bc526c3beeedd6 Mon Sep 17 00:00:00 2001 From: Daniel Ponte Date: Fri, 18 Oct 2024 00:15:21 -0400 Subject: [PATCH 3/3] Formatters --- pkg/gordio/server/logging.go | 106 +++++++++++++++++++++++++++++++++-- pkg/gordio/server/server.go | 5 +- 2 files changed, 103 insertions(+), 8 deletions(-) diff --git a/pkg/gordio/server/logging.go b/pkg/gordio/server/logging.go index 9ff4c4f..8ee84c9 100644 --- a/pkg/gordio/server/logging.go +++ b/pkg/gordio/server/logging.go @@ -1,14 +1,19 @@ 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" ) @@ -21,13 +26,22 @@ 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{ - console: &zerolog.ConsoleWriter{Out: os.Stderr}, + 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 { @@ -40,7 +54,7 @@ func NewLogger(cfg *config.Config) (*Logger, error) { continue } - log.Logger = log.Output(zerolog.MultiLevelWriter(l.writers...)) + l.Install() } }() @@ -51,11 +65,15 @@ func NewLogger(cfg *config.Config) (*Logger, error) { return nil, err } - log.Logger = log.Output(zerolog.MultiLevelWriter(l.writers...)) + 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 { @@ -94,7 +112,7 @@ func (l *Logger) OpenLogs(cfg *config.Config) error { case nil: w.Writer = &zerolog.LevelWriterAdapter{Writer: l.console} default: - f, err := os.OpenFile(*lc.File, os.O_WRONLY|os.O_CREATE, LOGPERM) + f, err := os.OpenFile(*lc.File, os.O_APPEND|os.O_WRONLY|os.O_CREATE, LOGPERM) if err != nil { return err } @@ -109,3 +127,81 @@ func (l *Logger) OpenLogs(cfg *config.Config) error { 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) +} diff --git a/pkg/gordio/server/server.go b/pkg/gordio/server/server.go index 0b870b0..2b7e9cb 100644 --- a/pkg/gordio/server/server.go +++ b/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" ) @@ -54,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"}, -- 2.48.1