Replace pkg/log with zerolog for normal logging #90

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)
+	slog.Info().Str("version", config.Version).Str("buildDate", config.BuildDate).Msg("Inbucket")
-	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)
 	// Write pidfile if requested.
 	if *pidfile != "" {
 		pidf, err := os.Create(*pidfile)
 		if err != nil {
-			log.Errorf("Failed to create %q: %v", *pidfile, err)
+			slog.Fatal().Err(err).Str("path", *pidfile).Msg("Failed to create pidfile")
-			os.Exit(1)
 		}
 		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.Info().Str("signal", "SIGHUP").Msg("Recieved SIGHUP, cycling logfile")
-				log.Rotate()
+				// 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)
 }

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")
 }

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.Debug().Str("module", "rest").Str("proto", "WebSocket").
-	log.Tracef("HTTP[%v] Upgraded to websocket", req.RemoteAddr)
+		Str("remote", conn.RemoteAddr().String()).Msg("Upgraded to WebSocket")
-
+	// Create, register listener; then interact with conn.
-	// 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.Debug().Str("module", "rest").Str("proto", "WebSocket").
-	log.Tracef("HTTP[%v] Upgraded to websocket", req.RemoteAddr)
+		Str("remote", conn.RemoteAddr().String()).Msg("Upgraded to WebSocket")
-
+	// Create, register listener; then interact with conn.
-	// Create, register listener; then interact with conn
 	ml := newMsgListener(ctx.MsgHub, name)
 	go ml.WSWriter(conn)
 	ml.WSReader(conn)
-
 	return nil
 }

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
 	}
-
+	slog.Info().Str("addr", addr.String()).Msg("POP3 listening on tcp4")
-	log.Infof("POP3 listening on TCP4 %v", addr)
 	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():
 	}
-
+	slog = log.With().Str("module", "pop3").Str("phase", "shutdown").Logger()
-	log.Tracef("POP3 shutdown requested, connections will be drained")
+	slog.Debug().Msg("POP3 shutdown requested, connections will be drained")
-	// Closing the listener will cause the serve() go routine to exit
+	// 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")
 }

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() {
+	// TODO #90 move elsewhere
-		expReceivedHist.Set(log.PushMetric(deliveredHist, expReceivedTotal))
+	// log.AddTickerFunc(func() {
-		expConnectsHist.Set(log.PushMetric(connectsHist, expConnectsTotal))
+	// 	expReceivedHist.Set(log.PushMetric(deliveredHist, expReceivedTotal))
-		expErrorsHist.Set(log.PushMetric(errorsHist, expErrorsTotal))
+	// 	expConnectsHist.Set(log.PushMetric(connectsHist, expConnectsTotal))
-		expWarnsHist.Set(log.PushMetric(warnsHist, expWarnsTotal))
+	// 	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
 	}
-
+	slog.Info().Str("addr", addr.String()).Msg("SMTP listening on tcp4")
-	log.Infof("SMTP listening on TCP4 %v", addr)
 	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")
+	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
+	// 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")
 }

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

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
 	}

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
 		}
 	}

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)
+			log.Info().Str("module", "storage").Str("mailbox", mb.name).
-			if err := mb.removeMessage(mb.messages[0].ID()); err != nil {
+				Msg("Mailbox over message cap")
-				log.Errorf("Error deleting message: %s", err)
+			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")
 			}
 		}
 	}

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

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

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() {
+	// TODO #90 move
-		expRetentionDeletesHist.Set(log.PushMetric(retentionDeletesHist, expRetentionDeletesTotal))
+	// log.AddTickerFunc(func() {
-		expRetainedHist.Set(log.PushMetric(retainedHist, expRetainedCurrent))
+	// 	expRetentionDeletesHist.Set(log.PushMetric(retentionDeletesHist, expRetentionDeletesTotal))
-		expSizeHist.Set(log.PushMetric(sizeHist, expRetainedSize))
+	// 	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

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