Merge pull request #150 from nyaruka/more-slog

Use more slog, replacing logrus

services/ivr/twiml/service.go

@@ -8,6 +8,7 @@ import (
 	"encoding/base64"
 	"encoding/xml"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"sort"
@@ -26,7 +27,6 @@ import (
 	"github.com/nyaruka/mailroom/core/models"
 	"github.com/nyaruka/mailroom/runtime"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 )
 
 // IgnoreSignatures controls whether we ignore signatures (public for testing overriding)
@@ -350,7 +350,7 @@ func (s *service) StatusForRequest(r *http.Request) (models.CallStatus, models.C
 		return models.CallStatusErrored, models.CallErrorProvider, 0
 
 	default:
-		logrus.WithField("call_status", status).Error("unknown call status in status callback")
+		slog.Error("unknown call status in status callback", "call_status", status)
 		return models.CallStatusFailed, models.CallErrorProvider, 0
 	}
 }

services/ivr/vonage/service.go

@@ -10,6 +10,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"math/rand"
 	"net/http"
 	"net/url"
@@ -33,7 +34,6 @@ import (
 	"github.com/nyaruka/mailroom/core/models"
 	"github.com/nyaruka/mailroom/runtime"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 )
 
 // IgnoreSignatures sets whether we ignore signatures (for unit tests)
