Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"history client encountered error" server log is wrong level and noisy #2700

Closed
Spikhalskiy opened this issue Apr 3, 2022 · 0 comments · Fixed by #2701
Closed

"history client encountered error" server log is wrong level and noisy #2700

Spikhalskiy opened this issue Apr 3, 2022 · 0 comments · Fixed by #2701
Labels
devexp enhancement New feature or request

Comments

@Spikhalskiy
Copy link
Contributor

Spikhalskiy commented Apr 3, 2022

Actual Behavior

It looks like the Temporal Server logs every time it/sdks sends a response with an error to the history service client. An example is

temporal                | {"level":"error","ts":"2022-04-03T17:42:02.372Z","msg":"history client encountered error","service":"frontend","error":"BadSearchAttributes: search attribute UnknownKey is not defined","service-error-type":"serviceerror.InvalidArgument","logging-call-at":"metricClient.go:638","stacktrace":"go.temporal.io/server/common/log.(*zapLogger).Error\n\t/home/builder/temporal/common/log/zap_logger.go:142\ngo.temporal.io/server/common/log.(*throttledLogger).Error.func1\n\t/home/builder/temporal/common/log/throttle_logger.go:79\ngo.temporal.io/server/common/log.(*throttledLogger).rateLimit\n\t/home/builder/temporal/common/log/throttle_logger.go:100\ngo.temporal.io/server/common/log.(*throttledLogger).Error\n\t/home/builder/temporal/common/log/throttle_logger.go:78\ngo.temporal.io/server/client/history.(*metricClient).finishMetricsRecording\n\t/home/builder/temporal/client/history/metricClient.go:638\ngo.temporal.io/server/client/history.(*metricClient).RespondWorkflowTaskCompleted.func1\n\t/home/builder/temporal/client/history/metricClient.go:229\ngo.temporal.io/server/client/history.(*metricClient).RespondWorkflowTaskCompleted\n\t/home/builder/temporal/client/history/metricClient.go:232\ngo.temporal.io/server/client/history.(*retryableClient).RespondWorkflowTaskCompleted.func1\n\t/home/builder/temporal/client/history/retryableClient.go:269\ngo.temporal.io/server/common/backoff.Retry.func1\n\t/home/builder/temporal/common/backoff/retry.go:104\ngo.temporal.io/server/common/backoff.RetryContext\n\t/home/builder/temporal/common/backoff/retry.go:125\ngo.temporal.io/server/common/backoff.Retry\n\t/home/builder/temporal/common/backoff/retry.go:105\ngo.temporal.io/server/client/history.(*retryableClient).RespondWorkflowTaskCompleted\n\t/home/builder/temporal/client/history/retryableClient.go:273\ngo.temporal.io/server/service/frontend.(*WorkflowHandler).RespondWorkflowTaskCompleted\n\t/home/builder/temporal/service/frontend/workflowHandler.go:977\ngo.temporal.io/server/service/frontend.(*DCRedirectionHandlerImpl).RespondWorkflowTaskCompleted.func2\n\t/home/builder/temporal/service/frontend/dcRedirectionHandler.go:968\ngo.temporal.io/server/service/frontend.(*NoopRedirectionPolicy).WithNamespaceIDRedirect\n\t/home/builder/temporal/service/frontend/dcRedirectionPolicy.go:120\ngo.temporal.io/server/service/frontend.(*DCRedirectionHandlerImpl).RespondWorkflowTaskCompleted\n\t/home/builder/temporal/service/frontend/dcRedirectionHandler.go:964\ngo.temporal.io/api/workflowservice/v1._WorkflowService_RespondWorkflowTaskCompleted_Handler.func1\n\t/go/pkg/mod/go.temporal.io/[email protected]/workflowservice/v1/service.pb.go:1215\ngo.temporal.io/server/common/rpc/interceptor.(*SDKVersionInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/sdk_version.go:63\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1116\ngo.temporal.io/server/common/authorization.(*interceptor).Interceptor\n\t/home/builder/temporal/common/authorization/interceptor.go:152\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*NamespaceCountLimitInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/namespace_count_limit.go:99\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*NamespaceRateLimitInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/namespace_rate_limit.go:89\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*RateLimitInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/rate_limit.go:84\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*NamespaceValidatorInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/namespace_validator.go:113\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*TelemetryInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/telemetry.go:108\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/metrics.NewServerMetricsContextInjectorInterceptor.func1\n\t/home/builder/temporal/common/metrics/grpc.go:66\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc.ServiceErrorInterceptor\n\t/home/builder/temporal/common/rpc/grpc.go:131\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngo.temporal.io/server/common/rpc/interceptor.(*NamespaceLogInterceptor).Intercept\n\t/home/builder/temporal/common/rpc/interceptor/namespace_logger.go:84\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1.1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1119\ngoogle.golang.org/grpc.chainUnaryInterceptors.func1\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1121\ngo.temporal.io/api/workflowservice/v1._WorkflowService_RespondWorkflowTaskCompleted_Handler\n\t/go/pkg/mod/go.temporal.io/[email protected]/workflowservice/v1/service.pb.go:1217\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1282\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:1619\ngoogle.golang.org/grpc.(*Server).serveStreams.func1.2\n\t/go/pkg/mod/google.golang.org/[email protected]/server.go:921"}

This may be neat, but it's extremely noisy for the logs and usually, these kinds of errors are NOT a server problem.
These log lines also tend to be huge with pretty irrelevant stacktrace for the reader.

Expected Behavior

This should be a warn on error in the client/sdk logs, but I propose that the level of these messages in the server log should be decreased. It probably should be an info, not an error in server logs.

@Spikhalskiy Spikhalskiy added enhancement New feature or request devexp labels Apr 3, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
devexp enhancement New feature or request
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant