[EXPERIMENTAL] feat: improve log information

ocis-pkg/log/log.go

@@ -137,6 +137,11 @@ func (l Logger) SubloggerWithRequestID(c context.Context) Logger {
 	}
 }
 
+func Ctx(ctx context.Context) Logger {
+	l := zerolog.Ctx(ctx)
+	return Logger{*l}
+}
+
 // Deprecation logs a deprecation message,
 // it is used to inform the user that a certain feature is deprecated and will be removed in the future.
 // Do not use a logger here because the message MUST be visible independent of the log level.

ocis-pkg/middleware/contextlogger.go

@@ -0,0 +1,29 @@
+package middleware
+
+import (
+	"net/http"
+
+	"github.com/owncloud/ocis/v2/ocis-pkg/log"
+)
+
+func NewContextLogger(logger *log.Logger) func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			newLogger := logger.With().
+				Str(log.RequestIDString, r.Header.Get("X-Request-ID")).
+				Str("proto", r.Proto).
+				Str("method", r.Method).
+				Str("host", r.Host).
+				Str("path", r.URL.Path).
+				Str("query", r.URL.RawQuery).
+				Str("fragment", r.URL.Fragment).
+				Str("remote-addr", r.RemoteAddr).
+				Str("user-agent", r.Header.Get("User-Agent")).
+				Str("content-length", r.Header.Get("Content-Length")).
+				Str("content-type", r.Header.Get("Content-Type")).
+				Logger()
+
+			next.ServeHTTP(w, r.WithContext(newLogger.WithContext(r.Context())))
+		})
+	}
+}

ocis-pkg/service/grpc/client.go

