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]>
67 lines
1.7 KiB
Go
67 lines
1.7 KiB
Go
package interceptor
|
|
|
|
import (
|
|
"context"
|
|
"time"
|
|
|
|
"go.temporal.io/server/common/api"
|
|
"go.temporal.io/server/common/dynamicconfig"
|
|
"go.temporal.io/server/common/log"
|
|
"go.temporal.io/server/common/log/tag"
|
|
"go.temporal.io/server/common/rpc/interceptor/logtags"
|
|
"go.temporal.io/server/common/tasktoken"
|
|
"google.golang.org/grpc"
|
|
)
|
|
|
|
type SlowRequestLoggerInterceptor struct {
|
|
logger log.Logger
|
|
workflowTags *logtags.WorkflowTags
|
|
slowRequestThreshold dynamicconfig.DurationPropertyFn
|
|
}
|
|
|
|
func NewSlowRequestLoggerInterceptor(
|
|
logger log.Logger,
|
|
slowRequestThreshold dynamicconfig.DurationPropertyFn,
|
|
) *SlowRequestLoggerInterceptor {
|
|
return &SlowRequestLoggerInterceptor{
|
|
logger: logger,
|
|
workflowTags: logtags.NewWorkflowTags(tasktoken.NewSerializer(), logger),
|
|
slowRequestThreshold: slowRequestThreshold,
|
|
}
|
|
}
|
|
|
|
func (i *SlowRequestLoggerInterceptor) Intercept(
|
|
ctx context.Context,
|
|
request interface{},
|
|
info *grpc.UnaryServerInfo,
|
|
handler grpc.UnaryHandler,
|
|
) (interface{}, error) {
|
|
// Long-polled methods aren't useful logged.
|
|
if api.GetMethodMetadata(info.FullMethod).Polling == api.PollingNone {
|
|
startTime := time.Now()
|
|
|
|
defer func() {
|
|
elapsed := time.Since(startTime)
|
|
if elapsed > i.slowRequestThreshold() {
|
|
i.logSlowRequest(request, info, elapsed)
|
|
}
|
|
}()
|
|
}
|
|
|
|
return handler(ctx, request)
|
|
}
|
|
|
|
func (i *SlowRequestLoggerInterceptor) logSlowRequest(
|
|
request interface{},
|
|
info *grpc.UnaryServerInfo,
|
|
elapsed time.Duration,
|
|
) {
|
|
method := info.FullMethod
|
|
|
|
tags := i.workflowTags.Extract(request, method)
|
|
tags = append(tags, tag.NewDurationTag("duration", elapsed))
|
|
tags = append(tags, tag.NewStringTag("method", method))
|
|
|
|
i.logger.Warn("Slow gRPC call", tags...)
|
|
}
|