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/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/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/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 c8f0a8b..e7c758e 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,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 } 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 new file mode 100644 index 0000000..8ee84c9 --- /dev/null +++ b/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) +} diff --git a/pkg/gordio/server/server.go b/pkg/gordio/server/server.go index e51fa6c..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" ) @@ -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 @@ -34,11 +40,12 @@ 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, } 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"},