@@ -9,6 +9,7 @@ import (
 	mgrpcc "github.com/go-micro/plugins/v4/client/grpc"
 	mtracer "github.com/go-micro/plugins/v4/wrapper/trace/opentelemetry"
 	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
+	ocisgrpcmeta "github.com/owncloud/ocis/v2/ocis-pkg/service/grpc/handler/metadata"
 	"github.com/owncloud/ocis/v2/ocis-pkg/shared"
 	"go-micro.dev/v4/client"
 	"go.opentelemetry.io/otel/trace"
@@ -17,9 +18,11 @@ import (
 
 // ClientOptions represent options (e.g. tls settings) for the grpc clients
 type ClientOptions struct {
-	tlsMode string
-	caCert  string
-	tp      trace.TracerProvider
+	tlsMode       string
+	caCert        string
+	tp            trace.TracerProvider
+	clientName    string
+	clientVersion string
 }
 
 // Option is used to pass client options
@@ -50,6 +53,13 @@ func WithTraceProvider(tp trace.TracerProvider) ClientOption {
 	}
 }
 
+func WithClientNameAndVersion(name, version string) ClientOption {
+	return func(o *ClientOptions) {
+		o.clientName = name
+		o.clientVersion = version
+	}
+}
+
 func GetClientOptions(t *shared.GRPCClientTLS) []ClientOption {
 	opts := []ClientOption{
 		WithTLSMode(t.Mode),
@@ -68,6 +78,12 @@ func NewClient(opts ...ClientOption) (client.Client, error) {
 	var tlsConfig *tls.Config
 	cOpts := []client.Option{
 		client.Registry(reg),
+		client.Wrap(ocisgrpcmeta.NewClientWrapper(
+			map[string]string{
+				"Client-Name":    options.clientName,
+				"Client-Version": options.clientVersion,
+			},
+		)),
 		client.Wrap(mtracer.NewClientWrapper(
 			mtracer.WithTraceProvider(options.tp),
 		)),

ocis-pkg/service/grpc/handler/metadata/client.go

@@ -0,0 +1,39 @@
+package metadata
+
+import (
+	"context"
+
+	"go-micro.dev/v4/client"
+	"go-micro.dev/v4/metadata"
+)
+
+type clientWrapper struct {
+	client.Client
+	mdata metadata.Metadata
+}
+
+func NewClientWrapper(mdata map[string]string) client.Wrapper {
+	meta := metadata.Metadata(mdata)
+	return func(c client.Client) client.Client {
+		w := &clientWrapper{
+			Client: c,
+			mdata:  meta,
+		}
+		return w
+	}
+}
+
+func (w *clientWrapper) Call(ctx context.Context, req client.Request, rsp interface{}, opts ...client.CallOption) error {
+	newCtx := metadata.MergeContext(ctx, w.mdata, true)
+	return w.Client.Call(newCtx, req, rsp, opts...)
+}
+
+func (w *clientWrapper) Stream(ctx context.Context, req client.Request, opts ...client.CallOption) (client.Stream, error) {
+	newCtx := metadata.MergeContext(ctx, w.mdata, true)
+	return w.Client.Stream(newCtx, req, opts...)
+}
+
+func (w *clientWrapper) Publish(ctx context.Context, p client.Message, opts ...client.PublishOption) error {
+	newCtx := metadata.MergeContext(ctx, w.mdata, true)
+	return w.Client.Publish(newCtx, p, opts...)
+}

ocis-pkg/service/grpc/handler/metadata/server.go

@@ -0,0 +1,97 @@
+package metadata
+
+import (
+	"context"
+	"sort"
+
+	"github.com/owncloud/ocis/v2/ocis-pkg/log"
+	"google.golang.org/grpc"
+	"google.golang.org/grpc/metadata"
+
+	micrometa "go-micro.dev/v4/metadata"
+	"go-micro.dev/v4/server"
+)
+
+func NewMetadataLogHandler(l *log.Logger) func(fn server.HandlerFunc) server.HandlerFunc {
+	return func(fn server.HandlerFunc) server.HandlerFunc {
+		return func(ctx context.Context, req server.Request, rsp interface{}) error {
+			if mdata, ok := micrometa.FromContext(ctx); ok {
+				keys := make([]string, 0, len(mdata))
+				for k, _ := range mdata {
+					keys = append(keys, k)
+				}
+				sort.Strings(keys)
+
+				logContext := l.With()
+				for _, sortedKey := range keys {
+					value, _ := mdata.Get(sortedKey)
+					logContext = logContext.Str(sortedKey, value)
+				}
+
+				mdataLogger := logContext.Str("target", req.Service()).
+					Str("method", req.Method()).
+					Str("endpoint", req.Endpoint()).
+					Bool("isStream", req.Stream()).
+					Logger()
+				ctx = mdataLogger.WithContext(ctx)
+			}
+			return fn(ctx, req, rsp)
+		}
+	}
+}
+
+func NewUnaryInterceptor(l *log.Logger) grpc.UnaryServerInterceptor {
+	return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
+		if mdata, ok := metadata.FromIncomingContext(ctx); ok {
+			keys := make([]string, 0, len(mdata))
+			for k, _ := range mdata {
+				keys = append(keys, k)
+			}
+			sort.Strings(keys)
+
+			logContext := l.With()
+			for _, sortedKey := range keys {
+				values := mdata.Get(sortedKey)
+				logContext = logContext.Strs(sortedKey, values)
+			}
+			mdataLogger := logContext.Logger()
+			ctx = mdataLogger.WithContext(ctx)
+		}
+		return handler(ctx, req)
+	}
+}
+
+type serverStreamWrapper struct {
+	grpc.ServerStream
+	ctx context.Context
+}
+
+func newServerStreamWrapper(ss grpc.ServerStream, ctx context.Context) grpc.ServerStream {
+	return &serverStreamWrapper{ss, ctx}
+}
+
+func (w *serverStreamWrapper) Context() context.Context {
+	return w.ctx
+}
+
+func NewStreamInterceptor(l *log.Logger) grpc.StreamServerInterceptor {
+	return func(srv interface{}, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
+		ctx := ss.Context()
+		if mdata, ok := metadata.FromIncomingContext(ctx); ok {
+			keys := make([]string, 0, len(mdata))
+			for k, _ := range mdata {
+				keys = append(keys, k)
+			}
+			sort.Strings(keys)
+
+			logContext := l.With()
+			for _, sortedKey := range keys {
+				values := mdata.Get(sortedKey)
+				logContext = logContext.Strs(sortedKey, values)
+			}
+			mdataLogger := logContext.Logger()
+			ctx = mdataLogger.WithContext(ctx)
+		}
+		return handler(srv, newServerStreamWrapper(ss, ctx))
+	}
+}

ocis-pkg/service/grpc/service.go

@@ -21,6 +21,7 @@ import (
 	ociscrypto "github.com/owncloud/ocis/v2/ocis-pkg/crypto"
 	"github.com/owncloud/ocis/v2/ocis-pkg/log"
 	"github.com/owncloud/ocis/v2/ocis-pkg/registry"
+	ocisgrpcmeta "github.com/owncloud/ocis/v2/ocis-pkg/service/grpc/handler/metadata"
 )
 
 // Service simply wraps the go-micro grpc service.
@@ -64,6 +65,7 @@ func NewServiceWithClient(client client.Client, opts ...Option) (Service, error)
 		mtracer.NewHandlerWrapper(
 			mtracer.WithTraceProvider(sopts.TraceProvider),
 		),
+		ocisgrpcmeta.NewMetadataLogHandler(&sopts.Logger),
 	}
 	if sopts.Logger.GetLevel() == zerolog.DebugLevel {
 		handlerWrappers = append(handlerWrappers, LogHandler(&sopts.Logger))

services/collaboration/pkg/middleware/accesslog.go

@@ -36,3 +36,27 @@ func AccessLog(logger log.Logger) func(http.Handler) http.Handler {
 		})
 	}
 }
+
+func AccessLog2() func(http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			logger := log.Ctx(r.Context())
+
+			start := time.Now()
+			requestID := middleware.GetReqID(r.Context())
+			// add Request Id to all responses
+			w.Header().Set(middleware.RequestIDHeader, requestID)
+			wrap := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
+			next.ServeHTTP(wrap, r)
+
+			spanContext := trace.SpanContextFromContext(r.Context())
+			logger.Info().
+				Str("traceid", spanContext.TraceID().String()).
+				Str("wopi-action", r.Header.Get("X-WOPI-Override")).
+				Int("status", wrap.Status()).
+				Dur("duration", time.Since(start)).
+				Int("bytes", wrap.BytesWritten()).
+				Msg("access-log")
+		})
+	}
+}

