add request id to important http handlers

changelog/unreleased/logging-improvements.md

@@ -0,0 +1,5 @@
+Enhancement: Improve logging
+
+We improved the logging by adding the request id to ocdav, ocs and several other http services.
+
+https://github.com/cs3org/reva/pull/3376

go.mod

@@ -23,7 +23,6 @@ require (
 	github.com/emvi/iso-639-1 v1.0.1
 	github.com/eventials/go-tus v0.0.0-20220610120217-05d0564bb571
 	github.com/gdexlab/go-render v1.0.1
-	github.com/go-chi/chi v4.1.2+incompatible
 	github.com/go-chi/chi/v5 v5.0.7
 	github.com/go-ldap/ldap/v3 v3.4.4
 	github.com/go-micro/plugins/v4/events/natsjs v1.1.0

go.sum

@@ -191,10 +191,6 @@ github.com/cpuguy83/go-md2man/v2 v2.0.2/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46t
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/cs3org/cato v0.0.0-20200828125504-e418fc54dd5e h1:tqSPWQeueWTKnJVMJffz4pz0o1WuQxJ28+5x5JgaHD8=
 github.com/cs3org/cato v0.0.0-20200828125504-e418fc54dd5e/go.mod h1:XJEZ3/EQuI3BXTp/6DUzFr850vlxq11I6satRtz0YQ4=
-github.com/cs3org/go-cs3apis v0.0.0-20220929083235-bb0b1a236d6c h1:b+YTmOGlf43mnF8MzO0fsy8/Ho8JLu44Iq5Y0fKLJMM=
-github.com/cs3org/go-cs3apis v0.0.0-20220929083235-bb0b1a236d6c/go.mod h1:UXha4TguuB52H14EMoSsCqDj7k8a/t7g4gVP+bgY5LY=
-github.com/cs3org/go-cs3apis v0.0.0-20221005085457-19ea8088a512 h1:xTvaIsLu1ezoWOJKnV0ehgiowkOiEhMaylaI1lD/Axw=
-github.com/cs3org/go-cs3apis v0.0.0-20221005085457-19ea8088a512/go.mod h1:UXha4TguuB52H14EMoSsCqDj7k8a/t7g4gVP+bgY5LY=
 github.com/cs3org/go-cs3apis v0.0.0-20221012090518-ef2996678965 h1:y4n2j68LLnvac+zw/al8MfPgO5aQiIwLmHM/JzYN8AM=
 github.com/cs3org/go-cs3apis v0.0.0-20221012090518-ef2996678965/go.mod h1:UXha4TguuB52H14EMoSsCqDj7k8a/t7g4gVP+bgY5LY=
 github.com/cubewise-code/go-mime v0.0.0-20200519001935-8c5762b177d8 h1:Z9lwXumT5ACSmJ7WGnFl+OMLLjpz5uR2fyz7dC255FI=
@@ -247,8 +243,6 @@ github.com/gliderlabs/ssh v0.2.2/go.mod h1:U7qILu1NlMHj9FlMhZLlkCdDnU1DBEAqr0aev
 github.com/go-acme/lego/v4 v4.4.0 h1:uHhU5LpOYQOdp3aDU+XY2bajseu8fuExphTL1Ss6/Fc=
 github.com/go-asn1-ber/asn1-ber v1.5.4 h1:vXT6d/FNDiELJnLb6hGNa309LMsrCoYFvpwHDF0+Y1A=
 github.com/go-asn1-ber/asn1-ber v1.5.4/go.mod h1:hEBeB/ic+5LoWskz+yKT7vGhhPYkProFKoKdwZRWMe0=
-github.com/go-chi/chi v4.1.2+incompatible h1:fGFk2Gmi/YKXk0OmGfBh0WgmN3XB8lVnEyNz34tQRec=
-github.com/go-chi/chi v4.1.2+incompatible/go.mod h1:eB3wogJHnLi3x/kFX2A+IbTBlXxmMeXJVKy9tTv1XzQ=
 github.com/go-chi/chi/v5 v5.0.7 h1:rDTPXLDHGATaeHvVlLcR4Qe0zftYethFucbjVQ1PxU8=
 github.com/go-chi/chi/v5 v5.0.7/go.mod h1:DslCQbL2OYiznFReuXYUmQ2hGd1aDpCnlMNITLSKoi8=
 github.com/go-git/gcfg v1.5.0 h1:Q5ViNfGF8zFgyJWPqYwA7qGFoMTEiBmdlkcfRmpIMa4=

internal/http/services/appprovider/appprovider.go

@@ -42,7 +42,7 @@ import (
 	"github.com/cs3org/reva/v2/pkg/storagespace"
 	"github.com/cs3org/reva/v2/pkg/utils"
 	iso6391 "github.com/emvi/iso-639-1"
-	"github.com/go-chi/chi"
+	"github.com/go-chi/chi/v5"
 	ua "github.com/mileusna/useragent"
 	"github.com/mitchellh/mapstructure"
 	"github.com/pkg/errors"

internal/http/services/archiver/handler.go

@@ -28,6 +28,7 @@ import (
 	gateway "github.com/cs3org/go-cs3apis/cs3/gateway/v1beta1"
 	rpc "github.com/cs3org/go-cs3apis/cs3/rpc/v1beta1"
 	provider "github.com/cs3org/go-cs3apis/cs3/storage/provider/v1beta1"
+	"github.com/go-chi/chi/middleware"
 
 	"regexp"
 
@@ -215,7 +216,7 @@ func (s *svc) writeHTTPError(rw http.ResponseWriter, err error) {
 }
 
 func (s *svc) Handler() http.Handler {
-	return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+	handler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
 		// get the paths and/or the resources id from the query
 		ctx := r.Context()
 		v := r.URL.Query()
@@ -271,6 +272,7 @@ func (s *svc) Handler() http.Handler {
 		}
 
 	})
+	return middleware.RequestID(handler)
 }
 
 func (s *svc) Prefix() string {

internal/http/services/dataprovider/dataprovider.go

@@ -35,6 +35,7 @@ import (
 	"github.com/cs3org/reva/v2/pkg/rhttp/router"
 	"github.com/cs3org/reva/v2/pkg/storage"
 	"github.com/cs3org/reva/v2/pkg/storage/fs/registry"
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/go-micro/plugins/v4/events/natsjs"
 	"github.com/mitchellh/mapstructure"
 	"github.com/rs/zerolog"
@@ -187,14 +188,15 @@ func (s *svc) Handler() http.Handler {
 
 func (s *svc) setHandler() error {
 
-	s.handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+	dataHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		log := appctx.GetLogger(r.Context())
 		log.Debug().Msgf("dataprovider routing: path=%s", r.URL.Path)
 
 		head, tail := router.ShiftPath(r.URL.Path)
 
 		if handler, ok := s.dataTXs[head]; ok {
 			r.URL.Path = tail
+
 			handler.ServeHTTP(w, r)
 			return
 		}
@@ -209,5 +211,8 @@ func (s *svc) setHandler() error {
 		w.WriteHeader(http.StatusInternalServerError)
 	})
 
+	// wrap with request-id middleware
+	s.handler = middleware.RequestID(dataHandler)
+
 	return nil
 }

internal/http/services/owncloud/ocdav/meta.go

@@ -95,6 +95,7 @@ func (h *MetaHandler) handlePathForUser(w http.ResponseWriter, r *http.Request,
 
 	id := storagespace.FormatResourceID(*rid)
 	sublog := appctx.GetLogger(ctx).With().Str("path", r.URL.Path).Str("resourceid", id).Logger()
+	sublog.Info().Msg("calling get path for user")
 	client, err := s.getClient()
 	if err != nil {
 		sublog.Error().Err(err).Msg("error getting grpc client")
@@ -118,7 +119,7 @@ func (h *MetaHandler) handlePathForUser(w http.ResponseWriter, r *http.Request,
 	pathReq := &provider.GetPathRequest{ResourceId: rid}
 	pathRes, err := client.GetPath(ctx, pathReq)
 	if err != nil {
-		sublog.Error().Err(err).Msg("error sending GetPath grpc request")
+		sublog.Error().Err(err).Msg("could not send GetPath grpc request: transport error")
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}

internal/http/services/owncloud/ocs/ocs.go

@@ -33,6 +33,7 @@ import (
 	"github.com/cs3org/reva/v2/pkg/appctx"
 	"github.com/cs3org/reva/v2/pkg/rhttp/global"
 	"github.com/go-chi/chi/v5"
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/jellydator/ttlcache/v2"
 	"github.com/mitchellh/mapstructure"
 	"github.com/rs/zerolog"
@@ -63,6 +64,9 @@ func New(m map[string]interface{}, log *zerolog.Logger) (global.Service, error)
 		router: r,
 	}
 
+	// request-id
+	r.Use(middleware.RequestID)
+
 	if err := s.routerInit(); err != nil {
 		return nil, err
 	}

pkg/appctx/appctx.go

@@ -22,6 +22,7 @@ import (
 	"context"
 
 	rtrace "github.com/cs3org/reva/v2/pkg/trace"
+	"github.com/go-chi/chi/v5/middleware"
 	"github.com/rs/zerolog"
 	"go.opentelemetry.io/otel/trace"
 )
@@ -37,7 +38,15 @@ func WithLogger(ctx context.Context, l *zerolog.Logger) context.Context {
 // GetLogger returns the logger associated with the given context
 // or a disabled logger in case no logger is stored inside the context.
 func GetLogger(ctx context.Context) *zerolog.Logger {
-	return zerolog.Ctx(ctx)
+	logger := zerolog.Ctx(ctx)
+	reqID := middleware.GetReqID(ctx)
+
+	if reqID != "" {
+		sublogger := logger.With().Str("request-id", reqID).Logger()
+		logger = &sublogger
+	}
+
+	return logger
 }
 
 // WithTracerProvider returns a context with an associated TracerProvider

pkg/micro/ocdav/service.go

@@ -31,6 +31,7 @@ import (
 	"github.com/cs3org/reva/v2/pkg/storage/favorite/memory"
 	rtrace "github.com/cs3org/reva/v2/pkg/trace"
 	"github.com/go-chi/chi/v5"
+	"github.com/go-chi/chi/v5/middleware"
 	httpServer "github.com/go-micro/plugins/v4/server/http"
 	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
 	"github.com/prometheus/client_golang/prometheus"
@@ -191,8 +192,11 @@ func useMiddlewares(r *chi.Mux, sopts *Options, svc global.Service, tp trace.Tra
 	// ctx
 	cm := appctx.New(sopts.Logger, tp)
 
+	// request-id
+	rm := middleware.RequestID
+
 	// actually register
-	r.Use(pm, tm, lm, authMiddle, cm)
+	r.Use(pm, tm, lm, authMiddle, rm, cm)
 	return nil
 }
 

pkg/rhttp/datatx/manager/tus/tus.go

@@ -170,14 +170,14 @@ type composable interface {
 }
 
 func setExpiresHeader(fs storage.FS, w http.ResponseWriter, r *http.Request) {
-	ctx := context.Background()
+	ctx := r.Context()
 	id := path.Base(r.URL.Path)
 	datastore, ok := fs.(tusd.DataStore)
 	if !ok {
 		appctx.GetLogger(ctx).Error().Interface("fs", fs).Msg("storage is not a tus datastore")
 		return
 	}
-	upload, err := datastore.GetUpload(context.Background(), id)
+	upload, err := datastore.GetUpload(ctx, id)
 	if err != nil {
 		appctx.GetLogger(ctx).Error().Err(err).Msg("could not get upload from storage")
 		return

pkg/storage/utils/decomposedfs/upload.go

@@ -44,7 +44,6 @@ import (
 	"github.com/cs3org/reva/v2/pkg/appctx"
 	ctxpkg "github.com/cs3org/reva/v2/pkg/ctx"
 	"github.com/cs3org/reva/v2/pkg/errtypes"
-	"github.com/cs3org/reva/v2/pkg/logger"
 	"github.com/cs3org/reva/v2/pkg/storage"
 	"github.com/cs3org/reva/v2/pkg/storage/utils/chunking"
 	"github.com/cs3org/reva/v2/pkg/storage/utils/decomposedfs/lookup"
@@ -393,6 +392,8 @@ func (fs *Decomposedfs) readInfo(id string) (tusd.FileInfo, error) {
 
 // GetUpload returns the Upload for the given upload id
 func (fs *Decomposedfs) GetUpload(ctx context.Context, id string) (tusd.Upload, error) {
+	l := appctx.GetLogger(ctx)
+	sub := l.With().Int("pid", os.Getpid()).Logger()
 	info, err := fs.readInfo(id)
 	if err != nil {
 		return nil, err
@@ -408,15 +409,6 @@ func (fs *Decomposedfs) GetUpload(ctx context.Context, id string) (tusd.Upload,
 	}
 
 	ctx = ctxpkg.ContextSetUser(ctx, u)
-	// TODO configure the logger the same way ... store and add traceid in file info
-
-	var opts []logger.Option
-	opts = append(opts, logger.WithLevel(info.Storage["LogLevel"]))
-	opts = append(opts, logger.WithWriter(os.Stderr, logger.ConsoleMode))
-	l := logger.New(opts...)
-
-	sub := l.With().Int("pid", os.Getpid()).Logger()
-
 	ctx = appctx.WithLogger(ctx, &sub)
 
 	return &fileUpload{