From c2a49d5a0ba146581cc4a6d118c51fe84422eafa Mon Sep 17 00:00:00 2001 From: SimFG Date: Mon, 13 Feb 2023 16:50:33 +0800 Subject: [PATCH] Add error log and metrics for the hook and privilege interceptor (#22111) (#22137) Signed-off-by: SimFG --- internal/metrics/metrics.go | 5 +++++ internal/metrics/proxy_metrics.go | 9 +++++++++ internal/proxy/hook_interceptor.go | 21 +++++++++++++++++++-- internal/proxy/privilege_interceptor.go | 12 +++++++----- internal/util/paramtable/hook_config.go | 6 ++++++ 5 files changed, 46 insertions(+), 7 deletions(-) diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 5c1d97271e..27facb4b38 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -60,6 +60,10 @@ const ( Leader = "OnLeader" FromLeader = "FromLeader" + HookBefore = "before" + HookAfter = "after" + HookMock = "mock" + nodeIDLabelName = "node_id" statusLabelName = "status" indexTaskStatusLabelName = "index_task_status" @@ -78,6 +82,7 @@ const ( cacheStateLabelName = "cache_state" indexCountLabelName = "indexed_field_count" requestScope = "scope" + fullMethodLabelName = "full_method" ) var ( diff --git a/internal/metrics/proxy_metrics.go b/internal/metrics/proxy_metrics.go index be623310f5..0db8d8c093 100644 --- a/internal/metrics/proxy_metrics.go +++ b/internal/metrics/proxy_metrics.go @@ -224,6 +224,14 @@ var ( Name: "limiter_rate", Help: "", }, []string{nodeIDLabelName, msgTypeLabelName}) + + ProxyHookFunc = prometheus.NewCounterVec( + prometheus.CounterOpts{ + Namespace: milvusNamespace, + Subsystem: typeutil.ProxyRole, + Name: "hook_func_count", + Help: "the hook function count", + }, []string{functionLabelName, fullMethodLabelName}) ) //RegisterProxy registers Proxy metrics @@ -258,6 +266,7 @@ func RegisterProxy(registry *prometheus.Registry) { registry.MustRegister(ProxyReadReqSendBytes) registry.MustRegister(ProxyLimiterRate) + registry.MustRegister(ProxyHookFunc) } // SetRateGaugeByRateType sets ProxyLimiterRate metrics. diff --git a/internal/proxy/hook_interceptor.go b/internal/proxy/hook_interceptor.go index d020ba7af8..acb7a674df 100644 --- a/internal/proxy/hook_interceptor.go +++ b/internal/proxy/hook_interceptor.go @@ -6,9 +6,9 @@ import ( "plugin" "github.com/milvus-io/milvus-proto/go-api/hook" - + "github.com/milvus-io/milvus/internal/log" + "github.com/milvus-io/milvus/internal/metrics" "go.uber.org/zap" - "google.golang.org/grpc" ) @@ -82,16 +82,33 @@ func UnaryServerHookInterceptor() grpc.UnaryServerInterceptor { ) if isMock, mockResp, err = hoo.Mock(ctx, req, fullMethod); isMock { + log.Info("hook mock", zap.String("user", getCurrentUser(ctx)), + zap.String("full method", fullMethod), zap.Error(err)) + metrics.ProxyHookFunc.WithLabelValues(metrics.HookMock, fullMethod).Inc() return mockResp, err } if newCtx, err = hoo.Before(ctx, req, fullMethod); err != nil { + log.Warn("hook before error", zap.String("user", getCurrentUser(ctx)), zap.String("full method", fullMethod), + zap.Any("request", req), zap.Error(err)) + metrics.ProxyHookFunc.WithLabelValues(metrics.HookBefore, fullMethod).Inc() return nil, err } realResp, realErr = handler(newCtx, req) if err = hoo.After(newCtx, realResp, realErr, fullMethod); err != nil { + log.Warn("hook after error", zap.String("user", getCurrentUser(ctx)), zap.String("full method", fullMethod), + zap.Any("request", req), zap.Error(err)) + metrics.ProxyHookFunc.WithLabelValues(metrics.HookAfter, fullMethod).Inc() return nil, err } return realResp, realErr } } + +func getCurrentUser(ctx context.Context) string { + username, err := GetCurUserFromContext(ctx) + if err != nil { + log.Warn("fail to get current user", zap.Error(err)) + } + return username +} diff --git a/internal/proxy/privilege_interceptor.go b/internal/proxy/privilege_interceptor.go index e78f296ddc..08f643f23d 100644 --- a/internal/proxy/privilege_interceptor.go +++ b/internal/proxy/privilege_interceptor.go @@ -73,7 +73,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context } username, err := GetCurUserFromContext(ctx) if err != nil { - log.Error("GetCurUserFromContext fail", zap.Error(err)) + log.Warn("GetCurUserFromContext fail", zap.Error(err)) return ctx, err } if username == util.UserRoot { @@ -81,7 +81,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context } roleNames, err := GetRole(username) if err != nil { - log.Error("GetRole fail", zap.String("username", username), zap.Error(err)) + log.Warn("GetRole fail", zap.String("username", username), zap.Error(err)) return ctx, err } roleNames = append(roleNames, util.RolePublic) @@ -96,7 +96,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context objectPrivilege := privilegeExt.ObjectPrivilege.String() policyInfo := strings.Join(globalMetaCache.GetPrivilegeInfo(ctx), ",") - log.Debug("current request info", zap.String("username", username), zap.Strings("role_names", roleNames), + logWithCurrentRequestInfo := log.With(zap.String("username", username), zap.Strings("role_names", roleNames), zap.String("object_type", objectType), zap.String("object_privilege", objectPrivilege), zap.Int32("object_index", objectNameIndex), zap.String("object_name", objectName), zap.Int32("object_indexs", objectNameIndexs), zap.Strings("object_names", objectNames), @@ -109,7 +109,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context casbinModel := templateModel.Copy() e, err := casbin.NewEnforcer(casbinModel, a) if err != nil { - log.Error("NewEnforcer fail", zap.String("policy", policy), zap.Error(err)) + logWithCurrentRequestInfo.Warn("NewEnforcer fail", zap.String("policy", policy), zap.Error(err)) return ctx, err } for _, roleName := range roleNames { @@ -126,6 +126,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context // handle the api which refers one resource permitObject, err := permitFunc(objectName) if err != nil { + logWithCurrentRequestInfo.Warn("fail to execute permit func", zap.String("name", objectName), zap.Error(err)) return ctx, err } if permitObject { @@ -139,6 +140,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context for _, name := range objectNames { p, err := permitFunc(name) if err != nil { + logWithCurrentRequestInfo.Warn("fail to execute permit func", zap.String("name", name), zap.Error(err)) return ctx, err } if !p { @@ -152,7 +154,7 @@ func PrivilegeInterceptor(ctx context.Context, req interface{}) (context.Context } } - log.Debug("permission deny", zap.String("policy", policy), zap.Strings("roles", roleNames)) + logWithCurrentRequestInfo.Info("permission deny", zap.String("policy", policy), zap.Strings("roles", roleNames)) return ctx, status.Error(codes.PermissionDenied, fmt.Sprintf("%s: permission deny", objectPrivilege)) } diff --git a/internal/util/paramtable/hook_config.go b/internal/util/paramtable/hook_config.go index 0b2fab511d..1adf78c599 100644 --- a/internal/util/paramtable/hook_config.go +++ b/internal/util/paramtable/hook_config.go @@ -1,5 +1,10 @@ package paramtable +import ( + "github.com/milvus-io/milvus/internal/log" + "go.uber.org/zap" +) + const hookYamlFile = "hook.yaml" type hookConfig struct { @@ -10,6 +15,7 @@ type hookConfig struct { func (h *hookConfig) init() { base := &BaseTable{YamlFile: hookYamlFile} base.init(0) + log.Info("hook config", zap.Any("hook", base.mgr.GetConfigs())) h.SoPath = ParamItem{ Key: "soPath",