Improve logging (#10)

api/api.go

@@ -14,9 +14,10 @@ import (
 	"github.com/etherlabsio/healthcheck"
 	"github.com/go-chi/chi/v5"
 	"github.com/go-chi/chi/v5/middleware"
-
-	"github.com/gofrs/uuid"
+	"github.com/google/uuid"
 	"github.com/ismrmrd/mrd-storage-server/core"
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
 )
 
 // use a dedicated type to avoid context key collisions
@@ -33,9 +34,9 @@ func BuildRouter(db core.MetadataDatabase, store core.BlobStore, logRequests boo
 	handler := Handler{db: db, store: store}
 	r := chi.NewRouter()
 
-	r.Use(middleware.RequestID)
+	r.Use(createRequestIdMiddleware)
 	if logRequests {
-		r.Use(middleware.Logger)
+		r.Use(createLoggerMiddleware(log.Logger))
 	}
 	r.Use(middleware.Recoverer)
 
@@ -73,6 +74,27 @@ func createApiVersionMiddleware(apiVersion string) func(next http.Handler) http.
 	}
 }
 
+func createLoggerMiddleware(logger zerolog.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		fn := func(rw http.ResponseWriter, r *http.Request) {
+			ww := middleware.NewWrapResponseWriter(rw, r.ProtoMajor)
+			start := time.Now().UTC()
+			defer func() {
+				log.Ctx(r.Context()).Info().
+					Int("status", ww.Status()).
+					Str("method", r.Method).
+					Str("path", r.URL.Path).
+					Str("query", r.URL.RawQuery).
+					Float32("latencyMs", float32(time.Since(start).Microseconds())/1000.0).
+					Msg("request completed")
+			}()
+
+			next.ServeHTTP(ww, r)
+		}
+		return http.HandlerFunc(fn)
+	}
+}
+
 func TagHeaderName(tagName string) string {
 	return TagHeaderPrefix + tagName
 }
