diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index d8fafa0f08..0b8197ca03 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -63,6 +63,10 @@ const ( Leader = "OnLeader" FromLeader = "FromLeader" + HookBefore = "before" + HookAfter = "after" + HookMock = "mock" + nodeIDLabelName = "node_id" statusLabelName = "status" indexTaskStatusLabelName = "index_task_status" @@ -82,6 +86,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 5a7d45ed75..99191c9972 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 f5d4146245..b77fcf1ddf 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.Any("request", req), 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 7c7ff09cc7..27c74687dd 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.Info("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 11bbaff9af..ada7394d85 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 { @@ -11,6 +16,7 @@ type HookConfig struct { func (h *HookConfig) init() { h.Base = &BaseTable{YamlFile: hookYamlFile} h.Base.Init() + log.Info("hook config", zap.Any("hook", h.Base.Configs())) h.initSoPath() h.initSoConfig()