mirror of
https://github.com/hanzoai/tasks.git
synced 2026-10-04 02:04:03 +00:00
0cd888ac49
## What changed?
A new interceptor has been written and added to frontend's FX chain that
logs slow gRPC requests. Requests are logged with their elapsed time,
and more importantly, their extracted request IDs/workflow tags, so
on-call can quickly determine the problematic IDs.
This is what the log line might look like:
```json
{
"level": "warn",
"ts": "2025-05-06T15:34:35.600-0700",
"msg": "Slow gRPC call",
"duration": "6.000857875s",
"method": "temporal.api.workflowservice.v1.WorkflowService/DescribeWorkflowExecution",
"wf-id": "fc48187c-3df0-4c6e-b898-027ffe3e9066",
"wf-run-id": "0196a7bc-73ec-7f1b-890d-a0bbbf63ac21",
"logging-call-at": "/Users/lina/code/temporal/common/rpc/interceptor/slow_request_logger.go:59"
}
```
## Why?
Because these request IDs are often deep within a protobuf request body,
they aren't visible through Envoy/Chronicle logs, so although we can
often see that a customer is experiencing request-reply latency, we have
little else to follow-up on without asking them for more information.
## How did you test it?
- [x] built
- [x] run locally and tested manually
- [ ] covered by existing tests
- [x] added new unit test(s)
- [ ] added new functional test(s)
## Potential risks
We could end up with spammy log lines if we have lots of methods which
regularly complete over the threshold, that aren't on the ignore list. I
based the ignore and threshold on the frontend API dashboards across a
few cells.
---------
Co-authored-by: David Reiss <[email protected]>
99 lines
2.9 KiB
Go
99 lines
2.9 KiB
Go
package interceptor_test
|
|
|
|
import (
|
|
"context"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/stretchr/testify/suite"
|
|
commonpb "go.temporal.io/api/common/v1"
|
|
"go.temporal.io/api/workflowservice/v1"
|
|
"go.temporal.io/server/common/dynamicconfig"
|
|
"go.temporal.io/server/common/log"
|
|
"go.temporal.io/server/common/rpc/interceptor"
|
|
"go.uber.org/mock/gomock"
|
|
"google.golang.org/grpc"
|
|
)
|
|
|
|
const (
|
|
testThreshold = 10 * time.Millisecond
|
|
)
|
|
|
|
type slowRequestLoggerSuite struct {
|
|
suite.Suite
|
|
controller *gomock.Controller
|
|
|
|
logger *log.MockLogger
|
|
interceptor *interceptor.SlowRequestLoggerInterceptor
|
|
}
|
|
|
|
func TestSlowRequestLoggerInterceptor(t *testing.T) {
|
|
suite.Run(t, &slowRequestLoggerSuite{})
|
|
}
|
|
|
|
func (s *slowRequestLoggerSuite) SetupTest() {
|
|
s.controller = gomock.NewController(s.T())
|
|
s.logger = log.NewMockLogger(s.controller)
|
|
s.interceptor = interceptor.NewSlowRequestLoggerInterceptor(
|
|
s.logger,
|
|
dynamicconfig.GetDurationPropertyFn(testThreshold),
|
|
)
|
|
}
|
|
|
|
func (s *slowRequestLoggerSuite) TestIntercept() {
|
|
ctx := context.Background()
|
|
|
|
// Factory function to return a UnaryHandler that sleeps for a duration.
|
|
makeHandler := func(delay time.Duration) grpc.UnaryHandler {
|
|
return func(_ context.Context, _ any) (any, error) {
|
|
//nolint:forbidigo // Allow time.Sleep for timeout tests
|
|
time.Sleep(delay)
|
|
return nil, nil
|
|
}
|
|
}
|
|
fastHandler := makeHandler(0) // sleep will return immediately
|
|
slowHandler := makeHandler(testThreshold + 1)
|
|
|
|
// Dummy request to test extraction.
|
|
request := &workflowservice.DescribeWorkflowExecutionRequest{
|
|
Namespace: "namespace-name",
|
|
Execution: &commonpb.WorkflowExecution{
|
|
WorkflowId: "wf-id",
|
|
RunId: "run-id",
|
|
},
|
|
}
|
|
info := &grpc.UnaryServerInfo{
|
|
FullMethod: workflowservice.WorkflowService_DescribeWorkflowExecution_FullMethodName,
|
|
}
|
|
|
|
// Ensure fast requests aren't logged.
|
|
_, err := s.interceptor.Intercept(ctx, request, info, fastHandler)
|
|
s.NoError(err)
|
|
|
|
// Ensure slow requests are logged.
|
|
expectedMsg := "Slow gRPC call"
|
|
s.logger.EXPECT().Warn(gomock.Eq(expectedMsg), gomock.Any()).Times(1)
|
|
_, err = s.interceptor.Intercept(ctx, request, info, slowHandler)
|
|
s.NoError(err)
|
|
|
|
// Slow request without parameters set.
|
|
s.logger.EXPECT().Warn(gomock.Eq(expectedMsg), gomock.Any()).Times(1)
|
|
_, err = s.interceptor.Intercept(ctx, &workflowservice.DescribeWorkflowExecutionRequest{}, info, slowHandler)
|
|
s.NoError(err)
|
|
|
|
// Nil request bodies.
|
|
s.logger.EXPECT().Warn(gomock.Eq(expectedMsg), gomock.Any()).Times(1)
|
|
_, err = s.interceptor.Intercept(ctx, nil, info, slowHandler)
|
|
s.NoError(err)
|
|
|
|
// Unknown request bodies.
|
|
s.logger.EXPECT().Warn(gomock.Eq(expectedMsg), gomock.Any()).Times(1)
|
|
_, err = s.interceptor.Intercept(ctx, &struct{}{}, info, slowHandler)
|
|
s.NoError(err)
|
|
|
|
// Ensure poll requests, or other expected-slow requests, aren't logged.
|
|
info.FullMethod = workflowservice.WorkflowService_PollWorkflowExecutionUpdate_FullMethodName
|
|
_, err = s.interceptor.Intercept(ctx, nil, info, slowHandler)
|
|
s.NoError(err)
|
|
}
|