Skip to content

Commit

Permalink
Merge pull request #655 from nyaruka/slog
Browse files Browse the repository at this point in the history 
More logrus replacement to use slog
  • Loading branch information
@rowanseymour
rowanseymour authored Oct 10, 2023
2 parents 5ecf683 + 05166db commit d5c9868
Show file tree
Hide file tree
Showing 6 changed files with 110 additions and 115 deletions.
4 changes: 2 additions & 2 deletions attachments.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import (
"context"
"encoding/json"
"io"
"log/slog"
"mime"
"net/http"
"net/url"
Expand All @@ -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"
)

Expand Down Expand Up @@ -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 {
Expand Down
1 change: 0 additions & 1 deletion cmd/courier/main.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()

Expand Down
102 changes: 52 additions & 50 deletions log.go
View file
Original file line number Diff line number Diff line change
@@ -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")
}
Expand Down
51 changes: 24 additions & 27 deletions sender.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -47,20 +47,19 @@ 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
// backend and assigning them to workers
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
Expand All @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -137,7 +133,7 @@ func (w *Sender) Start() {

// exit if we were stopped
if msg == nil {
log.Debug("stopped")
slog.Debug("stopped")
return
}

Expand All @@ -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()
Expand All @@ -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()
Expand All @@ -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)
}
}

Expand All @@ -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
Expand All @@ -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.Warn("duplicate send, marking as wired")

} else {
// send our message
Expand All @@ -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 {
Expand All @@ -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.Warn("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)
}
}
Expand All @@ -242,15 +239,15 @@ 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()

// 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
Expand Down
Loading

0 comments on commit d5c9868

Please sign in to comment.