From e4885cba15cbac2d442b6b17217b43734d39cf4b Mon Sep 17 00:00:00 2001 From: Youngteac Hong Date: Tue, 2 Jul 2024 11:42:26 +0900 Subject: [PATCH] Add Project field to YorkieService logs (#911) This commit adds project field to the YorkieService logs for easier project identification during debugging. Additionally, removes LoggingInterceptor to allow each service to define its own log fields, as YorkieService and AdminService logs may differ. --- server/logging/logging.go | 24 +++++- server/rpc/connecthelper/logging.go | 77 ------------------- server/rpc/connecthelper/status.go | 1 + .../interceptors/{admin_auth.go => admin.go} | 77 ++++++++++++------- server/rpc/interceptors/default.go | 5 +- server/rpc/interceptors/requestid.go | 42 ++++++++++ .../interceptors/{context.go => yorkie.go} | 45 ++++++----- server/rpc/server.go | 6 +- 8 files changed, 144 insertions(+), 133 deletions(-) delete mode 100644 server/rpc/connecthelper/logging.go rename server/rpc/interceptors/{admin_auth.go => admin.go} (69%) create mode 100644 server/rpc/interceptors/requestid.go rename server/rpc/interceptors/{context.go => yorkie.go} (76%) diff --git a/server/logging/logging.go b/server/logging/logging.go index 1faabd318..371496d09 100644 --- a/server/logging/logging.go +++ b/server/logging/logging.go @@ -30,6 +30,9 @@ import ( // Logger is a wrapper of zap.Logger. type Logger = *zap.SugaredLogger +// Field is a wrapper of zap.Field. +type Field = zap.Field + var defaultLogger Logger var logLevel = zapcore.InfoLevel var loggerOnce sync.Once @@ -57,8 +60,25 @@ func SetLogLevel(level string) error { } // New creates a new logger with the given configuration. -func New(name string) Logger { - return newLogger(name) +func New(name string, fields ...Field) Logger { + logger := newLogger(name) + + if len(fields) > 0 { + var args = make([]interface{}, len(fields)) + for i, field := range fields { + args[i] = field + } + + logger = logger.With(args...) + } + + return logger +} + +// NewField creates a new field with the given key and value. +func NewField(key string, value string) Field { + return zap.String(key, value) + } // DefaultLogger returns the default logger used by Yorkie. diff --git a/server/rpc/connecthelper/logging.go b/server/rpc/connecthelper/logging.go deleted file mode 100644 index 01359b480..000000000 --- a/server/rpc/connecthelper/logging.go +++ /dev/null @@ -1,77 +0,0 @@ -/* - * Copyright 2022 The Yorkie Authors. All rights reserved. - * - * 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. - */ - -// Package connecthelper provides helper functions for connectRPC. -package connecthelper - -import ( - "context" - "strconv" - "sync/atomic" - - "connectrpc.com/connect" - - "github.com/yorkie-team/yorkie/server/logging" -) - -type reqID int32 - -func (c *reqID) next() string { - next := atomic.AddInt32((*int32)(c), 1) - return "r" + strconv.Itoa(int(next)) -} - -// LoggingInterceptor is an interceptor for request logging. -type LoggingInterceptor struct { - reqID reqID -} - -// NewLoggingInterceptor creates a new instance of LoggingInterceptor. -func NewLoggingInterceptor() *LoggingInterceptor { - return &LoggingInterceptor{} -} - -// WrapUnary creates a unary server interceptor for request logging. -func (i *LoggingInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { - return func( - ctx context.Context, - req connect.AnyRequest, - ) (connect.AnyResponse, error) { - reqLogger := logging.New(i.reqID.next()) - return next(logging.With(ctx, reqLogger), req) - } -} - -// WrapStreamingClient creates a stream client interceptor for request logging. -func (i *LoggingInterceptor) WrapStreamingClient(next connect.StreamingClientFunc) connect.StreamingClientFunc { - return func( - ctx context.Context, - spec connect.Spec, - ) connect.StreamingClientConn { - return next(ctx, spec) - } -} - -// WrapStreamingHandler creates a stream server interceptor for request logging. -func (i *LoggingInterceptor) WrapStreamingHandler(next connect.StreamingHandlerFunc) connect.StreamingHandlerFunc { - return func( - ctx context.Context, - conn connect.StreamingHandlerConn, - ) error { - reqLogger := logging.New(i.reqID.next()) - return next(logging.With(ctx, reqLogger), conn) - } -} diff --git a/server/rpc/connecthelper/status.go b/server/rpc/connecthelper/status.go index ad7a4be9b..6301980db 100644 --- a/server/rpc/connecthelper/status.go +++ b/server/rpc/connecthelper/status.go @@ -14,6 +14,7 @@ * limitations under the License. */ +// Package connecthelper provides helper functions for connectRPC. package connecthelper import ( diff --git a/server/rpc/interceptors/admin_auth.go b/server/rpc/interceptors/admin.go similarity index 69% rename from server/rpc/interceptors/admin_auth.go rename to server/rpc/interceptors/admin.go index 39ee85119..1f6ab5373 100644 --- a/server/rpc/interceptors/admin_auth.go +++ b/server/rpc/interceptors/admin.go @@ -26,6 +26,7 @@ import ( "github.com/yorkie-team/yorkie/api/types" "github.com/yorkie-team/yorkie/server/backend" + "github.com/yorkie-team/yorkie/server/logging" "github.com/yorkie-team/yorkie/server/projects" "github.com/yorkie-team/yorkie/server/rpc/auth" "github.com/yorkie-team/yorkie/server/rpc/connecthelper" @@ -35,22 +36,34 @@ import ( // ErrUnauthenticated is returned when authentication is failed. var ErrUnauthenticated = errors.New("authorization is not provided") -// AdminAuthInterceptor is an interceptor for authentication. -type AdminAuthInterceptor struct { +func isAdminService(method string) bool { + return strings.HasPrefix(method, "/yorkie.v1.AdminService") +} + +func isRequiredAuth(method string) bool { + return method != "/yorkie.v1.AdminService/LogIn" && + method != "/yorkie.v1.AdminService/SignUp" +} + +// AdminServiceInterceptor is an interceptor for building additional context +// and handling authentication for AdminService. +type AdminServiceInterceptor struct { backend *backend.Backend + requestID *requestID tokenManager *auth.TokenManager } -// NewAdminAuthInterceptor creates a new instance of AdminAuthInterceptor. -func NewAdminAuthInterceptor(be *backend.Backend, tokenManager *auth.TokenManager) *AdminAuthInterceptor { - return &AdminAuthInterceptor{ +// NewAdminServiceInterceptor creates a new instance of AdminServiceInterceptor. +func NewAdminServiceInterceptor(be *backend.Backend, tokenManager *auth.TokenManager) *AdminServiceInterceptor { + return &AdminServiceInterceptor{ backend: be, + requestID: newRequestID("a"), tokenManager: tokenManager, } } // WrapUnary creates a unary server interceptor for authentication. -func (i *AdminAuthInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { +func (i *AdminServiceInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { return func( ctx context.Context, req connect.AnyRequest, @@ -59,12 +72,9 @@ func (i *AdminAuthInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFu return next(ctx, req) } - if isRequiredAuth(req.Spec().Procedure) { - user, err := i.authenticate(ctx, req.Header()) - if err != nil { - return nil, err - } - ctx = users.With(ctx, user) + ctx, err := i.buildContext(ctx, req.Spec().Procedure, req.Header()) + if err != nil { + return nil, err } res, err := next(ctx, req) @@ -92,7 +102,7 @@ func (i *AdminAuthInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFu } // WrapStreamingClient creates a stream client interceptor for authentication. -func (i *AdminAuthInterceptor) WrapStreamingClient(next connect.StreamingClientFunc) connect.StreamingClientFunc { +func (i *AdminServiceInterceptor) WrapStreamingClient(next connect.StreamingClientFunc) connect.StreamingClientFunc { return func( ctx context.Context, spec connect.Spec, @@ -102,7 +112,7 @@ func (i *AdminAuthInterceptor) WrapStreamingClient(next connect.StreamingClientF } // WrapStreamingHandler creates a stream server interceptor for authentication. -func (i *AdminAuthInterceptor) WrapStreamingHandler(next connect.StreamingHandlerFunc) connect.StreamingHandlerFunc { +func (i *AdminServiceInterceptor) WrapStreamingHandler(next connect.StreamingHandlerFunc) connect.StreamingHandlerFunc { return func( ctx context.Context, conn connect.StreamingHandlerConn, @@ -111,15 +121,12 @@ func (i *AdminAuthInterceptor) WrapStreamingHandler(next connect.StreamingHandle return next(ctx, conn) } - if isRequiredAuth(conn.Spec().Procedure) { - user, err := i.authenticate(ctx, conn.RequestHeader()) - if err != nil { - return err - } - ctx = users.With(ctx, user) + ctx, err := i.buildContext(ctx, conn.Spec().Procedure, conn.RequestHeader()) + if err != nil { + return err } - err := next(ctx, conn) + err = next(ctx, conn) // TODO(hackerwins, emplam27): Consider splitting between admin and sdk metrics. sdkType, sdkVersion := connecthelper.SDKTypeAndVersion(conn.RequestHeader()) @@ -143,17 +150,27 @@ func (i *AdminAuthInterceptor) WrapStreamingHandler(next connect.StreamingHandle } } -func isAdminService(method string) bool { - return strings.HasPrefix(method, "/yorkie.v1.AdminService") -} +// buildContext builds a new context with the given request header. +func (i *AdminServiceInterceptor) buildContext( + ctx context.Context, + procedure string, + header http.Header, +) (context.Context, error) { + if isRequiredAuth(procedure) { + user, err := i.authenticate(ctx, header) + if err != nil { + return nil, err + } + ctx = users.With(ctx, user) + } -func isRequiredAuth(method string) bool { - return method != "/yorkie.v1.AdminService/LogIn" && - method != "/yorkie.v1.AdminService/SignUp" + ctx = logging.With(ctx, logging.New(i.requestID.next())) + + return ctx, nil } // authenticate does authenticate the request. -func (i *AdminAuthInterceptor) authenticate( +func (i *AdminServiceInterceptor) authenticate( ctx context.Context, header http.Header, ) (*types.User, error) { @@ -163,6 +180,7 @@ func (i *AdminAuthInterceptor) authenticate( } // NOTE(raararaara): If the token is access token, return the user of the token. + // This is used for the case where the user uses dashboard or CLI. claims, err := i.tokenManager.Verify(authorization) if err == nil { user, err := users.GetUserByName(ctx, i.backend, claims.Username) @@ -172,6 +190,9 @@ func (i *AdminAuthInterceptor) authenticate( } // NOTE(raararaara): If the token is secret key, return the owner of the project. + // This is used for the case where the user uses REST API. + // TODO(hackerwins): In this case, attacker can hijack the project owner's identity. + // We need to separate project-wide API and user-wide API from AdminService. project, err := projects.GetProjectFromSecretKey(ctx, i.backend, authorization) if err == nil { user, err := users.GetUserByID(ctx, i.backend, project.Owner) diff --git a/server/rpc/interceptors/default.go b/server/rpc/interceptors/default.go index acdfe8c4a..674c40296 100644 --- a/server/rpc/interceptors/default.go +++ b/server/rpc/interceptors/default.go @@ -23,12 +23,11 @@ import ( "connectrpc.com/connect" - "github.com/yorkie-team/yorkie/server/rpc/connecthelper" - "github.com/yorkie-team/yorkie/server/logging" + "github.com/yorkie-team/yorkie/server/rpc/connecthelper" ) -// DefaultInterceptor is a interceptor for default. +// DefaultInterceptor is an interceptor for common RPC. type DefaultInterceptor struct{} // NewDefaultInterceptor creates a new instance of DefaultInterceptor. diff --git a/server/rpc/interceptors/requestid.go b/server/rpc/interceptors/requestid.go new file mode 100644 index 000000000..f43068340 --- /dev/null +++ b/server/rpc/interceptors/requestid.go @@ -0,0 +1,42 @@ +/* + * Copyright 2022 The Yorkie Authors. All rights reserved. + * + * 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. + */ + +package interceptors + +import ( + "strconv" + "sync/atomic" +) + +// requestID is used to generate a unique request ID. +type requestID struct { + prefix string + id int32 +} + +// newRequestID creates a new requestID. +func newRequestID(prefix string) *requestID { + return &requestID{ + prefix: prefix, + id: 0, + } +} + +// next generates a new request ID. +func (r *requestID) next() string { + next := atomic.AddInt32(&r.id, 1) + return r.prefix + strconv.Itoa(int(next)) +} diff --git a/server/rpc/interceptors/context.go b/server/rpc/interceptors/yorkie.go similarity index 76% rename from server/rpc/interceptors/context.go rename to server/rpc/interceptors/yorkie.go index 076b15a55..5a29812fc 100644 --- a/server/rpc/interceptors/context.go +++ b/server/rpc/interceptors/yorkie.go @@ -35,26 +35,33 @@ import ( "github.com/yorkie-team/yorkie/server/rpc/metadata" ) -// ContextInterceptor is an interceptor for building additional context. -type ContextInterceptor struct { +func isYorkieService(method string) bool { + return strings.HasPrefix(method, "/yorkie.v1.YorkieService/") +} + +// YorkieServiceInterceptor is an interceptor for building additional context +// and handling authentication for YorkieService. +type YorkieServiceInterceptor struct { backend *backend.Backend + requestID *requestID projectInfoCache *cache.LRUExpireCache[string, *types.Project] } -// NewContextInterceptor creates a new instance of ContextInterceptor. -func NewContextInterceptor(be *backend.Backend) *ContextInterceptor { +// NewYorkieServiceInterceptor creates a new instance of YorkieServiceInterceptor. +func NewYorkieServiceInterceptor(be *backend.Backend) *YorkieServiceInterceptor { projectInfoCache, err := cache.NewLRUExpireCache[string, *types.Project](be.Config.ProjectInfoCacheSize) if err != nil { logging.DefaultLogger().Fatal("Failed to create project info cache: %v", err) } - return &ContextInterceptor{ + return &YorkieServiceInterceptor{ backend: be, + requestID: newRequestID("r"), projectInfoCache: projectInfoCache, } } // WrapUnary creates a unary server interceptor for building additional context. -func (i *ContextInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { +func (i *YorkieServiceInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc { return func( ctx context.Context, req connect.AnyRequest, @@ -93,7 +100,7 @@ func (i *ContextInterceptor) WrapUnary(next connect.UnaryFunc) connect.UnaryFunc } // WrapStreamingClient creates a stream client interceptor for building additional context. -func (i *ContextInterceptor) WrapStreamingClient(next connect.StreamingClientFunc) connect.StreamingClientFunc { +func (i *YorkieServiceInterceptor) WrapStreamingClient(next connect.StreamingClientFunc) connect.StreamingClientFunc { return func( ctx context.Context, spec connect.Spec, @@ -103,7 +110,9 @@ func (i *ContextInterceptor) WrapStreamingClient(next connect.StreamingClientFun } // WrapStreamingHandler creates a stream server interceptor for building additional context. -func (i *ContextInterceptor) WrapStreamingHandler(next connect.StreamingHandlerFunc) connect.StreamingHandlerFunc { +func (i *YorkieServiceInterceptor) WrapStreamingHandler( + next connect.StreamingHandlerFunc, +) connect.StreamingHandlerFunc { return func( ctx context.Context, conn connect.StreamingHandlerConn, @@ -141,13 +150,9 @@ func (i *ContextInterceptor) WrapStreamingHandler(next connect.StreamingHandlerF } } -func isYorkieService(method string) bool { - return strings.HasPrefix(method, "/yorkie.v1.YorkieService/") -} - // buildContext builds a context data for RPC. It includes the metadata of the // request and the project information. -func (i *ContextInterceptor) buildContext(ctx context.Context, header http.Header) (context.Context, error) { +func (i *YorkieServiceInterceptor) buildContext(ctx context.Context, header http.Header) (context.Context, error) { // 01. building metadata md := metadata.Metadata{} @@ -166,16 +171,18 @@ func (i *ContextInterceptor) buildContext(ctx context.Context, header http.Heade cacheKey := md.APIKey // 02. building project - if cachedProjectInfo, ok := i.projectInfoCache.Get(cacheKey); ok { - ctx = projects.With(ctx, cachedProjectInfo) - } else { - project, err := projects.GetProjectFromAPIKey(ctx, i.backend, md.APIKey) + if _, ok := i.projectInfoCache.Get(cacheKey); !ok { + prj, err := projects.GetProjectFromAPIKey(ctx, i.backend, md.APIKey) if err != nil { return nil, connecthelper.ToStatusError(err) } - i.projectInfoCache.Add(cacheKey, project, i.backend.Config.ParseProjectInfoCacheTTL()) - ctx = projects.With(ctx, project) + i.projectInfoCache.Add(cacheKey, prj, i.backend.Config.ParseProjectInfoCacheTTL()) } + project, _ := i.projectInfoCache.Get(cacheKey) + ctx = projects.With(ctx, project) + + // 03. building logger + ctx = logging.With(ctx, logging.New(i.requestID.next(), logging.NewField("prj", project.Name))) return ctx, nil } diff --git a/server/rpc/server.go b/server/rpc/server.go index e3977853b..85f57b521 100644 --- a/server/rpc/server.go +++ b/server/rpc/server.go @@ -36,7 +36,6 @@ import ( "github.com/yorkie-team/yorkie/server/backend" "github.com/yorkie-team/yorkie/server/logging" "github.com/yorkie-team/yorkie/server/rpc/auth" - "github.com/yorkie-team/yorkie/server/rpc/connecthelper" "github.com/yorkie-team/yorkie/server/rpc/interceptors" ) @@ -57,9 +56,8 @@ func NewServer(conf *Config, be *backend.Backend) (*Server, error) { opts := []connect.HandlerOption{ connect.WithInterceptors( - connecthelper.NewLoggingInterceptor(), - interceptors.NewAdminAuthInterceptor(be, tokenManager), - interceptors.NewContextInterceptor(be), + interceptors.NewAdminServiceInterceptor(be, tokenManager), + interceptors.NewYorkieServiceInterceptor(be), interceptors.NewDefaultInterceptor(), ), }