services/collaboration/pkg/server/grpc/server.go

@@ -2,6 +2,7 @@ package grpc
 
 import (
 	appproviderv1beta1 "github.com/cs3org/go-cs3apis/cs3/app/provider/v1beta1"
+	"github.com/owncloud/ocis/v2/ocis-pkg/service/grpc/handler/metadata"
 	"github.com/owncloud/ocis/v2/ocis-pkg/tracing"
 	svc "github.com/owncloud/ocis/v2/services/collaboration/pkg/service/grpc/v0"
 	"go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc"
@@ -20,6 +21,12 @@ func Server(opts ...Option) (*grpc.Server, func(), error) {
 				otelgrpc.WithPropagators(tracing.GetPropagator()),
 			),
 		),
+		grpc.ChainUnaryInterceptor(
+			metadata.NewUnaryInterceptor(&options.Logger),
+		),
+		grpc.ChainStreamInterceptor(
+			metadata.NewStreamInterceptor(&options.Logger),
+		),
 	}
 	grpcServer := grpc.NewServer(grpcOpts...)
 

services/collaboration/pkg/server/http/server.go

@@ -7,7 +7,6 @@ import (
 	"github.com/go-chi/chi/v5"
 	chimiddleware "github.com/go-chi/chi/v5/middleware"
 	"github.com/owncloud/ocis/v2/ocis-pkg/account"
-	"github.com/owncloud/ocis/v2/ocis-pkg/log"
 	"github.com/owncloud/ocis/v2/ocis-pkg/middleware"
 	"github.com/owncloud/ocis/v2/ocis-pkg/service/http"
 	"github.com/owncloud/ocis/v2/ocis-pkg/tracing"
@@ -44,9 +43,8 @@ func Server(opts ...Option) (http.Service, error) {
 			options.Config.Service.Name+"."+options.Config.App.Name,
 			version.GetString(),
 		),
-		colabmiddleware.AccessLog(
-			options.Logger,
-		),
+		middleware.NewContextLogger(&options.Logger),
+		colabmiddleware.AccessLog2(),
 		middleware.ExtractAccountUUID(
 			account.Logger(options.Logger),
 			account.JWTSecret(options.Config.TokenManager.JWTSecret),
@@ -95,19 +93,21 @@ func Server(opts ...Option) (http.Service, error) {
 // prepareRoutes will prepare all the implemented routes
 func prepareRoutes(r *chi.Mux, options Options) {
 	adapter := options.Adapter
-	logger := options.Logger
+	//logger := options.Logger
 	// prepare basic logger for the request
-	r.Use(func(h stdhttp.Handler) stdhttp.Handler {
-		return stdhttp.HandlerFunc(func(w stdhttp.ResponseWriter, r *stdhttp.Request) {
-			ctx := logger.With().
-				Str(log.RequestIDString, r.Header.Get("X-Request-ID")).
-				Str("proto", r.Proto).
-				Str("method", r.Method).
-				Str("path", r.URL.Path).
-				Logger().WithContext(r.Context())
-			h.ServeHTTP(w, r.WithContext(ctx))
+	/*
+		r.Use(func(h stdhttp.Handler) stdhttp.Handler {
+			return stdhttp.HandlerFunc(func(w stdhttp.ResponseWriter, r *stdhttp.Request) {
+				ctx := logger.With().
+					Str(log.RequestIDString, r.Header.Get("X-Request-ID")).
+					Str("proto", r.Proto).
+					Str("method", r.Method).
+					Str("path", r.URL.Path).
+					Logger().WithContext(r.Context())
+				h.ServeHTTP(w, r.WithContext(ctx))
+			})
 		})
-	})
+	*/
 	r.Route("/wopi", func(r chi.Router) {
 
 		r.Get("/", func(w stdhttp.ResponseWriter, r *stdhttp.Request) {

services/collaboration/pkg/service/grpc/v0/service.go

@@ -67,6 +67,8 @@ func (s *Service) OpenInApp(
 	ctx context.Context,
 	req *appproviderv1beta1.OpenInAppRequest,
 ) (*appproviderv1beta1.OpenInAppResponse, error) {
+	ll := log.Ctx(ctx)
+	ll.Error().Msg("collaboration openinapp") //FIXME: this is just for testing. It needs to be removed.
 
 	// get the current user
 	var user *userv1beta1.User = nil

services/graph/pkg/server/http/server.go

@@ -85,7 +85,12 @@ func Server(opts ...Option) (http.Service, error) {
 	var roleService svc.RoleService
 	var valueService settingssvc.ValueService
 	var gatewaySelector pool.Selectable[gateway.GatewayAPIClient]
-	grpcClient, err := grpc.NewClient(append(grpc.GetClientOptions(options.Config.GRPCClientTLS), grpc.WithTraceProvider(options.TraceProvider))...)
+	grpcClient, err := grpc.NewClient(
+		append(
+			grpc.GetClientOptions(options.Config.GRPCClientTLS),
+			grpc.WithTraceProvider(options.TraceProvider),
+			grpc.WithClientNameAndVersion(options.Config.Service.Name, version.GetString()),
+		)...)
 	if err != nil {
 		return http.Service{}, err
 	}

services/settings/pkg/service/v0/service.go

@@ -367,6 +367,9 @@ func (g Service) ListRoleAssignmentsFiltered(ctx context.Context, req *settingss
 
 // AssignRoleToUser implements the RoleServiceHandler interface
 func (g Service) AssignRoleToUser(ctx context.Context, req *settingssvc.AssignRoleToUserRequest, res *settingssvc.AssignRoleToUserResponse) error {
+	ll := log.Ctx(ctx)
+	ll.Error().Msg("test message for debugging purposes") //FIXME: this is just for testing. It needs to be removed.
+
 	req.AccountUuid = getValidatedAccountUUID(ctx, req.AccountUuid)
 	if validationError := validateAssignRoleToUser(req); validationError != nil {
 		return merrors.BadRequest(g.id, validationError.Error())