diff --git a/cmd/inbucket/main.go b/cmd/inbucket/main.go index 17ccb0e..9423128 100644 --- a/cmd/inbucket/main.go +++ b/cmd/inbucket/main.go @@ -13,7 +13,6 @@ import ( "time" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/message" "github.com/jhillyerd/inbucket/pkg/msghub" "github.com/jhillyerd/inbucket/pkg/policy" @@ -25,6 +24,8 @@ import ( "github.com/jhillyerd/inbucket/pkg/storage/file" "github.com/jhillyerd/inbucket/pkg/storage/mem" "github.com/jhillyerd/inbucket/pkg/webui" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" ) var ( @@ -57,6 +58,7 @@ func main() { help := flag.Bool("help", false, "Displays help on flags and env variables.") pidfile := flag.String("pidfile", "", "Write our PID into the specified file.") logfile := flag.String("logfile", "stderr", "Write out log into the specified file.") + logjson := flag.Bool("logjson", false, "Logs are written in JSON format.") flag.Usage = func() { fmt.Fprintln(os.Stderr, "Usage: inbucket [options]") flag.PrintDefaults() @@ -68,6 +70,17 @@ func main() { config.Usage() return } + // Logger setup. + if !*logjson { + log.Logger = log.Output(zerolog.ConsoleWriter{Out: os.Stderr}) + zerolog.SetGlobalLevel(zerolog.DebugLevel) + } + _ = logfile + // } else if *logfile != "stderr" { + // // TODO #90 file output + // // defer close + // } + slog := log.With().Str("phase", "startup").Logger() // Process configuration. config.Version = version config.BuildDate = date @@ -80,23 +93,16 @@ func main() { sigChan := make(chan os.Signal, 1) signal.Notify(sigChan, syscall.SIGHUP, syscall.SIGTERM, syscall.SIGINT) // Initialize logging. - log.SetLogLevel(conf.LogLevel) - if err := log.Initialize(*logfile); err != nil { - fmt.Fprintf(os.Stderr, "%v", err) - os.Exit(1) - } - defer log.Close() - log.Infof("Inbucket %v (%v) starting...", config.Version, config.BuildDate) + slog.Info().Str("version", config.Version).Str("buildDate", config.BuildDate).Msg("Inbucket") // Write pidfile if requested. if *pidfile != "" { pidf, err := os.Create(*pidfile) if err != nil { - log.Errorf("Failed to create %q: %v", *pidfile, err) - os.Exit(1) + slog.Fatal().Err(err).Str("path", *pidfile).Msg("Failed to create pidfile") } fmt.Fprintf(pidf, "%v\n", os.Getpid()) if err := pidf.Close(); err != nil { - log.Errorf("Failed to close PID file %q: %v", *pidfile, err) + slog.Fatal().Err(err).Str("path", *pidfile).Msg("Failed to close pidfile") } } // Configure internal services. @@ -104,9 +110,8 @@ func main() { shutdownChan := make(chan bool) store, err := storage.FromConfig(conf.Storage) if err != nil { - log.Errorf("Fatal storage error: %v", err) removePIDFile(*pidfile) - os.Exit(1) + slog.Fatal().Err(err).Str("module", "storage").Msg("Fatal storage error") } msgHub := msghub.New(rootCtx, conf.Web.MonitorHistory) addrPolicy := &policy.Addressing{Config: conf.SMTP} @@ -132,15 +137,17 @@ signalLoop: case sig := <-sigChan: switch sig { case syscall.SIGHUP: - log.Infof("Recieved SIGHUP, cycling logfile") - log.Rotate() + log.Info().Str("signal", "SIGHUP").Msg("Recieved SIGHUP, cycling logfile") + // TODO #90 log.Rotate() case syscall.SIGINT: // Shutdown requested - log.Infof("Received SIGINT, shutting down") + log.Info().Str("phase", "shutdown").Str("signal", "SIGINT"). + Msg("Received SIGINT, shutting down") close(shutdownChan) case syscall.SIGTERM: // Shutdown requested - log.Infof("Received SIGTERM, shutting down") + log.Info().Str("phase", "shutdown").Str("signal", "SIGTERM"). + Msg("Received SIGTERM, shutting down") close(shutdownChan) } case <-shutdownChan: @@ -160,7 +167,8 @@ signalLoop: func removePIDFile(pidfile string) { if pidfile != "" { if err := os.Remove(pidfile); err != nil { - log.Errorf("Failed to remove %q: %v", pidfile, err) + log.Error().Str("phase", "shutdown").Err(err).Str("path", pidfile). + Msg("Failed to remove pidfile") } } } @@ -168,7 +176,7 @@ func removePIDFile(pidfile string) { // timedExit is called as a goroutine during shutdown, it will force an exit after 15 seconds. func timedExit(pidfile string) { time.Sleep(15 * time.Second) - log.Errorf("Clean shutdown took too long, forcing exit") removePIDFile(pidfile) + log.Error().Str("phase", "shutdown").Msg("Clean shutdown took too long, forcing exit") os.Exit(0) } diff --git a/pkg/rest/apiv1_controller.go b/pkg/rest/apiv1_controller.go index 34dea29..adef527 100644 --- a/pkg/rest/apiv1_controller.go +++ b/pkg/rest/apiv1_controller.go @@ -9,7 +9,6 @@ import ( "encoding/hex" "strconv" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/rest/model" "github.com/jhillyerd/inbucket/pkg/server/web" "github.com/jhillyerd/inbucket/pkg/storage" @@ -28,8 +27,6 @@ func MailboxListV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) ( // This doesn't indicate empty, likely an IO error return fmt.Errorf("Failed to get messages for %v: %v", name, err) } - log.Tracef("Got %v messsages", len(messages)) - jmessages := make([]*model.JSONMessageHeaderV1, len(messages)) for i, msg := range messages { jmessages[i] = &model.JSONMessageHeaderV1{ @@ -62,7 +59,6 @@ func MailboxShowV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) ( // This doesn't indicate empty, likely an IO error return fmt.Errorf("GetMessage(%q) failed: %v", id, err) } - attachParts := msg.Attachments() attachments := make([]*model.JSONMessageAttachmentV1, len(attachParts)) for i, part := range attachParts { @@ -78,7 +74,6 @@ func MailboxShowV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) ( MD5: hex.EncodeToString(checksum[:]), } } - return web.RenderJSON(w, &model.JSONMessageV1{ Mailbox: name, @@ -109,8 +104,6 @@ func MailboxPurgeV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) if err != nil { return fmt.Errorf("Mailbox(%q) purge failed: %v", name, err) } - log.Tracef("HTTP purged mailbox for %q", name) - return web.RenderJSON(w, "OK") } @@ -122,7 +115,6 @@ func MailboxSourceV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) if err != nil { return err } - r, err := ctx.Manager.SourceReader(name, id) if err == storage.ErrNotExist { http.NotFound(w, req) @@ -155,6 +147,5 @@ func MailboxDeleteV1(w http.ResponseWriter, req *http.Request, ctx *web.Context) // This doesn't indicate missing, likely an IO error return fmt.Errorf("RemoveMessage(%q) failed: %v", id, err) } - return web.RenderJSON(w, "OK") } diff --git a/pkg/rest/socketv1_controller.go b/pkg/rest/socketv1_controller.go index d0ceddd..7c5b019 100644 --- a/pkg/rest/socketv1_controller.go +++ b/pkg/rest/socketv1_controller.go @@ -5,10 +5,10 @@ import ( "time" "github.com/gorilla/websocket" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/msghub" "github.com/jhillyerd/inbucket/pkg/rest/model" "github.com/jhillyerd/inbucket/pkg/server/web" + "github.com/rs/zerolog/log" ) const ( @@ -62,11 +62,13 @@ func (ml *msgListener) Receive(msg msghub.Message) error { // WSReader makes sure the websocket client is still connected, discards any messages from client func (ml *msgListener) WSReader(conn *websocket.Conn) { + slog := log.With().Str("module", "rest").Str("proto", "WebSocket"). + Str("remote", conn.RemoteAddr().String()).Logger() defer ml.Close() conn.SetReadLimit(maxMessageSize) conn.SetReadDeadline(time.Now().Add(pongWait)) conn.SetPongHandler(func(string) error { - log.Tracef("HTTP[%v] Got WebSocket pong", conn.RemoteAddr()) + slog.Debug().Msg("Got pong") conn.SetReadDeadline(time.Now().Add(pongWait)) return nil }) @@ -80,9 +82,9 @@ func (ml *msgListener) WSReader(conn *websocket.Conn) { websocket.CloseNoStatusReceived, ) { // Unexpected close code - log.Warnf("HTTP[%v] WebSocket error: %v", conn.RemoteAddr(), err) + slog.Warn().Err(err).Msg("Socket error") } else { - log.Tracef("HTTP[%v] Closing WebSocket", conn.RemoteAddr()) + slog.Debug().Msg("Closing socket") } break } @@ -127,7 +129,8 @@ func (ml *msgListener) WSWriter(conn *websocket.Conn) { // Write error return } - log.Tracef("HTTP[%v] Sent WebSocket ping", conn.RemoteAddr()) + log.Debug().Str("module", "rest").Str("proto", "WebSocket"). + Str("remote", conn.RemoteAddr().String()).Msg("Sent ping") } } } @@ -147,7 +150,7 @@ func (ml *msgListener) Close() { // the client of all messages received. func MonitorAllMessagesV1( w http.ResponseWriter, req *http.Request, ctx *web.Context) (err error) { - // Upgrade to Websocket + // Upgrade to Websocket. conn, err := upgrader.Upgrade(w, req, nil) if err != nil { return err @@ -157,14 +160,12 @@ func MonitorAllMessagesV1( _ = conn.Close() web.ExpWebSocketConnectsCurrent.Add(-1) }() - - log.Tracef("HTTP[%v] Upgraded to websocket", req.RemoteAddr) - - // Create, register listener; then interact with conn + log.Debug().Str("module", "rest").Str("proto", "WebSocket"). + Str("remote", conn.RemoteAddr().String()).Msg("Upgraded to WebSocket") + // Create, register listener; then interact with conn. ml := newMsgListener(ctx.MsgHub, "") go ml.WSWriter(conn) ml.WSReader(conn) - return nil } @@ -176,7 +177,7 @@ func MonitorMailboxMessagesV1( if err != nil { return err } - // Upgrade to Websocket + // Upgrade to Websocket. conn, err := upgrader.Upgrade(w, req, nil) if err != nil { return err @@ -186,13 +187,11 @@ func MonitorMailboxMessagesV1( _ = conn.Close() web.ExpWebSocketConnectsCurrent.Add(-1) }() - - log.Tracef("HTTP[%v] Upgraded to websocket", req.RemoteAddr) - - // Create, register listener; then interact with conn + log.Debug().Str("module", "rest").Str("proto", "WebSocket"). + Str("remote", conn.RemoteAddr().String()).Msg("Upgraded to WebSocket") + // Create, register listener; then interact with conn. ml := newMsgListener(ctx.MsgHub, name) go ml.WSWriter(conn) ml.WSReader(conn) - return nil } diff --git a/pkg/server/pop3/listener.go b/pkg/server/pop3/listener.go index 2db2d00..bf9d6fd 100644 --- a/pkg/server/pop3/listener.go +++ b/pkg/server/pop3/listener.go @@ -7,8 +7,8 @@ import ( "time" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/storage" + "github.com/rs/zerolog/log" ) // Server defines an instance of our POP3 server @@ -36,44 +36,42 @@ func New(cfg config.POP3, shutdownChan chan bool, store storage.Store) *Server { // Start the server and listen for connections func (s *Server) Start(ctx context.Context) { + slog := log.With().Str("module", "pop3").Str("phase", "startup").Logger() addr, err := net.ResolveTCPAddr("tcp4", s.host) if err != nil { - log.Errorf("POP3 Failed to build tcp4 address: %v", err) + slog.Error().Err(err).Msg("Failed to build tcp4 address") s.emergencyShutdown() return } - - log.Infof("POP3 listening on TCP4 %v", addr) + slog.Info().Str("addr", addr.String()).Msg("POP3 listening on tcp4") s.listener, err = net.ListenTCP("tcp4", addr) if err != nil { - log.Errorf("POP3 failed to start tcp4 listener: %v", err) + slog.Error().Err(err).Msg("Failed to start tcp4 listener") s.emergencyShutdown() return } - - // Listener go routine + // Listener go routine. go s.serve(ctx) - - // Wait for shutdown + // Wait for shutdown. select { case _ = <-ctx.Done(): } - - log.Tracef("POP3 shutdown requested, connections will be drained") - // Closing the listener will cause the serve() go routine to exit + slog = log.With().Str("module", "pop3").Str("phase", "shutdown").Logger() + slog.Debug().Msg("POP3 shutdown requested, connections will be drained") + // Closing the listener will cause the serve() go routine to exit. if err := s.listener.Close(); err != nil { - log.Errorf("Error closing POP3 listener: %v", err) + slog.Error().Err(err).Msg("Failed to close POP3 listener") } } -// serve is the listen/accept loop +// serve is the listen/accept loop. func (s *Server) serve(ctx context.Context) { - // Handle incoming connections + // Handle incoming connections. var tempDelay time.Duration for sid := 1; ; sid++ { if conn, err := s.listener.Accept(); err != nil { if nerr, ok := err.(net.Error); ok && nerr.Temporary() { - // Temporary error, sleep for a bit and try again + // Temporary error, sleep for a bit and try again. if tempDelay == 0 { tempDelay = 5 * time.Millisecond } else { @@ -82,17 +80,18 @@ func (s *Server) serve(ctx context.Context) { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - log.Errorf("POP3 accept error: %v; retrying in %v", err, tempDelay) + log.Error().Str("module", "pop3").Err(err). + Msgf("POP3 accept error; retrying in %v", tempDelay) time.Sleep(tempDelay) continue } else { - // Permanent error + // Permanent error. select { case <-ctx.Done(): - // POP3 is shutting down + // POP3 is shutting down. return default: - // Something went wrong + // Something went wrong. s.emergencyShutdown() return } @@ -118,5 +117,5 @@ func (s *Server) emergencyShutdown() { func (s *Server) Drain() { // Wait for sessions to close s.waitgroup.Wait() - log.Tracef("POP3 connections have drained") + log.Debug().Str("module", "pop3").Str("phase", "shutdown").Msg("POP3 connections have drained") } diff --git a/pkg/server/smtp/listener.go b/pkg/server/smtp/listener.go index 339e32e..d566e15 100644 --- a/pkg/server/smtp/listener.go +++ b/pkg/server/smtp/listener.go @@ -10,9 +10,9 @@ import ( "time" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/message" "github.com/jhillyerd/inbucket/pkg/policy" + "github.com/rs/zerolog/log" ) func init() { @@ -27,12 +27,13 @@ func init() { m.Set("WarnsTotal", expWarnsTotal) m.Set("WarnsHist", expWarnsHist) - log.AddTickerFunc(func() { - expReceivedHist.Set(log.PushMetric(deliveredHist, expReceivedTotal)) - expConnectsHist.Set(log.PushMetric(connectsHist, expConnectsTotal)) - expErrorsHist.Set(log.PushMetric(errorsHist, expErrorsTotal)) - expWarnsHist.Set(log.PushMetric(warnsHist, expWarnsTotal)) - }) + // TODO #90 move elsewhere + // log.AddTickerFunc(func() { + // expReceivedHist.Set(log.PushMetric(deliveredHist, expReceivedTotal)) + // expConnectsHist.Set(log.PushMetric(connectsHist, expConnectsTotal)) + // expErrorsHist.Set(log.PushMetric(errorsHist, expErrorsTotal)) + // expWarnsHist.Set(log.PushMetric(warnsHist, expWarnsTotal)) + // }) } // Server holds the configuration and state of our SMTP server @@ -99,51 +100,48 @@ func NewServer( } } -// Start the listener and handle incoming connections +// Start the listener and handle incoming connections. func (s *Server) Start(ctx context.Context) { + slog := log.With().Str("module", "smtp").Str("phase", "startup").Logger() addr, err := net.ResolveTCPAddr("tcp4", s.host) if err != nil { - log.Errorf("Failed to build tcp4 address: %v", err) + slog.Error().Err(err).Msg("Failed to build tcp4 address") s.emergencyShutdown() return } - - log.Infof("SMTP listening on TCP4 %v", addr) + slog.Info().Str("addr", addr.String()).Msg("SMTP listening on tcp4") s.listener, err = net.ListenTCP("tcp4", addr) if err != nil { - log.Errorf("SMTP failed to start tcp4 listener: %v", err) + slog.Error().Err(err).Msg("Failed to start tcp4 listener") s.emergencyShutdown() return } - if !s.storeMessages { - log.Infof("Load test mode active, messages will not be stored") + slog.Info().Msg("Load test mode active, messages will not be stored") } else if s.domainNoStore != "" { - log.Infof("Messages sent to domain '%v' will be discarded", s.domainNoStore) + slog.Info().Msgf("Messages sent to domain '%v' will be discarded", s.domainNoStore) } - - // Listener go routine + // Listener go routine. go s.serve(ctx) - - // Wait for shutdown + // Wait for shutdown. <-ctx.Done() - log.Tracef("SMTP shutdown requested, connections will be drained") - - // Closing the listener will cause the serve() go routine to exit + slog = log.With().Str("module", "smtp").Str("phase", "shutdown").Logger() + slog.Debug().Msg("SMTP shutdown requested, connections will be drained") + // Closing the listener will cause the serve() go routine to exit. if err := s.listener.Close(); err != nil { - log.Errorf("Failed to close SMTP listener: %v", err) + slog.Error().Err(err).Msg("Failed to close SMTP listener") } } -// serve is the listen/accept loop +// serve is the listen/accept loop. func (s *Server) serve(ctx context.Context) { - // Handle incoming connections + // Handle incoming connections. var tempDelay time.Duration for sessionID := 1; ; sessionID++ { if conn, err := s.listener.Accept(); err != nil { - // There was an error accepting the connection + // There was an error accepting the connection. if nerr, ok := err.(net.Error); ok && nerr.Temporary() { - // Temporary error, sleep for a bit and try again + // Temporary error, sleep for a bit and try again. if tempDelay == 0 { tempDelay = 5 * time.Millisecond } else { @@ -152,17 +150,18 @@ func (s *Server) serve(ctx context.Context) { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - log.Errorf("SMTP accept error: %v; retrying in %v", err, tempDelay) + log.Error().Str("module", "smtp").Err(err). + Msgf("SMTP accept error; retrying in %v", tempDelay) time.Sleep(tempDelay) continue } else { - // Permanent error + // Permanent error. select { case <-ctx.Done(): - // SMTP is shutting down + // SMTP is shutting down. return default: - // Something went wrong + // Something went wrong. s.emergencyShutdown() return } @@ -177,7 +176,7 @@ func (s *Server) serve(ctx context.Context) { } func (s *Server) emergencyShutdown() { - // Shutdown Inbucket + // Shutdown Inbucket. select { case <-s.globalShutdown: default: @@ -187,7 +186,7 @@ func (s *Server) emergencyShutdown() { // Drain causes the caller to block until all active SMTP sessions have finished func (s *Server) Drain() { - // Wait for sessions to close + // Wait for sessions to close. s.waitgroup.Wait() - log.Tracef("SMTP connections have drained") + log.Debug().Str("module", "smtp").Str("phase", "shutdown").Msg("SMTP connections have drained") } diff --git a/pkg/server/web/helpers.go b/pkg/server/web/helpers.go index c41e1e6..60d2edc 100644 --- a/pkg/server/web/helpers.go +++ b/pkg/server/web/helpers.go @@ -8,7 +8,7 @@ import ( "strings" "time" - "github.com/jhillyerd/inbucket/pkg/log" + "github.com/rs/zerolog/log" ) // TemplateFuncs declares functions made available to all templates (including partials) @@ -42,7 +42,8 @@ func Reverse(name string, things ...interface{}) string { // Grab the route u, err := Router.Get(name).URL(strs...) if err != nil { - log.Errorf("Failed to reverse route: %v", err) + log.Error().Str("module", "web").Str("name", name).Err(err). + Msg("Failed to reverse route") return "/ROUTE-ERROR" } return u.Path diff --git a/pkg/server/web/server.go b/pkg/server/web/server.go index 8e5524c..a60735a 100644 --- a/pkg/server/web/server.go +++ b/pkg/server/web/server.go @@ -13,9 +13,9 @@ import ( "github.com/gorilla/securecookie" "github.com/gorilla/sessions" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/message" "github.com/jhillyerd/inbucket/pkg/msghub" + "github.com/rs/zerolog/log" ) // Handler is a function type that handles an HTTP request in Inbucket @@ -66,17 +66,20 @@ func Initialize( // Content Paths staticPath := filepath.Join(conf.Web.UIDir, staticDir) - log.Infof("Web UI content mapped to path: %s", conf.Web.UIDir) + log.Info().Str("module", "web").Str("phase", "startup").Str("path", conf.Web.UIDir). + Msg("Web UI content mapped") Router.PathPrefix("/public/").Handler(http.StripPrefix("/public/", http.FileServer(http.Dir(staticPath)))) http.Handle("/", Router) // Session cookie setup if conf.Web.CookieAuthKey == "" { - log.Infof("HTTP generating random cookie.auth.key") + log.Info().Str("module", "web").Str("phase", "startup"). + Msg("Generating random cookie.auth.key") sessionStore = sessions.NewCookieStore(securecookie.GenerateRandomKey(64)) } else { - log.Tracef("HTTP using configured cookie.auth.key") + log.Info().Str("module", "web").Str("phase", "startup"). + Msg("Using configured cookie.auth.key") sessionStore = sessions.NewCookieStore([]byte(conf.Web.CookieAuthKey)) } } @@ -91,11 +94,13 @@ func Start(ctx context.Context) { } // We don't use ListenAndServe because it lacks a way to close the listener - log.Infof("HTTP listening on TCP4 %v", server.Addr) + log.Info().Str("module", "web").Str("phase", "startup").Str("addr", server.Addr). + Msg("HTTP listening on tcp4") var err error listener, err = net.Listen("tcp", server.Addr) if err != nil { - log.Errorf("HTTP failed to start TCP4 listener: %v", err) + log.Error().Str("module", "web").Str("phase", "startup").Err(err). + Msg("HTTP failed to start TCP4 listener") emergencyShutdown() return } @@ -106,12 +111,14 @@ func Start(ctx context.Context) { // Wait for shutdown select { case _ = <-ctx.Done(): - log.Tracef("HTTP server shutting down on request") + log.Debug().Str("module", "web").Str("phase", "shutdown"). + Msg("HTTP server shutting down on request") } // Closing the listener will cause the serve() go routine to exit if err := listener.Close(); err != nil { - log.Errorf("Failed to close HTTP listener: %v", err) + log.Debug().Str("module", "web").Str("phase", "shutdown").Err(err). + Msg("Failed to close HTTP listener") } } @@ -124,7 +131,8 @@ func serve(ctx context.Context) { case _ = <-ctx.Done(): // Nop default: - log.Errorf("HTTP server failed: %v", err) + log.Error().Str("module", "web").Str("phase", "startup").Err(err). + Msg("HTTP server failed") emergencyShutdown() return } @@ -135,17 +143,19 @@ func (h Handler) ServeHTTP(w http.ResponseWriter, req *http.Request) { // Create the context ctx, err := NewContext(req) if err != nil { - log.Errorf("HTTP failed to create context: %v", err) + log.Error().Str("module", "web").Err(err).Msg("HTTP failed to create context") http.Error(w, err.Error(), http.StatusInternalServerError) return } defer ctx.Close() // Run the handler, grab the error, and report it - log.Tracef("HTTP[%v] %v %v %q", req.RemoteAddr, req.Proto, req.Method, req.RequestURI) + log.Debug().Str("module", "web").Str("remote", req.RemoteAddr).Str("proto", req.Proto). + Str("method", req.Method).Str("path", req.RequestURI).Msg("Request") err = h(w, req, ctx) if err != nil { - log.Errorf("HTTP error handling %q: %v", req.RequestURI, err) + log.Error().Str("module", "web").Str("path", req.RequestURI).Err(err). + Msg("Error handling request") http.Error(w, err.Error(), http.StatusInternalServerError) return } diff --git a/pkg/server/web/template.go b/pkg/server/web/template.go index 87675a5..f9f8da2 100644 --- a/pkg/server/web/template.go +++ b/pkg/server/web/template.go @@ -7,7 +7,7 @@ import ( "path/filepath" "sync" - "github.com/jhillyerd/inbucket/pkg/log" + "github.com/rs/zerolog/log" ) var cachedMutex sync.Mutex @@ -19,7 +19,8 @@ var cachedPartials = map[string]*template.Template{} func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error { t, err := ParseTemplate(name, false) if err != nil { - log.Errorf("Error in template '%v': %v", name, err) + log.Error().Str("module", "web").Str("path", name).Err(err). + Msg("Error in template") return err } w.Header().Set("Expires", "-1") @@ -31,7 +32,8 @@ func RenderTemplate(name string, w http.ResponseWriter, data interface{}) error func RenderPartial(name string, w http.ResponseWriter, data interface{}) error { t, err := ParseTemplate(name, true) if err != nil { - log.Errorf("Error in template '%v': %v", name, err) + log.Error().Str("module", "web").Str("path", name).Err(err). + Msg("Error in template") return err } w.Header().Set("Expires", "-1") @@ -49,7 +51,7 @@ func ParseTemplate(name string, partial bool) (*template.Template, error) { } tempFile := filepath.Join(rootConfig.Web.UIDir, templateDir, filepath.FromSlash(name)) - log.Tracef("Parsing template %v", tempFile) + log.Debug().Str("module", "web").Str("path", name).Msg("Parsing template") var err error var t *template.Template @@ -70,10 +72,10 @@ func ParseTemplate(name string, partial bool) (*template.Template, error) { // Allows us to disable caching for theme development if rootConfig.Web.TemplateCache { if partial { - log.Tracef("Caching partial %v", name) + log.Debug().Str("module", "web").Str("path", name).Msg("Caching partial") cachedTemplates[name] = t } else { - log.Tracef("Caching template %v", name) + log.Debug().Str("module", "web").Str("path", name).Msg("Caching template") cachedTemplates[name] = t } } diff --git a/pkg/storage/file/fmessage.go b/pkg/storage/file/fmessage.go index 79d1a65..961df62 100644 --- a/pkg/storage/file/fmessage.go +++ b/pkg/storage/file/fmessage.go @@ -7,7 +7,7 @@ import ( "path/filepath" "time" - "github.com/jhillyerd/inbucket/pkg/log" + "github.com/rs/zerolog/log" ) // Message implements Message and contains a little bit of data about a @@ -35,9 +35,12 @@ func (mb *mbox) newMessage() (*Message, error) { // Delete old messages over messageCap if mb.store.messageCap > 0 { for len(mb.messages) >= mb.store.messageCap { - log.Infof("Mailbox %q over configured message cap", mb.name) - if err := mb.removeMessage(mb.messages[0].ID()); err != nil { - log.Errorf("Error deleting message: %s", err) + log.Info().Str("module", "storage").Str("mailbox", mb.name). + Msg("Mailbox over message cap") + id := mb.messages[0].ID() + if err := mb.removeMessage(id); err != nil { + log.Error().Str("module", "storage").Str("mailbox", mb.name).Str("id", id). + Err(err).Msg("Unable to delete message") } } } diff --git a/pkg/storage/file/fstore.go b/pkg/storage/file/fstore.go index fa00f3c..75ec3ba 100644 --- a/pkg/storage/file/fstore.go +++ b/pkg/storage/file/fstore.go @@ -10,10 +10,10 @@ import ( "time" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/policy" "github.com/jhillyerd/inbucket/pkg/storage" "github.com/jhillyerd/inbucket/pkg/stringutil" + "github.com/rs/zerolog/log" ) // Name of index file in each mailbox @@ -57,7 +57,8 @@ func New(cfg config.Storage) (storage.Store, error) { if _, err := os.Stat(mailPath); err != nil { // Mail datastore does not yet exist if err = os.MkdirAll(mailPath, 0770); err != nil { - log.Errorf("Error creating dir %q: %v", mailPath, err) + log.Error().Str("module", "storage").Str("path", mailPath).Err(err). + Msg("Error creating dir") } } return &Store{path: path, mailPath: mailPath, messageCap: cfg.MailboxMsgCap}, nil diff --git a/pkg/storage/file/mbox.go b/pkg/storage/file/mbox.go index 9a59984..8c85145 100644 --- a/pkg/storage/file/mbox.go +++ b/pkg/storage/file/mbox.go @@ -9,8 +9,8 @@ import ( "path/filepath" "sync" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/storage" + "github.com/rs/zerolog/log" ) // mbox manages the mail for a specific user and correlates to a particular directory on disk. @@ -87,7 +87,7 @@ func (mb *mbox) removeMessage(id string) error { return nil } // There are still messages in the index - log.Tracef("Deleting %v", msg.rawPath()) + log.Debug().Str("module", "storage").Str("path", msg.rawPath()).Msg("Deleting file") return os.Remove(msg.rawPath()) } @@ -104,7 +104,8 @@ func (mb *mbox) readIndex() error { // Check if index exists if _, err := os.Stat(mb.indexPath); err != nil { // Does not exist, but that's not an error in our world - log.Tracef("Index %v does not exist (yet)", mb.indexPath) + log.Debug().Str("module", "storage").Str("path", mb.indexPath). + Msg("Index does not yet exist") mb.indexLoaded = true return nil } @@ -114,7 +115,8 @@ func (mb *mbox) readIndex() error { } defer func() { if err := file.Close(); err != nil { - log.Errorf("Failed to close %q: %v", mb.indexPath, err) + log.Error().Str("module", "storage").Str("path", mb.indexPath).Err(err). + Msg("Failed to close") } }() // Decode gob data @@ -171,12 +173,13 @@ func (mb *mbox) writeIndex() error { return err } if err := file.Close(); err != nil { - log.Errorf("Failed to close %q: %v", mb.indexPath, err) + log.Error().Str("module", "storage").Str("path", mb.indexPath).Err(err). + Msg("Failed to close") return err } } else { // No messages, delete index+maildir - log.Tracef("Removing mailbox %v", mb.path) + log.Debug().Str("module", "storage").Str("path", mb.path).Msg("Removing mailbox") return mb.removeDir() } return nil @@ -186,7 +189,8 @@ func (mb *mbox) writeIndex() error { func (mb *mbox) createDir() error { if _, err := os.Stat(mb.path); err != nil { if err := os.MkdirAll(mb.path, 0770); err != nil { - log.Errorf("Failed to create directory %v, %v", mb.path, err) + log.Error().Str("module", "storage").Str("path", mb.path).Err(err). + Msg("Failed to create directory") return err } } @@ -223,10 +227,10 @@ func removeDirIfEmpty(path string) (removed bool) { // Dir not empty return false } - log.Tracef("Removing dir %v", path) + log.Debug().Str("module", "storage").Str("path", path).Msg("Removing dir") err = os.Remove(path) if err != nil { - log.Errorf("Failed to remove %q: %v", path, err) + log.Error().Str("module", "storage").Str("path", path).Err(err).Msg("Failed to remove") return false } return true diff --git a/pkg/storage/retention.go b/pkg/storage/retention.go index c17e725..6a0b714 100644 --- a/pkg/storage/retention.go +++ b/pkg/storage/retention.go @@ -7,7 +7,7 @@ import ( "time" "github.com/jhillyerd/inbucket/pkg/config" - "github.com/jhillyerd/inbucket/pkg/log" + "github.com/rs/zerolog/log" ) var ( @@ -42,11 +42,12 @@ func init() { rm.Set("RetainedSize", expRetainedSize) rm.Set("SizeHist", expSizeHist) - log.AddTickerFunc(func() { - expRetentionDeletesHist.Set(log.PushMetric(retentionDeletesHist, expRetentionDeletesTotal)) - expRetainedHist.Set(log.PushMetric(retainedHist, expRetainedCurrent)) - expSizeHist.Set(log.PushMetric(sizeHist, expRetainedSize)) - }) + // TODO #90 move + // log.AddTickerFunc(func() { + // expRetentionDeletesHist.Set(log.PushMetric(retentionDeletesHist, expRetentionDeletesTotal)) + // expRetainedHist.Set(log.PushMetric(retainedHist, expRetainedCurrent)) + // expSizeHist.Set(log.PushMetric(sizeHist, expRetainedSize)) + // }) } // RetentionScanner looks for messages older than the configured retention period and deletes them. @@ -79,16 +80,18 @@ func NewRetentionScanner( // Start up the retention scanner if retention period > 0 func (rs *RetentionScanner) Start() { if rs.retentionPeriod <= 0 { - log.Infof("Retention scanner disabled") + log.Info().Str("phase", "startup").Str("module", "storage").Msg("Retention scanner disabled") close(rs.retentionShutdown) return } - log.Infof("Retention configured for %v", rs.retentionPeriod) + log.Info().Str("phase", "startup").Str("module", "storage"). + Msgf("Retention configured for %v", rs.retentionPeriod) go rs.run() } // run loops to kick off the scanner on the correct schedule func (rs *RetentionScanner) run() { + slog := log.With().Str("module", "storage").Logger() start := time.Now() retentionLoop: for { @@ -96,7 +99,7 @@ retentionLoop: since := time.Since(start) if since < time.Minute { dur := time.Minute - since - log.Tracef("Retention scanner sleeping for %v", dur) + slog.Debug().Msgf("Retention scanner sleeping for %v", dur) select { case <-rs.globalShutdown: break retentionLoop @@ -106,7 +109,7 @@ retentionLoop: // Kickoff scan start = time.Now() if err := rs.DoScan(); err != nil { - log.Errorf("Error during retention scan: %v", err) + slog.Error().Err(err).Msg("Error during retention scan") } // Check for global shutdown select { @@ -115,13 +118,14 @@ retentionLoop: default: } } - log.Tracef("Retention scanner shut down") + slog.Debug().Str("phase", "shutdown").Msg("Retention scanner shut down") close(rs.retentionShutdown) } // DoScan does a single pass of all mailboxes looking for messages that can be purged. func (rs *RetentionScanner) DoScan() error { - log.Tracef("Starting retention scan") + slog := log.With().Str("module", "storage").Logger() + slog.Debug().Msg("Starting retention scan") cutoff := time.Now().Add(-1 * rs.retentionPeriod) retained := 0 storeSize := int64(0) @@ -129,9 +133,11 @@ func (rs *RetentionScanner) DoScan() error { err := rs.ds.VisitMailboxes(func(messages []Message) bool { for _, msg := range messages { if msg.Date().Before(cutoff) { - log.Tracef("Purging expired message %v/%v", msg.Mailbox(), msg.ID()) + slog.Debug().Str("mailbox", msg.Mailbox()). + Msgf("Purging expired message %v", msg.ID()) if err := rs.ds.RemoveMessage(msg.Mailbox(), msg.ID()); err != nil { - log.Errorf("Failed to purge message %v: %v", msg.ID(), err) + slog.Error().Str("mailbox", msg.Mailbox()).Err(err). + Msgf("Failed to purge message %v", msg.ID()) } else { expRetentionDeletesTotal.Add(1) } @@ -142,7 +148,7 @@ func (rs *RetentionScanner) DoScan() error { } select { case <-rs.globalShutdown: - log.Tracef("Retention scan aborted due to shutdown") + slog.Debug().Str("phase", "shutdown").Msg("Retention scan aborted due to shutdown") return false case <-time.After(rs.retentionSleep): // Reduce disk thrashing diff --git a/pkg/webui/mailbox_controller.go b/pkg/webui/mailbox_controller.go index e835d78..199b5e4 100644 --- a/pkg/webui/mailbox_controller.go +++ b/pkg/webui/mailbox_controller.go @@ -7,10 +7,10 @@ import ( "net/http" "strconv" - "github.com/jhillyerd/inbucket/pkg/log" "github.com/jhillyerd/inbucket/pkg/server/web" "github.com/jhillyerd/inbucket/pkg/storage" "github.com/jhillyerd/inbucket/pkg/webui/sanitize" + "github.com/rs/zerolog/log" ) // MailboxIndex renders the index page for a particular mailbox @@ -76,7 +76,6 @@ func MailboxList(w http.ResponseWriter, req *http.Request, ctx *web.Context) (er // This doesn't indicate empty, likely an IO error return fmt.Errorf("Failed to get messages for %v: %v", name, err) } - log.Tracef("Got %v messsages", len(messages)) // Render partial template return web.RenderPartial("mailbox/_list.html", w, map[string]interface{}{ "ctx": ctx, @@ -109,7 +108,9 @@ func MailboxShow(w http.ResponseWriter, req *http.Request, ctx *web.Context) (er if str, err := sanitize.HTML(msg.HTML()); err == nil { htmlBody = template.HTML(str) } else { - log.Warnf("HTML sanitizer failed: %s", err) + // Soft failure, render empty tab. + log.Warn().Str("module", "webui").Str("mailbox", name).Str("id", id).Err(err). + Msg("HTML sanitizer failed") } } // Render partial template