GO-2050 Add errors and performance tracking

cmd/grpcserver/grpc.go

@@ -108,6 +108,7 @@ func main() {
 	if metrics.Enabled {
 		unaryInterceptors = append(unaryInterceptors, grpc_prometheus.UnaryServerInterceptor)
 	}
+	unaryInterceptors = append(unaryInterceptors, metrics.UnaryTraceInterceptor())
 	unaryInterceptors = append(unaryInterceptors, func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (resp interface{}, err error) {
 		resp, err = mw.Authorize(ctx, req, info, handler)
 		if err != nil {

core/block.go

@@ -177,7 +177,7 @@ func (mw *Middleware) BlockCopy(cctx context.Context, req *pb.RpcBlockCopyReques
 func (mw *Middleware) BlockPaste(cctx context.Context, req *pb.RpcBlockPasteRequest) *pb.RpcBlockPasteResponse {
 	ctx := mw.newContext(cctx)
 	response := func(code pb.RpcBlockPasteResponseErrorCode, blockIds []string, caretPosition int32, isSameBlockCaret bool, err error) *pb.RpcBlockPasteResponse {
-		m := &pb.RpcBlockPasteResponse{Error: &pb.RpcBlockPasteResponseError{Code: code}, BlockIds: blockIds, CaretPosition: caretPosition, IsSameBlockCaret: isSameBlockCaret}
+		m := &pb.RpcBlockPasteResponse{Error: &pb.RpcBlockPasteResponseError{Code: 2}, BlockIds: blockIds, CaretPosition: caretPosition, IsSameBlockCaret: isSameBlockCaret}
 		if err != nil {
 			m.Error.Description = err.Error()
 		} else {

metrics/events.go

@@ -308,12 +308,12 @@ type ImportStartedEvent struct {
 	ImportType string
 }
 
-func (c ImportStartedEvent) getBackend() MetricsBackend {
+func (i ImportStartedEvent) getBackend() MetricsBackend {
 	return ampl
 }
 
-func (i ImportStartedEvent) ToEvent() *Event {
-	return &Event{
+func (i ImportStartedEvent) Tget() *anyEvent {
+	return &anyEvent{
 		eventType: "import_started",
 		eventData: map[string]interface{}{
 			"import_id":   i.ID,
@@ -327,8 +327,12 @@ type ImportFinishedEvent struct {
 	ImportType string
 }
 
-func (i ImportFinishedEvent) ToEvent() *Event {
-	return &Event{
+func (i ImportFinishedEvent) getBackend() MetricsBackend {
+	return ampl
+}
+
+func (i ImportFinishedEvent) get() *anyEvent {
+	return &anyEvent{
 		eventType: "import_finished",
 		eventData: map[string]interface{}{
 			"import_id":   i.ID,
@@ -336,3 +340,32 @@ func (i ImportFinishedEvent) ToEvent() *Event {
 		},
 	}
 }
+
+type MethodEvent struct {
+	methodName string
+	middleTime int64
+	errorCode   int64
+	description string
+}
+
+func (c MethodEvent) getBackend() MetricsBackend {
+	return inhouse
+}
+
+func (c MethodEvent) get() *anyEvent {
+	return &anyEvent{
+		eventType: "MethodEvent",
+		eventData: map[string]interface{}{
+			"methodName": c.methodName,
+			"middleTime": c.middleTime,
+			"errorCode":   c.errorCode,
+			"description": c.description,
+		},
+	}
+}
+
+type MethodSuccessEvent struct {
+	methodName  string
+	errorCode   int64
+	description string
+}

metrics/interceptors.go

@@ -2,31 +2,100 @@ package metrics
 
 import (
 	"context"
+	"strings"
 	"time"
 
-	"github.com/anyproto/anytype-heart/util/debug"
+	"github.com/samber/lo"
+	"google.golang.org/grpc"
+
+	"github.com/anyproto/anytype-heart/util/reflection"
 )
 
-const defaultUnaryWarningAfter = time.Second * 3
+const (
+	BlockSetCarriage      = "BlockSetCarriage"
+	BlockTextSetText      = "BlockTextSetText"
+	ObjectSearchSubscribe = "ObjectSearchSubscribe"
+	fastEventsLimit       = 100
+	unexpectedErrorCode   = -1
+	parsingErrorCode      = -2
+)
 
-func SharedLongMethodsInterceptor(ctx context.Context, req any, methodName string, actualCall func(ctx context.Context, req any) (any, error)) (any, error) {
-	doneCh := make(chan struct{})
-	start := time.Now()
-
-	l := log.With("method", methodName)
-
-	go func() {
-		select {
-		case <-doneCh:
-		case <-time.After(defaultUnaryWarningAfter):
-			l.With("in_progress", true).With("goroutines", debug.StackCompact(true)).With("total", defaultUnaryWarningAfter.Milliseconds()).Warnf("grpc unary request is taking too long")
-		}
-	}()
-	ctx = context.WithValue(ctx, CtxKeyRPC, methodName)
-	resp, err := actualCall(ctx, req)
-	close(doneCh)
-	if time.Since(start) > defaultUnaryWarningAfter {
-		l.With("error", err).With("in_progress", false).With("total", time.Since(start).Milliseconds()).Warnf("grpc unary request took too long")
-	}
-	return resp, err
+var excludedMethods = []string{
+	BlockSetCarriage,
+	BlockTextSetText,
+	ObjectSearchSubscribe,
+}
+
+func UnaryTraceInterceptor() func(
+	ctx context.Context,
+	req interface{},
+	info *grpc.UnaryServerInfo,
+	handler grpc.UnaryHandler,
+) (interface{}, error) {
+	return func(
+		ctx context.Context,
+		req interface{},
+		info *grpc.UnaryServerInfo,
+		handler grpc.UnaryHandler,
+	) (interface{}, error) {
+		start := time.Now().UnixMilli()
+		resp, err := handler(ctx, req)
+		delta := time.Now().UnixMilli() - start
+
+		// it looks like that, we need the last part /anytype.ClientCommands/FileNodeUsage
+		method := strings.Split(info.FullMethod, "/")[2]
+		if !lo.Contains(excludedMethods, method) || delta > fastEventsLimit {
+			if err != nil {
+				sendUnexpectedError(method, err.Error())
+			}
+			errorCode, description, err := reflection.GetError(resp)
+			if err != nil {
+				sendErrorParsingError(method)
+			}
+			if errorCode > 0 {
+				sendExpectedError(method, errorCode, description)
+			}
+			sendSuccess(method, delta)
+		}
+
+		return resp, err
+	}
+}
+
+func sendSuccess(method string, delta int64) {
+	Service.Send(
+		&MethodEvent{
+			methodName: method,
+			middleTime: delta,
+		},
+	)
+}
+
+func sendExpectedError(method string, code int64, description string) {
+	Service.Send(
+		&MethodEvent{
+			methodName:  method,
+			errorCode:   code,
+			description: description,
+		},
+	)
+}
+
+func sendErrorParsingError(method string) {
+	Service.Send(
+		&MethodEvent{
+			methodName: method,
+			errorCode:  parsingErrorCode,
+		},
+	)
+}
+
+func sendUnexpectedError(method string, description string) {
+	Service.Send(
+		&MethodEvent{
+			methodName:  method,
+			errorCode:   unexpectedErrorCode,
+			description: description,
+		},
+	)
 }

tests/util_test.go

@@ -12,6 +12,8 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/anyproto/anytype-heart/util/reflection"
+
 	"github.com/stretchr/testify/require"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/metadata"
@@ -45,30 +47,6 @@ func cachedString(key string, rewriteCache bool, proc func() (string, error)) (s
 	return result, true, nil
 }
 
-func getError(i interface{}) error {
-	v := reflect.ValueOf(i).Elem()
-
-	for i := 0; i < v.NumField(); i++ {
-		f := v.Field(i)
-		if f.Kind() != reflect.Pointer {
-			continue
-		}
-		el := f.Elem()
-		if !el.IsValid() {
-			continue
-		}
-		if strings.Contains(el.Type().Name(), "ResponseError") {
-			code := el.FieldByName("Code").Int()
-			desc := el.FieldByName("Description").String()
-			if code > 0 {
-				return fmt.Errorf("error code %d: %s", code, desc)
-			}
-			return nil
-		}
-	}
-	return nil
-}
-
 type callCtx struct {
 	t     *testing.T
 	token string
@@ -112,7 +90,7 @@ func callReturnError[reqT any, respT any](
 	if err != nil {
 		return nilResp, err
 	}
-	err = getError(resp)
+	_, _, err = reflection.GetError(resp)
 	if err != nil {
 		return nilResp, err
 	}

util/reflection/util.go

@@ -0,0 +1,29 @@
+package reflection
+
+import (
+	"errors"
+	"reflect"
+	"strings"
+)
+
+func GetError(i interface{}) (code int64, description string, err error) {
+	v := reflect.ValueOf(i).Elem()
+
+	for i := 0; i < v.NumField(); i++ {
+		f := v.Field(i)
+		if f.Kind() != reflect.Pointer {
+			continue
+		}
+		el := f.Elem()
+		if !el.IsValid() {
+			continue
+		}
+		if strings.Contains(el.Type().Name(), "ResponseError") {
+			code = el.FieldByName("Code").Int()
+			description = el.FieldByName("Description").String()
+			return
+		}
+	}
+	err = errors.New("can't extract the error field")
+	return
+}