diff --git a/attachments.go b/attachments.go index 022645ff8..e6b587fcd 100644 --- a/attachments.go +++ b/attachments.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "io" + "log/slog" "mime" "net/http" "net/url" @@ -12,7 +13,6 @@ import ( "github.com/nyaruka/courier/utils" "github.com/nyaruka/gocommon/httpx" "github.com/pkg/errors" - "github.com/sirupsen/logrus" "gopkg.in/h2non/filetype.v1" ) @@ -64,7 +64,7 @@ func fetchAttachment(ctx context.Context, b Backend, r *http.Request) (*fetchAtt // try to write channel log even if we have an error clog.End() if err := b.WriteChannelLog(ctx, clog); err != nil { - logrus.WithError(err).Error() + slog.Error("error writing log", "error", err) } if err != nil { diff --git a/cmd/courier/main.go b/cmd/courier/main.go index 577a2e89c..be2563ac0 100644 --- a/cmd/courier/main.go +++ b/cmd/courier/main.go @@ -132,7 +132,6 @@ func main() { ch := make(chan os.Signal, 1) signal.Notify(ch, syscall.SIGINT, syscall.SIGTERM) slog.Info("stopping", "comp", "main", "signal", <-ch) - logrus.WithField("comp", "main").WithField("signal", <-ch) server.Stop() diff --git a/log.go b/log.go index 9a871ea55..fc9dfdac6 100644 --- a/log.go +++ b/log.go @@ -1,88 +1,90 @@ package courier import ( + "log/slog" "net/http" "time" - - "github.com/sirupsen/logrus" ) // LogMsgStatusReceived logs our that we received a new MsgStatus func LogMsgStatusReceived(r *http.Request, status StatusUpdate) { - if logrus.IsLevelEnabled(logrus.DebugLevel) { - logrus.WithFields(logrus.Fields{ - "channel_uuid": status.ChannelUUID(), - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "status": status.Status(), - "msg_id": status.MsgID(), - "msg_external_id": status.ExternalID(), - }).Debug("status updated") + if slog.Default().Enabled(r.Context(), slog.LevelDebug) { + slog.Debug("status updated", + "channel_uuid", status.ChannelUUID(), + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "status", status.Status(), + "msg_id", status.MsgID(), + "msg_external_id", status.ExternalID(), + ) } + } // LogMsgReceived logs that we received the passed in message func LogMsgReceived(r *http.Request, msg MsgIn) { - if logrus.IsLevelEnabled(logrus.DebugLevel) { - logrus.WithFields(logrus.Fields{ - "channel_uuid": msg.Channel().UUID(), - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "msg_uuid": msg.UUID(), - "msg_id": msg.ID(), - "msg_urn": msg.URN().Identity(), - "msg_text": msg.Text(), - "msg_attachments": msg.Attachments(), - }).Debug("msg received") + if slog.Default().Enabled(r.Context(), slog.LevelDebug) { + slog.Debug("msg received", + "channel_uuid", msg.Channel().UUID(), + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "msg_uuid", msg.UUID(), + "msg_id", msg.ID(), + "msg_urn", msg.URN().Identity(), + "msg_text", msg.Text(), + "msg_attachments", msg.Attachments(), + ) } + } // LogChannelEventReceived logs that we received the passed in channel event func LogChannelEventReceived(r *http.Request, event ChannelEvent) { - if logrus.IsLevelEnabled(logrus.DebugLevel) { - logrus.WithFields(logrus.Fields{ - "channel_uuid": event.ChannelUUID(), - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "event_type": event.EventType(), - "event_urn": event.URN().Identity(), - }).Debug("event received") + if slog.Default().Enabled(r.Context(), slog.LevelDebug) { + slog.Debug("event received", + "channel_uuid", event.ChannelUUID(), + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "event_type", event.EventType(), + "event_urn", event.URN().Identity(), + ) } } // LogRequestIgnored logs that we ignored the passed in request func LogRequestIgnored(r *http.Request, channel Channel, details string) { - if logrus.IsLevelEnabled(logrus.DebugLevel) { - logrus.WithFields(logrus.Fields{ - "channel_uuid": channel.UUID(), - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "details": details, - }).Debug("request ignored") + if slog.Default().Enabled(r.Context(), slog.LevelDebug) { + slog.Debug("request ignored", + "channel_uuid", channel.UUID(), + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "details", details, + ) } } // LogRequestHandled logs that we handled the passed in request but didn't create any events func LogRequestHandled(r *http.Request, channel Channel, details string) { - if logrus.IsLevelEnabled(logrus.DebugLevel) { - logrus.WithFields(logrus.Fields{ - "channel_uuid": channel.UUID(), - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "details": details, - }).Debug("request handled") + if slog.Default().Enabled(r.Context(), slog.LevelDebug) { + slog.Debug("request handled", + "channel_uuid", channel.UUID(), + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "details", details, + ) } } // LogRequestError logs that errored during parsing (this is logged as an info as it isn't an error on our side) func LogRequestError(r *http.Request, channel Channel, err error) { - log := logrus.WithFields(logrus.Fields{ - "url": r.Context().Value(contextRequestURL), - "elapsed_ms": getElapsedMS(r), - "error": err.Error(), - }) + log := slog.With( + "url", r.Context().Value(contextRequestURL), + "elapsed_ms", getElapsedMS(r), + "error", err, + ) + if channel != nil { - log = log.WithField("channel_uuid", channel.UUID()) + log = log.With("channel_uuid", channel.UUID()) } log.Info("request errored") } diff --git a/sender.go b/sender.go index 9eb43bc2f..c713b6873 100644 --- a/sender.go +++ b/sender.go @@ -3,10 +3,10 @@ package courier import ( "context" "fmt" + "log/slog" "time" "github.com/nyaruka/gocommon/analytics" - "github.com/sirupsen/logrus" ) // Foreman takes care of managing our set of sending workers and assigns msgs for each to send @@ -47,7 +47,7 @@ func (f *Foreman) Stop() { sender.Stop() } close(f.quit) - logrus.WithField("comp", "foreman").WithField("state", "stopping").Info("foreman stopping") + slog.Info("foreman stopping", "comp", "foreman", "state", "stopping") } // Assign is our main loop for the Foreman, it takes care of popping the next outgoing messages from our @@ -55,12 +55,11 @@ func (f *Foreman) Stop() { func (f *Foreman) Assign() { f.server.WaitGroup().Add(1) defer f.server.WaitGroup().Done() - log := logrus.WithField("comp", "foreman") + log := slog.With("comp", "foreman") - log.WithFields(logrus.Fields{ - "state": "started", - "senders": len(f.senders), - }).Info("senders started and waiting") + log.Info("senders started and waiting", + "state", "started", + "senders", len(f.senders)) backend := f.server.Backend() lastSleep := false @@ -69,7 +68,7 @@ func (f *Foreman) Assign() { select { // return if we have been told to stop case <-f.quit: - log.WithField("state", "stopped").Info("foreman stopped") + log.Info("foreman stopped", "state", "stopped") return // otherwise, grab the next msg and assign it to a sender @@ -86,7 +85,7 @@ func (f *Foreman) Assign() { } else { // we received an error getting the next message, log it if err != nil { - log.WithError(err).Error("error popping outgoing msg") + log.Error("error popping outgoing msg", "error", err) } // add our sender back to our queue and sleep a bit @@ -124,10 +123,7 @@ func (w *Sender) Start() { go func() { defer w.foreman.server.WaitGroup().Done() - - log := logrus.WithField("comp", "sender").WithField("sender_id", w.id) - log.Debug("started") - + slog.Debug("started", "comp", "sender", "sender_id", w.id) for { // list ourselves as available for work w.foreman.availableSenders <- w @@ -137,7 +133,7 @@ func (w *Sender) Start() { // exit if we were stopped if msg == nil { - log.Debug("stopped") + slog.Debug("stopped") return } @@ -152,7 +148,8 @@ func (w *Sender) Stop() { } func (w *Sender) sendMessage(msg MsgOut) { - log := logrus.WithField("comp", "sender").WithField("sender_id", w.id).WithField("channel_uuid", msg.Channel().UUID()) + + log := slog.With("comp", "sender", "sender_id", w.id, "channel_uuid", msg.Channel().UUID()) server := w.foreman.server backend := server.Backend() @@ -161,12 +158,12 @@ func (w *Sender) sendMessage(msg MsgOut) { sendCTX, cancel := context.WithTimeout(context.Background(), time.Second*35) defer cancel() - log = log.WithField("msg_id", msg.ID()).WithField("msg_text", msg.Text()).WithField("msg_urn", msg.URN().Identity()) + log = log.With("msg_id", msg.ID(), "msg_text", msg.Text(), "msg_urn", msg.URN().Identity()) if len(msg.Attachments()) > 0 { - log = log.WithField("attachments", msg.Attachments()) + log = log.With("attachments", msg.Attachments()) } if len(msg.QuickReplies()) > 0 { - log = log.WithField("quick_replies", msg.QuickReplies()) + log = log.With("quick_replies", msg.QuickReplies()) } start := time.Now() @@ -175,7 +172,7 @@ func (w *Sender) sendMessage(msg MsgOut) { if msg.IsResend() { err := backend.ClearMsgSent(sendCTX, msg.ID()) if err != nil { - log.WithError(err).Error("error clearing sent status for msg") + log.Error("error clearing sent status for msg", "error", err) } } @@ -184,7 +181,7 @@ func (w *Sender) sendMessage(msg MsgOut) { // failing on a lookup isn't a halting problem but we should log it if err != nil { - log.WithError(err).Error("error looking up msg was sent") + log.Error("error looking up msg was sent", "error", err) } var status StatusUpdate @@ -199,12 +196,12 @@ func (w *Sender) sendMessage(msg MsgOut) { if handler == nil { // if there's no handler, create a FAILED status for it status = backend.NewStatusUpdate(msg.Channel(), msg.ID(), MsgStatusFailed, clog) - log.Errorf("unable to find handler for channel type: %s", msg.Channel().ChannelType()) + log.Error(fmt.Sprintf("unable to find handler for channel type: %s", msg.Channel().ChannelType())) } else if sent { // if this message was already sent, create a WIRED status for it status = backend.NewStatusUpdate(msg.Channel(), msg.ID(), MsgStatusWired, clog) - log.Warning("duplicate send, marking as wired") + log.Info("duplicate send, marking as wired") } else { // send our message @@ -213,7 +210,7 @@ func (w *Sender) sendMessage(msg MsgOut) { secondDuration := float64(duration) / float64(time.Second) if err != nil { - log.WithError(err).WithField("elapsed", duration).Error("error sending message") + log.Error("error sending message", "error", err, "elapsed", duration) // handlers should log errors implicitly with user friendly messages.. but if not.. add what we have if len(clog.Errors()) == 0 { @@ -228,10 +225,10 @@ func (w *Sender) sendMessage(msg MsgOut) { // report to librato and log locally if status.Status() == MsgStatusErrored || status.Status() == MsgStatusFailed { - log.WithField("elapsed", duration).Warning("msg errored") + log.Info("msg errored", "elapsed", duration) analytics.Gauge(fmt.Sprintf("courier.msg_send_error_%s", msg.Channel().ChannelType()), secondDuration) } else { - log.WithField("elapsed", duration).Debug("msg sent") + log.Debug("msg sent", "elapsed", duration) analytics.Gauge(fmt.Sprintf("courier.msg_send_%s", msg.Channel().ChannelType()), secondDuration) } } @@ -242,7 +239,7 @@ func (w *Sender) sendMessage(msg MsgOut) { err = backend.WriteStatusUpdate(writeCTX, status) if err != nil { - log.WithError(err).Info("error writing msg status") + log.Info("error writing msg status", "error", err) } clog.End() @@ -250,7 +247,7 @@ func (w *Sender) sendMessage(msg MsgOut) { // write our logs as well err = backend.WriteChannelLog(writeCTX, clog) if err != nil { - log.WithError(err).Info("error writing msg logs") + log.Info("error writing msg logs", "error", err) } // mark our send task as complete diff --git a/server.go b/server.go index f132a470c..6210e3c3e 100644 --- a/server.go +++ b/server.go @@ -22,7 +22,6 @@ import ( "github.com/nyaruka/gocommon/httpx" "github.com/nyaruka/gocommon/jsonx" "github.com/pkg/errors" - "github.com/sirupsen/logrus" ) // for use in request.Context @@ -138,7 +137,7 @@ func (s *server) Start() error { defer s.waitGroup.Done() err := s.httpServer.ListenAndServe() if err != nil && err != http.ErrServerClosed { - logrus.WithFields(logrus.Fields{"comp": "server", "state": "stopping"}).Error(err) + slog.Error("failed to start server", "error", err, "comp", "server", "state", "stopping") } }() @@ -155,18 +154,18 @@ func (s *server) Start() error { case <-time.After(time.Minute): err := s.backend.Heartbeat() if err != nil { - logrus.WithError(err).Error("error running backend heartbeat") + slog.Error("error running backend heartbeat", "error", err) } } } }() - logrus.WithFields(logrus.Fields{ - "comp": "server", - "port": s.config.Port, - "state": "started", - "version": s.config.Version, - }).Info("server listening on ", s.config.Port) + slog.Info(fmt.Sprintf("server listening on %d", s.config.Port), + "comp", "server", + "port", s.config.Port, + "state", "started", + "version", s.config.Version, + ) // start our foreman for outgoing messages s.foreman = NewForeman(s, s.config.MaxWorkers) @@ -177,15 +176,15 @@ func (s *server) Start() error { // Stop stops the server, returning only after all threads have stopped func (s *server) Stop() error { - log := logrus.WithField("comp", "server") - log.WithField("state", "stopping").Info("stopping server") + log := slog.With("comp", "server") + log.Info("stopping server", "state", "stopping") // stop our foreman s.foreman.Stop() // shut down our HTTP server if err := s.httpServer.Shutdown(context.Background()); err != nil { - log.WithField("state", "stopping").WithError(err).Error("error shutting down server") + log.Error("error shutting down server", "error", err, "state", "stopping") } // stop everything @@ -205,8 +204,7 @@ func (s *server) Stop() error { // clean things up, tearing down any connections s.backend.Cleanup() - - log.WithField("state", "stopped").Info("server stopped") + log.Info("server stopped", "state", "stopped") return nil } @@ -252,7 +250,7 @@ func (s *server) initializeChannelHandlers() { } activeHandlers[handler.ChannelType()] = handler - logrus.WithField("comp", "server").WithField("handler", handler.ChannelName()).WithField("handler_type", channelType).Info("handler initialized") + slog.Info("handler initialized", "comp", "server", "handler", handler.ChannelName(), "handler_type", channelType) } } @@ -296,7 +294,7 @@ func (s *server) channelHandleWrapper(handler ChannelHandler, handlerFunc Channe panicLog := recover() if panicLog != nil { debug.PrintStack() - logrus.WithError(err).WithField("channel_uuid", channelUUID).WithField("request", string(recorder.Trace.RequestTrace)).WithField("trace", panicLog).Error("panic handling request") + slog.Error("panic handling request", "error", err, "channel_uuid", channelUUID, "request", recorder.Trace.RequestTrace, "trace", panicLog) writeAndLogRequestError(ctx, handler, recorder.ResponseWriter, r, channel, errors.New("panic handling msg")) } }() @@ -309,13 +307,13 @@ func (s *server) channelHandleWrapper(handler ChannelHandler, handlerFunc Channe // if we received an error, write it out and report it if hErr != nil { - logrus.WithError(hErr).WithField("channel_uuid", channelUUID).WithField("request", string(recorder.Trace.RequestTrace)).Error("error handling request") + slog.Error("error handling request", "error", err, "channel_uuid", channelUUID, "request", recorder.Trace.RequestTrace) writeAndLogRequestError(ctx, handler, recorder.ResponseWriter, r, channel, hErr) } // end recording of the request so that we have a response trace if err := recorder.End(); err != nil { - logrus.WithError(err).WithField("channel_uuid", channelUUID).WithField("request", string(recorder.Trace.RequestTrace)).Error("error recording request") + slog.Error("error recording request", "error", err, "channel_uuid", channelUUID, "request", recorder.Trace.RequestTrace) writeAndLogRequestError(ctx, handler, w, r, channel, err) } @@ -348,12 +346,11 @@ func (s *server) channelHandleWrapper(handler ChannelHandler, handlerFunc Channe clog.End() if err := s.backend.WriteChannelLog(ctx, clog); err != nil { - logrus.WithError(err).Error("error writing channel log") + slog.Error("error writing channel log", "error", err) } } else { - logrus.WithError(err).WithFields( - logrus.Fields{"channel_type": handler.ChannelType(), "request": string(recorder.Trace.RequestTrace), "status": recorder.Trace.Response.StatusCode}, - ).Info("non-channel specific request") + slog.Info("non-channel specific request", "error", err, "channel_type", handler.ChannelType(), "request", recorder.Trace.RequestTrace, "status", recorder.Trace.Response.StatusCode) + } } } @@ -404,7 +401,7 @@ func (s *server) handleFetchAttachment(w http.ResponseWriter, r *http.Request) { resp, err := fetchAttachment(ctx, s.backend, r) if err != nil { - logrus.WithError(err).Error() + slog.Error("error fetching attachment", "error", err) WriteError(w, http.StatusBadRequest, err) return } @@ -415,20 +412,21 @@ func (s *server) handleFetchAttachment(w http.ResponseWriter, r *http.Request) { } func (s *server) handle404(w http.ResponseWriter, r *http.Request) { - logrus.WithField("url", r.URL.String()).WithField("method", r.Method).WithField("resp_status", "404").Info("not found") + slog.Info("not found", "url", r.URL.String(), "method", r.Method, "resp_status", "404") errors := []any{NewErrorData(fmt.Sprintf("not found: %s", r.URL.String()))} err := WriteDataResponse(w, http.StatusNotFound, "Not Found", errors) if err != nil { - logrus.WithError(err).Error() + slog.Error("error writing response", "error", err) } } func (s *server) handle405(w http.ResponseWriter, r *http.Request) { - logrus.WithField("url", r.URL.String()).WithField("method", r.Method).WithField("resp_status", "405").Info("invalid method") + slog.Info("invalid method", "url", r.URL.String(), "method", r.Method, "resp_status", "405") errors := []any{NewErrorData(fmt.Sprintf("method not allowed: %s", r.Method))} err := WriteDataResponse(w, http.StatusMethodNotAllowed, "Method Not Allowed", errors) if err != nil { - logrus.WithError(err).Error() + slog.Error("error writing response", "error", err) + } } diff --git a/spool.go b/spool.go index 6e4cee5a9..fc451bed1 100644 --- a/spool.go +++ b/spool.go @@ -4,13 +4,12 @@ import ( "encoding/json" "errors" "fmt" + "log/slog" "os" "path" "path/filepath" "strings" "time" - - "github.com/sirupsen/logrus" ) // FlusherFunc defines our interface for flushers, they are handed a filename and byte blob and are expected @@ -46,8 +45,8 @@ func startSpoolFlushers(s Server) { go func() { defer s.WaitGroup().Done() - log := logrus.WithField("comp", "spool") - log.WithField("state", "started").Info("spool started") + log := slog.With("comp", "spool") + log.Info("spool started", "state", "started") // runs until stopped, checking every 30 seconds if there is anything to flush from our spool for { @@ -55,7 +54,7 @@ func startSpoolFlushers(s Server) { // our server is shutting down, exit case <-s.StopChan(): - log.WithField("state", "stopped").Info("spool stopped") + log.Info("spool stopped", "state", "stopped") return // every 30 seconds we check to see if there are any files to spool @@ -99,18 +98,18 @@ func newSpoolFlusher(s Server, dir string, flusherFunc FlusherFunc) *flusher { return nil } - log := logrus.WithField("comp", "spool").WithField("filename", filename) + log := slog.With("comp", "spool", "filename", filename) // otherwise, read our msg json contents, err := os.ReadFile(filename) if err != nil { - log.WithError(err).Error("reading spool file") + log.Error("reading spool file", "error", err) return nil } err = flusherFunc(filename, contents) if err != nil { - log.WithError(err).Error("flushing spool file") + log.Error("flushing spool file", "error", err) return err } log.Info("flushed")