@@ -206,7 +206,7 @@ func (s *service) PreprocessStatus(ctx context.Context, rt *runtime.Runtime, r *
 	redisKey := fmt.Sprintf("dial_%s", legUUID)
 	dialContinue, err := redis.String(rc.Do("get", redisKey))
 
-	logrus.WithField("redisKey", redisKey).WithField("redisValue", dialContinue).WithError(err).WithField("status", nxStatus).Debug("looking up dial continue")
+	slog.Debug("looking up dial continue", "error", err, "status", nxStatus, "redisKey", redisKey, "redisValue", dialContinue)
 
 	// no associated call, move on
 	if err == redis.ErrNil {
@@ -224,7 +224,7 @@ func (s *service) PreprocessStatus(ctx context.Context, rt *runtime.Runtime, r *
 	// we found an associated call, if the status is complete, have it continue, we call out to
 	// redis and hand it our flow to resume on to get the next NCCO
 	if nxStatus == "completed" {
-		logrus.Debug("found completed call, trying to finish with call ID: ", callUUID)
+		slog.Debug("found completed call, trying to finish with call", "call_uuid", callUUID)
 		statusKey := fmt.Sprintf("dial_status_%s", callUUID)
 		status, err := redis.String(rc.Do("get", statusKey))
 		if err == redis.ErrNil {
@@ -273,7 +273,7 @@ func (s *service) PreprocessStatus(ctx context.Context, rt *runtime.Runtime, r *
 			return nil, errors.Wrapf(err, "error inserting recording URL into redis")
 		}
 
-		logrus.WithField("redisKey", redisKey).WithField("status", status).WithField("callUUID", callUUID).Debug("saved intermediary dial status for call")
+		slog.Debug("saved intermediary dial status for call", "callUUID", callUUID, "status", status, "redisKey", redisKey)
 		return s.MakeEmptyResponseBody(fmt.Sprintf("updated status for call: %s to: %s", callUUID, status)), nil
 	}
 
@@ -303,7 +303,7 @@ func (s *service) PreprocessResume(ctx context.Context, rt *runtime.Runtime, cal
 		// found a URL, stuff it in our request and move on
 		if recordingURL != "" {
 			r.URL.RawQuery = "&recording_url=" + url.QueryEscape(recordingURL)
-			logrus.WithField("recording_url", recordingURL).Info("found recording URL")
+			slog.Info("found recording URL", "recording_url", recordingURL)
 			rc.Do("del", redisKey)
 			return nil, nil
 		}
@@ -402,7 +402,7 @@ func (s *service) RequestCall(number urns.URN, resumeURL string, statusURL strin
 		return ivr.NilCallID, trace, errors.Errorf("call status returned as failed")
 	}
 
-	logrus.WithField("body", string(trace.ResponseBody)).WithField("status", trace.Response.StatusCode).Debug("requested call")
+	slog.Debug("requested call", "body", string(trace.ResponseBody), "status", trace.Response.StatusCode)
 
 	return ivr.CallID(call.UUID), trace, nil
 }
@@ -469,7 +469,7 @@ func (s *service) ResumeForRequest(r *http.Request) (ivr.Resume, error) {
 			if recordingURL == "" {
 				return ivr.InputResume{}, nil
 			}
-			logrus.WithField("recording_url", recordingURL).Info("input found recording")
+			slog.Info("input found recording", "recording_url", recordingURL)
 			return ivr.InputResume{Attachment: utils.Attachment("audio:" + recordingURL)}, nil
 
 		default:
@@ -496,7 +496,7 @@ func (s *service) ResumeForRequest(r *http.Request) (ivr.Resume, error) {
 		duration = parsed
 	}
 
-	logrus.WithField("status", status).WithField("duration", duration).Info("input found dial status and duration")
+	slog.Info("input found dial status and duration", "status", status, "duration", duration)
 	return ivr.DialResume{Status: flows.DialStatus(status), Duration: duration}, nil
 }
 
@@ -515,14 +515,14 @@ func (s *service) StatusForRequest(r *http.Request) (models.CallStatus, models.C
 
 	bb, err := readBody(r)
 	if err != nil {
-		logrus.WithError(err).Error("error reading status request body")
+		slog.Error("error reading status request body", "error", err)
 		return models.CallStatusErrored, models.CallErrorProvider, 0
 	}
 
 	status := &StatusRequest{}
 	err = json.Unmarshal(bb, status)
 	if err != nil {
-		logrus.WithError(err).WithField("body", string(bb)).Error("error unmarshalling ncco status")
+		slog.Error("error unmarshalling ncco status", "error", err, "body", string(bb))
 		return models.CallStatusErrored, models.CallErrorProvider, 0
 	}
 
@@ -553,7 +553,7 @@ func (s *service) StatusForRequest(r *http.Request) (models.CallStatus, models.C
 		return models.CallStatusErrored, models.CallErrorProvider, 0
 
 	default:
-		logrus.WithField("status", status.Status).Error("unknown call status in ncco callback")
+		slog.Error("unknown call status in ncco callback", "status", status.Status)
 		return models.CallStatusFailed, models.CallErrorProvider, 0
 	}
 }
@@ -823,7 +823,7 @@ func (s *service) responseForSprint(ctx context.Context, rp *redis.Pool, channel
 			}
 
 			trace, err := s.makeRequest(http.MethodPost, s.callURL, cr)
-			logrus.WithField("trace", trace).Debug("initiated new call for transfer")
+			slog.Debug("initiated new call for transfer", "trace", trace)
 			if err != nil {
 				return "", errors.Wrapf(err, "error trying to start call")
 			}
@@ -849,7 +849,7 @@ func (s *service) responseForSprint(ctx context.Context, rp *redis.Pool, channel
 			if err != nil {
 				return "", errors.Wrapf(err, "error inserting transfer ID into redis")
 			}
-			logrus.WithField("transferUUID", transferUUID).WithField("callID", call.ExternalID()).WithField("redisKey", redisKey).WithField("redisValue", redisValue).Debug("saved away call id")
+			slog.Debug("saved away call", "transferUUID", transferUUID, "callID", call.ExternalID(), "redisKey", redisKey, "redisValue", redisValue)
 		}
 	}
 

services/tickets/zendesk/web.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"strings"
 	"time"
@@ -17,7 +18,6 @@ import (
 	"github.com/nyaruka/mailroom/services/tickets"
 	"github.com/nyaruka/mailroom/web"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 )
 
 func init() {
@@ -146,7 +146,7 @@ func handleEventCallback(ctx context.Context, rt *runtime.Runtime, r *http.Reque
 }
 
 func processChannelEvent(ctx context.Context, rt *runtime.Runtime, event *channelEvent, l *models.HTTPLogger) error {
-	lr := logrus.WithField("integration_id", event.IntegrationID).WithField("subdomain", event.Subdomain)
+	lr := slog.With("integration_id", event.IntegrationID, "subdomain", event.Subdomain)
 
 	switch event.TypeID {
 

web/ivr/ivr.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"database/sql"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"time"
@@ -18,7 +19,6 @@ import (
 	"github.com/nyaruka/mailroom/runtime"
 	"github.com/nyaruka/mailroom/web"
 	"github.com/pkg/errors"
-	"github.com/sirupsen/logrus"
 )
 
 func init() {
@@ -73,18 +73,18 @@ func newIVRHandler(handler ivrHandlerFn, logType models.ChannelLogType) web.Hand
 		call, rerr := handler(ctx, rt, oa, ch, svc, r, recorder.ResponseWriter)
 		if call != nil {
 			if err := call.AttachLog(ctx, rt.DB, clog); err != nil {
-				logrus.WithError(err).WithField("http_request", r).Error("error attaching ivr channel log")
+				slog.Error("error attaching ivr channel log", "error", err, "http_request", r)
 			}
 		}
 
 		if err := recorder.End(); err != nil {
-			logrus.WithError(err).WithField("http_request", r).Error("error recording IVR request")
+			slog.Error("error recording IVR request", "error", err, "http_request", r)
 		}
 
 		clog.End()
 
 		if err := models.InsertChannelLogs(ctx, rt, []*models.ChannelLog{clog}); err != nil {
-			logrus.WithError(err).WithField("http_request", r).Error("error writing ivr channel log")
+			slog.Error("error writing ivr channel log", "error", err, "http_request", r)
 		}
 
 		return rerr
@@ -132,8 +132,7 @@ func handleIncoming(ctx context.Context, rt *runtime.Runtime, oa *models.OrgAsse
 	// try to handle this event
 	session, err := handler.HandleChannelEvent(ctx, rt, models.EventTypeIncomingCall, event, call)
 	if err != nil {
-		logrus.WithError(err).WithField("http_request", r).Error("error handling incoming call")
-
+		slog.Error("error handling incoming call", "error", err, "http_request", r)
 		return call, svc.WriteErrorResponse(w, errors.Wrapf(err, "error handling incoming call"))
 	}
 
@@ -247,7 +246,7 @@ func handleCallback(ctx context.Context, rt *runtime.Runtime, oa *models.OrgAsse
 
 	// had an error? mark our call as errored and log it
 	if err != nil {
-		logrus.WithError(err).WithField("http_request", r).Error("error while handling IVR")
+		slog.Error("error while handling IVR", "error", err, "http_request", r)
 		return conn, ivr.HandleAsFailure(ctx, rt.DB, svc, conn, w, err)
 	}
 
@@ -290,7 +289,7 @@ func handleStatus(ctx context.Context, rt *runtime.Runtime, oa *models.OrgAssets
 
 	// had an error? mark our call as errored and log it
 	if err != nil {
-		logrus.WithError(err).WithField("http_request", r).Error("error while handling status")
+		slog.Error("error while handling status", "error", err, "http_request", r)
 		return conn, ivr.HandleAsFailure(ctx, rt.DB, svc, conn, w, err)
 	}
 

web/ivr/ivr_test.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"net/url"
@@ -26,15 +27,14 @@ import (
 	"github.com/nyaruka/mailroom/testsuite"
 	"github.com/nyaruka/mailroom/testsuite/testdata"
 	"github.com/nyaruka/mailroom/web"
-	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
 // mocks the Twilio API
 func mockTwilioHandler(w http.ResponseWriter, r *http.Request) {
 	r.ParseForm()
-	logrus.WithField("method", r.Method).WithField("url", r.URL.String()).WithField("form", r.Form).Info("test server called")
+	slog.Info("test server called", "method", r.Method, "url", r.URL.String(), "form", r.Form)
 	if strings.HasSuffix(r.URL.String(), "Calls.json") {
 		to := r.Form.Get("To")
 		if to == "+16055741111" {
@@ -350,7 +350,7 @@ func mockVonageHandler(w http.ResponseWriter, r *http.Request) {
 		body, _ := io.ReadAll(r.Body)
 		form := &CallForm{}
 		json.Unmarshal(body, form)
-		logrus.WithField("method", r.Method).WithField("url", r.URL.String()).WithField("body", string(body)).WithField("form", form).Info("test server called")
+		slog.Info("test server called", "method", r.Method, "url", r.URL.String(), "body", body, "form", form)
 
 		// end of a leg
 		if form.Action == "transfer" {

web/middleware.go

@@ -1,15 +1,14 @@
 package web
 
 import (
-	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"runtime/debug"
 	"strconv"
 	"time"
 
 	"github.com/go-chi/chi/middleware"
-	log "github.com/sirupsen/logrus"
 )
 
 func requestLogger(next http.Handler) http.Handler {
@@ -29,14 +28,8 @@ func requestLogger(next http.Handler) http.Handler {
 		ww.Header().Set("X-Elapsed-NS", strconv.FormatInt(int64(elapsed), 10))
 
 		if r.RequestURI != "/" {
-			log.WithFields(log.Fields{
-				"method":     r.Method,
-				"status":     ww.Status(),
-				"elapsed":    elapsed,
-				"length":     ww.BytesWritten(),
-				"url":        uri,
-				"user_agent": r.UserAgent(),
-			}).Info("request completed")
+			slog.Info("request completed", "method", r.Method, "status", ww.Status(), "elapsed", elapsed, "length", ww.BytesWritten(), "url", uri, "user_agent", r.UserAgent())
+
 		}
 	})
 }
@@ -47,7 +40,7 @@ func panicRecovery(next http.Handler) http.Handler {
 		defer func() {
 			if rvr := recover(); rvr != nil {
 				debug.PrintStack()
-				log.WithError(errors.New(fmt.Sprint(rvr))).Error("recovered from panic in web handling")
+				slog.Error("recovered from panic in web handling", "error", fmt.Sprint(rvr))
 				http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
 			}
 		}()