Merge pull request #3376 from micbar/requestID

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/interceptors/loader/loader.go

@@ -23,5 +23,6 @@ import (
 	_ "github.com/cs3org/reva/v2/internal/http/interceptors/cors"
 	_ "github.com/cs3org/reva/v2/internal/http/interceptors/prometheus"
 	_ "github.com/cs3org/reva/v2/internal/http/interceptors/providerauthorizer"
+	_ "github.com/cs3org/reva/v2/internal/http/interceptors/requestid"
 	// Add your own middleware.
 )

internal/http/interceptors/requestid/requestid.go

@@ -0,0 +1,54 @@
+// Copyright 2018-2021 CERN
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+//
+// In applying this license, CERN does not waive the privileges and immunities
+// granted to it by virtue of its status as an Intergovernmental Organization
+// or submit itself to any jurisdiction.
+
+package requestid
+
+import (
+	"net/http"
+
+	"github.com/cs3org/reva/v2/pkg/rhttp/global"
+	"github.com/go-chi/chi/v5/middleware"
+)
+
+const (
+	defaultPriority = 100
+)
+
+func init() {
+	global.RegisterMiddleware("requestid", New)
+}
+
+// New returns a new HTTP middleware that adds the X-Request-ID to the context
+func New(m map[string]interface{}) (global.Middleware, int, error) {
+	rh := requestIDHandler{}
+	return rh.handler, defaultPriority, nil
+}
+
+type requestIDHandler struct {
+	h http.Handler
+}
+
+// handler is a request id middleware
+func (rh requestIDHandler) handler(h http.Handler) http.Handler {
+	rh.h = middleware.RequestID(h)
+	return rh
+}
+
+func (rh requestIDHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	rh.h.ServeHTTP(w, r)
+}

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

@@ -25,12 +25,12 @@ import (
 	"net/http"
 	"time"
 
+	"regexp"
+
 	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"
 
-	"regexp"
-
 	"github.com/cs3org/reva/v2/internal/http/services/archiver/manager"
 	"github.com/cs3org/reva/v2/pkg/errtypes"
 	"github.com/cs3org/reva/v2/pkg/rgrpc/todo/pool"

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/handlers/apps/sharing/shares/shares.go

@@ -607,7 +607,7 @@ func (h *Handler) GetShare(w http.ResponseWriter, r *http.Request) {
 		// the path (/users/u-u-i-d/foo) will not be accessible
 
 		// in a global namespace we can access the share using the full path
-		// in a jailed namespace we have to point to the mount point in the users /Shares jail
+		// in a jailed namespace we have to point to the mount point in the users /Shares Jail
 		// - needed for oc10 hot migration
 		// or use the /dav/spaces/<space id> endpoint?
 
@@ -619,7 +619,7 @@ func (h *Handler) GetShare(w http.ResponseWriter, r *http.Request) {
 		// - no, the gateway only sees the same list any has the same options as the ocs service
 		// - we would need to have a list of mountpoints for the shares -> owncloudstorageprovider for hot migration migration
 
-		// best we can do for now is stat the /Shares jail if it is set and return those paths
+		// best we can do for now is stat the /Shares Jail if it is set and return those paths
 
 		// if we are in a jail and the current share has been accepted use the stat from the share jail
 		// Needed because received shares can be jailed in a folder in the users home
@@ -934,7 +934,7 @@ func (h *Handler) listSharesWithMe(w http.ResponseWriter, r *http.Request) {
 			// the path (/users/u-u-i-d/foo) will not be accessible
 
 			// in a global namespace we can access the share using the full path
-			// in a jailed namespace we have to point to the mount point in the users /Shares jail
+			// in a jailed namespace we have to point to the mount point in the users /Shares Jail
 			// - needed for oc10 hot migration
 			// or use the /dav/spaces/<space id> endpoint?
 
@@ -946,7 +946,7 @@ func (h *Handler) listSharesWithMe(w http.ResponseWriter, r *http.Request) {
 			// - no, the gateway only sees the same list any has the same options as the ocs service
 			// - we would need to have a list of mountpoints for the shares -> owncloudstorageprovider for hot migration migration
 
-			// best we can do for now is stat the /Shares jail if it is set and return those paths
+			// best we can do for now is stat the /Shares Jail if it is set and return those paths
 
 			// if we are in a jail and the current share has been accepted use the stat from the share jail
 			// Needed because received shares can be jailed in a folder in the users home

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"
@@ -398,6 +397,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
@@ -413,15 +414,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{