@@ -107,7 +129,7 @@ func getBlobCombinedId(key core.BlobKey) string {
 
 func getBlobSubjectAndIdFromCombinedId(combinedId string) (key core.BlobKey, ok bool) {
 	if len(combinedId) >= 37 {
-		id, err := uuid.FromString(combinedId[:36])
+		id, err := uuid.Parse(combinedId[:36])
 		if err == nil {
 			key.Id = id
 			key.Subject = combinedId[37:]

api/create.go

@@ -3,12 +3,13 @@ package api
 import (
 	"errors"
 	"fmt"
-	"github.com/gofrs/uuid"
-	"github.com/ismrmrd/mrd-storage-server/core"
-	log "github.com/sirupsen/logrus"
 	"net/http"
 	"regexp"
 	"time"
+
+	"github.com/google/uuid"
+	"github.com/ismrmrd/mrd-storage-server/core"
+	"github.com/rs/zerolog/log"
 )
 
 const (
@@ -35,11 +36,7 @@ type TagValidator func(tagName string, tagValues []string) error
 
 func (handler *Handler) CreateBlob(w http.ResponseWriter, r *http.Request) {
 
-	id, err := uuid.NewV4()
-	if err != nil {
-		log.Panic(err)
-	}
-
+	id := uuid.New()
 	key := core.BlobKey{Id: id}
 
 	query := normalizeQueryMapToLowercaseKeys(r.URL.Query())
@@ -74,24 +71,24 @@ func (handler *Handler) CreateBlob(w http.ResponseWriter, r *http.Request) {
 
 	blobInfo, err := handler.db.StageBlobMetadata(r.Context(), key, &tags)
 	if err != nil {
-		log.Errorf("Failed to stage blob metadata: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to stage blob metadata: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
 	if err := handler.store.SaveBlob(r.Context(), r.Body, key); err != nil {
-		log.Errorf("Failed to save blob: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to save blob: %v", err)
 
 		err = handler.db.DeleteBlobMetadata(r.Context(), key)
 		if err != nil {
-			log.Errorf("Failed to revert staged blob metadata: %v", err)
+			log.Ctx(r.Context()).Error().Msgf("Failed to revert staged blob metadata: %v", err)
 		}
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
 	if err := handler.db.CompleteStagedBlobMetadata(r.Context(), key); err != nil {
-		log.Errorf("Failed to complete staged metadata to database: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to complete staged metadata to database: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}

api/create_test.go

@@ -2,21 +2,21 @@ package api
 
 import (
 	"errors"
-	"io/ioutil"
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"strings"
 	"testing"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/rs/zerolog/log"
 	"github.com/stretchr/testify/assert"
 
 	"github.com/golang/mock/gomock"
 	"github.com/ismrmrd/mrd-storage-server/mocks"
 )
 
 func init() {
-	log.SetOutput(ioutil.Discard)
+	log.Logger = log.Output(io.Discard)
 }
 
 func TestStorageWriteFailureRevertsStagedMetadata(t *testing.T) {

api/read.go

@@ -7,7 +7,7 @@ import (
 
 	"github.com/go-chi/chi/v5"
 	"github.com/ismrmrd/mrd-storage-server/core"
-	log "github.com/sirupsen/logrus"
+	"github.com/rs/zerolog/log"
 	"github.com/xorcare/pointer"
 )
 
@@ -30,7 +30,7 @@ func (handler *Handler) MakeBlobEndpoint(responder Responder, grace time.Duratio
 				return
 			}
 
-			log.Errorf("Database read failed: %v", err)
+			log.Ctx(r.Context()).Error().Msgf("Database read failed: %v", err)
 			w.WriteHeader(http.StatusInternalServerError)
 			return
 		}
@@ -48,7 +48,7 @@ func (handler *Handler) BlobDataResponse(w http.ResponseWriter, r *http.Request,
 	writeTagsAsHeaders(w, blobInfo)
 
 	if err := handler.store.ReadBlob(r.Context(), w, blobInfo.Key); err != nil {
-		log.Errorf("Failed to read blob from storage: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to read blob from storage: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 	}
 }

api/requestid.go

@@ -0,0 +1,41 @@
+package api
+
+import (
+	"context"
+	"net/http"
+
+	"github.com/google/uuid"
+	"github.com/rs/zerolog/log"
+)
+
+// Key to use when setting the request ID.
+type ctxKeyRequestID int
+
+// requestIDKey is the key that holds the unique request ID in a request context.
+const requestIDKey ctxKeyRequestID = 0
+
+// requestIDHeader is the name of the HTTP Header that contains the request id.
+var requestIDHeader = "X-Request-Id"
+
+// Creates an ID for the request. This will be stored in the forwarded context
+// and is added as a context field to the logger.
+func createRequestIdMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		id := uuid.New().String()
+		w.Header().Add(requestIDHeader, id)
+
+		logger := log.With().Str("requestId", id).Logger()
+
+		ctx := r.Context()
+		ctx = context.WithValue(ctx, requestIDKey, id)
+		ctx = logger.WithContext(ctx)
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+	})
+}
+
+// Gets the ID for the current request or empty if there is none.
+func GetRequestId(ctx context.Context) string {
+	id, _ := ctx.Value(requestIDKey).(string)
+	return id
+}

api/requestid_test.go

@@ -0,0 +1,51 @@
+package api
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/rs/zerolog"
+	"github.com/rs/zerolog/log"
+
+	"github.com/stretchr/testify/require"
+)
+
+func TestAddsHeader(t *testing.T) {
+	require := require.New(t)
+	nextCalled := false
+	nextHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+		nextCalled = true
+		require.NotEmpty(GetRequestId(r.Context()))
+	})
+
+	handler := createRequestIdMiddleware(nextHandler)
+
+	recorder := httptest.NewRecorder()
+	handler.ServeHTTP(recorder, httptest.NewRequest("GET", "http://abc", nil))
+	require.True(nextCalled)
+	require.NotEmpty(recorder.Result().Header.Get(requestIDHeader))
+}
+
+func TestAddsRequestIdToLogEntries(t *testing.T) {
+	require := require.New(t)
+	existingLogger := log.Logger
+	defer func() { log.Logger = existingLogger }()
+
+	buf := bytes.Buffer{}
+	log.Logger = zerolog.New(&buf)
+
+	nextHandler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+		log.Ctx(r.Context()).Info().Msg("hello")
+	})
+
+	handler := createRequestIdMiddleware(nextHandler)
+	handler.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("GET", "http://abc", nil))
+
+	require.NotEmpty(buf.String())
+	loggedMap := make(map[string]string)
+	require.Nil(json.Unmarshal(buf.Bytes(), &loggedMap))
+	require.NotEmpty(loggedMap["requestId"])
+}

api/search.go

@@ -8,7 +8,7 @@ import (
 	"time"
 
 	"github.com/ismrmrd/mrd-storage-server/core"
-	log "github.com/sirupsen/logrus"
+	"github.com/rs/zerolog/log"
 )
 
 func (handler *Handler) SearchBlobs(w http.ResponseWriter, r *http.Request) {
@@ -27,7 +27,7 @@ func (handler *Handler) SearchBlobs(w http.ResponseWriter, r *http.Request) {
 			return
 		}
 
-		log.Errorf("Failed to search blobs in DB: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to search blobs in DB: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
@@ -63,7 +63,7 @@ func (handler *Handler) GetLatestBlobData(w http.ResponseWriter, r *http.Request
 	results, _, err := handler.db.SearchBlobMetadata(r.Context(), query, at, nil, 1, time.Now())
 
 	if err != nil {
-		log.Errorf("Failed to search blobs in DB: %v", err)
+		log.Ctx(r.Context()).Error().Msgf("Failed to search blobs in DB: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}

core/garbage.go

@@ -5,7 +5,7 @@ import (
 	"errors"
 	"time"
 
-	log "github.com/sirupsen/logrus"
+	"github.com/rs/zerolog/log"
 )
 
 // When we write a blob, we first stage it in the metadata database, then write it to the blob store, then
@@ -34,7 +34,7 @@ func CollectGarbage(ctx context.Context, db MetadataDatabase, store BlobStore, o
 }
 
 func processExpiredKey(ctx context.Context, db MetadataDatabase, store BlobStore, key BlobKey) error {
-	log.Infof("Removing expired key %v", key)
+	log.Ctx(ctx).Info().Msgf("Removing expired key %v", key)
 	if err := store.DeleteBlob(ctx, key); err != nil {
 		return err
 	}

core/garbage_test.go

@@ -5,8 +5,8 @@ import (
 	"testing"
 	"time"
 
-	"github.com/gofrs/uuid"
 	"github.com/golang/mock/gomock"
+	"github.com/google/uuid"
 	"github.com/ismrmrd/mrd-storage-server/core"
 	"github.com/ismrmrd/mrd-storage-server/mocks"
 	"github.com/stretchr/testify/assert"

core/types.go

@@ -8,7 +8,7 @@ import (
 	"io"
 	"time"
 
-	"github.com/gofrs/uuid"
+	"github.com/google/uuid"
 )
 
 var (

database/database.go

@@ -12,14 +12,14 @@ import (
 	"strings"
 	"time"
 
-	"github.com/gofrs/uuid"
+	"github.com/google/uuid"
 	"github.com/ismrmrd/mrd-storage-server/core"
-	log "github.com/sirupsen/logrus"
+	gormzerolog "github.com/mpalmer/gorm-zerolog"
+	"github.com/rs/zerolog/log"
 	"gorm.io/driver/postgres"
 	"gorm.io/driver/sqlite"
 	"gorm.io/gorm"
 	"gorm.io/gorm/clause"
-	"gorm.io/gorm/logger"
 )
 
 const (
@@ -87,7 +87,7 @@ func ConnectPostgresqlDatabase(connectionString, password string) (core.Metadata
 
 func createRepository(dialector gorm.Dialector) (core.MetadataDatabase, error) {
 	db, err := gorm.Open(dialector, &gorm.Config{
-		Logger:                 logger.Default.LogMode(logger.Warn),
+		Logger:                 gormzerolog.Logger{},
 		SkipDefaultTransaction: true,
 		NowFunc: func() time.Time {
 			return time.Now().UTC()
@@ -415,7 +415,7 @@ func (r databaseRepository) HealthCheck(ctx context.Context) error {
 	s := r.db.WithContext(ctx).Exec("SELECT NULL from blob_metadata LIMIT 1")
 	err := s.Error
 	if err != nil {
-		log.Errorf("database health check failed: %v", err)
+		log.Ctx(ctx).Error().Msgf("database health check failed: %v", err)
 		return errors.New("failed to connect to database")
 	}
 	return nil