Add error log and metrics for the hook and privilege interceptor (#22111) (#22137)

Signed-off-by: SimFG <bang.fu@zilliz.com>

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 (

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.

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
+}

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))
 }
 

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",