diff --git a/CHANGELOG.md b/CHANGELOG.md index 875156ea2..b89461f8a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,5 @@ +* Massive changed log messages - those have more details now. + ## v3.99.7 * Fixed not passing request context to topic event logs * Fixed deadlock on closing table session with internal query session core diff --git a/internal/topic/topicwriterinternal/writer_single_stream.go b/internal/topic/topicwriterinternal/writer_single_stream.go index 6dbb3803c..ada95c16c 100644 --- a/internal/topic/topicwriterinternal/writer_single_stream.go +++ b/internal/topic/topicwriterinternal/writer_single_stream.go @@ -126,7 +126,7 @@ func (w *SingleStreamWriter) start() { func (w *SingleStreamWriter) initStream() (err error) { traceOnDone := trace.TopicOnWriterInitStream(w.cfg.Tracer, w.cfg.reconnectorInstanceID, w.cfg.topic, w.cfg.producerID) - defer traceOnDone(w.SessionID, err) + defer func() { traceOnDone(w.SessionID, err) }() req := w.createInitRequest() if err = w.cfg.stream.Send(&req); err != nil { diff --git a/log/coordination.go b/log/coordination.go index d14bf4eac..1fdd19a13 100644 --- a/log/coordination.go +++ b/log/coordination.go @@ -25,11 +25,11 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "new") - l.Log(ctx, "start") + l.Log(ctx, "starting coordination client...") start := time.Now() return func(info trace.CoordinationNewDoneInfo) { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "coordination client started", kv.Latency(start), kv.Version(), ) @@ -40,18 +40,18 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "create") - l.Log(ctx, "start", + l.Log(ctx, "starting coordination node...", kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationCreateNodeDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "coordination node started", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "coordination node start failed", kv.Latency(start), kv.Version(), ) @@ -63,18 +63,18 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "alter") - l.Log(ctx, "start", + l.Log(ctx, "starting alter coordination node...", kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationAlterNodeDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "alter coordination node done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "alter coordination node failed", kv.Latency(start), kv.Version(), ) @@ -86,18 +86,18 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "drop") - l.Log(ctx, "start", + l.Log(ctx, "starting drop coordination node...", kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationDropNodeDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "coordination node dropped", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "coordination node drop failed", kv.Latency(start), kv.Version(), ) @@ -109,18 +109,18 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "describe") - l.Log(ctx, "start", + l.Log(ctx, "starting describe coordination node...", kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationDescribeNodeDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "describe node started", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "describe node start failed", kv.Latency(start), kv.Version(), ) @@ -132,16 +132,16 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "describe") - l.Log(ctx, "start") + l.Log(ctx, "starting create coordination session...") start := time.Now() return func(info trace.CoordinationSessionDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "coordination session created", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "create coordination session failed", kv.Latency(start), kv.Version(), ) @@ -153,16 +153,16 @@ func internalCoordination( return nil } ctx := with(*info.Context, TRACE, "ydb", "coordination", "close") - l.Log(ctx, "start") + l.Log(ctx, "start closing coordination client...") start := time.Now() return func(info trace.CoordinationCloseDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "coordination client closed", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "fail", + l.Log(WithLevel(ctx, ERROR), "close coordination client failed", kv.Latency(start), kv.Version(), ) @@ -178,11 +178,11 @@ func internalCoordination( return nil } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stream", "new") - l.Log(ctx, "stream") + l.Log(ctx, "starting new coordination session stam...") start := time.Now() return func(info trace.CoordinationSessionNewStreamDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "new coordination session stream started", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -194,7 +194,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "started") - l.Log(ctx, "", + l.Log(ctx, "coordination session started", kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), ) @@ -204,7 +204,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "start", "timeout") - l.Log(ctx, "", + l.Log(ctx, "coordination session start timeout", kv.Stringer("timeout", info.Timeout), ) }, @@ -213,7 +213,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "keepAlive", "timeout") - l.Log(ctx, "", + l.Log(ctx, "coordination session keep alive timeout", kv.Stringer("timeout", info.Timeout), kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime), ) @@ -223,7 +223,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stopped") - l.Log(ctx, "", + l.Log(ctx, "coordination session stopped", kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), ) @@ -233,7 +233,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop", "timeout") - l.Log(ctx, "", + l.Log(ctx, "coordination session stop timeout", kv.Stringer("timeout", info.Timeout), ) }, @@ -242,7 +242,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "client", "timeout") - l.Log(ctx, "", + l.Log(ctx, "coordination session client timeout", kv.Stringer("timeout", info.Timeout), kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime), ) @@ -252,7 +252,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "expire") - l.Log(ctx, "", + l.Log(ctx, "coordination session server expire", kv.Stringer("failure", info.Failure), ) }, @@ -261,7 +261,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "error") - l.Log(ctx, "", + l.Log(ctx, "coordination session server error", kv.Stringer("failure", info.Failure), ) }, @@ -274,11 +274,11 @@ func internalCoordination( return nil } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "receive") - l.Log(ctx, "receive") + l.Log(ctx, "starting coordination session receive") start := time.Now() return func(info trace.CoordinationSessionReceiveDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "coordination session received", kv.Latency(start), kv.Error(info.Error), kv.Stringer("response", info.Response), @@ -291,7 +291,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "receive", "unexpected") - l.Log(ctx, "", + l.Log(ctx, "coordination session received unexpected", kv.Stringer("response", info.Response), ) }, @@ -300,7 +300,7 @@ func internalCoordination( return } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop") - l.Log(ctx, "", + l.Log(ctx, "coordination session stopped", kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), ) }, @@ -313,11 +313,11 @@ func internalCoordination( return nil } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "start") - l.Log(ctx, "start") + l.Log(ctx, "starting coordination session...") start := time.Now() return func(info trace.CoordinationSessionStartDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "coordination session start done", kv.Latency(start), kv.Error(info.Error), kv.Version(), diff --git a/log/discovery.go b/log/discovery.go index 24c382687..ec52cb5dc 100644 --- a/log/discovery.go +++ b/log/discovery.go @@ -18,7 +18,7 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) { return nil } ctx := with(*info.Context, DEBUG, "ydb", "discovery", "list", "endpoints") - l.Log(ctx, "start", + l.Log(ctx, "starting discovery...", kv.String("address", info.Address), kv.String("database", info.Database), ) @@ -26,12 +26,12 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) { return func(info trace.DiscoveryDiscoverDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "discovery done", kv.Latency(start), kv.Stringer("endpoints", kv.Endpoints(info.Endpoints)), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "discovery failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -44,18 +44,18 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) { return nil } ctx := with(*info.Context, TRACE, "ydb", "discovery", "whoAmI") - l.Log(ctx, "start") + l.Log(ctx, "starting discovery whoami") start := time.Now() return func(info trace.DiscoveryWhoAmIDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "discovery whoami done", kv.Latency(start), kv.String("user", info.User), kv.Strings("groups", info.Groups), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "discovery whoami failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), diff --git a/log/driver.go b/log/driver.go index 4a52fc2b7..5f3d54200 100644 --- a/log/driver.go +++ b/log/driver.go @@ -28,19 +28,19 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(context.Background(), TRACE, "ydb", "driver", "resolver", "update") target := info.Target addresses := info.Resolved - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting resolve...", kv.String("target", target), kv.Strings("resolved", addresses), ) return func(info trace.DriverResolveDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver resolve done", kv.String("target", target), kv.Strings("resolved", addresses), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "resolve failed", kv.Error(info.Error), kv.String("target", target), kv.Strings("resolved", addresses), @@ -57,7 +57,7 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { database := info.Database secure := info.Secure ctx := with(*info.Context, DEBUG, "ydb", "driver", "resolver", "init") - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting init...", kv.String("endpoint", endpoint), kv.String("database", database), kv.Bool("secure", secure), @@ -66,14 +66,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverInitDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver init done", kv.String("endpoint", endpoint), kv.String("database", database), kv.Bool("secure", secure), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb driver init failed", kv.Error(info.Error), kv.String("endpoint", endpoint), kv.String("database", database), @@ -89,16 +89,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "resolver", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting close...") start := time.Now() return func(info trace.DriverCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver close failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -112,19 +112,19 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "dial") endpoint := info.Endpoint - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting dial...", kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnDialDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver dial done", kv.Stringer("endpoint", endpoint), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver dial failed", kv.Error(info.Error), kv.Stringer("endpoint", endpoint), kv.Latency(start), @@ -139,14 +139,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { } ctx := with(context.Background(), TRACE, "ydb", "driver", "conn", "state", "change") endpoint := info.Endpoint - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting state change...", kv.Stringer("endpoint", endpoint), kv.Stringer("state", info.State), ) start := time.Now() return func(info trace.DriverConnStateChangeDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver state change done", kv.Stringer("endpoint", endpoint), kv.Latency(start), kv.Stringer("state", info.State), @@ -159,19 +159,19 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "close") endpoint := info.Endpoint - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting connection close...", kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver connection close done", kv.Stringer("endpoint", endpoint), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver connection close failed", kv.Error(info.Error), kv.Stringer("endpoint", endpoint), kv.Latency(start), @@ -187,7 +187,7 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "invoke") endpoint := info.Endpoint method := string(info.Method) - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting connection invoke...", kv.Stringer("endpoint", endpoint), kv.String("method", method), ) @@ -195,14 +195,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverConnInvokeDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver connection invoke done", kv.Stringer("endpoint", endpoint), kv.String("method", method), kv.Latency(start), kv.Stringer("metadata", kv.Metadata(info.Metadata)), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver connection invoke failed", kv.Error(info.Error), kv.Stringer("endpoint", endpoint), kv.String("method", method), @@ -224,7 +224,7 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "stream", "New") endpoint := info.Endpoint method := string(info.Method) - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting new connection stream...", kv.Stringer("endpoint", endpoint), kv.String("method", method), ) @@ -232,13 +232,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverConnNewStreamDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver connection new stream done", kv.Stringer("endpoint", endpoint), kv.String("method", method), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver connection new stream failed", kv.Error(info.Error), kv.Stringer("endpoint", endpoint), kv.String("method", method), @@ -255,16 +255,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "stream", "CloseSend") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting send stream close...") start := time.Now() return func(info trace.DriverConnStreamCloseSendDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver connection stream closed done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver connection stream closed failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -277,16 +277,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "stream", "SendMsg") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting send stream msg...") start := time.Now() return func(info trace.DriverConnStreamSendMsgDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver send stream msg done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver send stream msg failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -299,16 +299,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "stream", "RecvMsg") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting receive stream msg...") start := time.Now() return func(info trace.DriverConnStreamRecvMsgDoneInfo) { if xerrors.HideEOF(info.Error) == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver receive stream msg done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver receive stream msg failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -323,14 +323,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "ban") endpoint := info.Endpoint cause := info.Cause - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting connection ban...", kv.Stringer("endpoint", endpoint), kv.NamedError("cause", cause), ) start := time.Now() return func(info trace.DriverConnBanDoneInfo) { - l.Log(WithLevel(ctx, WARN), "done", + l.Log(WithLevel(ctx, WARN), "ydb driver connection ban done", kv.Stringer("endpoint", endpoint), kv.Latency(start), kv.Stringer("state", info.State), @@ -345,13 +345,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { } ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "allow") endpoint := info.Endpoint - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting connection allow...", kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnAllowDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver connection allow done", kv.Stringer("endpoint", endpoint), kv.Latency(start), kv.Stringer("state", info.State), @@ -365,7 +365,7 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "repeater", "wake", "up") name := info.Name event := info.Event - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting repeater wakeup...", kv.String("name", name), kv.String("event", event), ) @@ -373,13 +373,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverRepeaterWakeUpDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver repeater wakeup done", kv.String("name", name), kv.String("event", event), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb driver repeater wakeup failed", kv.Error(info.Error), kv.String("name", name), kv.String("event", event), @@ -394,11 +394,11 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "balancer", "init") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting balancer init...") start := time.Now() return func(info trace.DriverBalancerInitDoneInfo) { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "ydb driver balancer init done", kv.Latency(start), ) } @@ -408,16 +408,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "balancer", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting balancer close...") start := time.Now() return func(info trace.DriverBalancerCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver balancer close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb driver balancer close failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -434,17 +434,17 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "balancer", "choose", "endpoint") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting balancer choose endpoint...") start := time.Now() return func(info trace.DriverBalancerChooseEndpointDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver balancer choose endpoint done", kv.Latency(start), kv.Stringer("endpoint", info.Endpoint), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb driver balancer choose endpoint failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -461,14 +461,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "balancer", "update") - l.Log(ctx, "start", + l.Log(ctx, "ydb driver starting balancer update...", kv.Bool("needLocalDC", info.NeedLocalDC), kv.String("database", info.Database), ) start := time.Now() return func(info trace.DriverBalancerUpdateDoneInfo) { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver balancer update done", kv.Latency(start), kv.Stringer("endpoints", kv.Endpoints(info.Endpoints)), kv.Stringer("added", kv.Endpoints(info.Added)), @@ -482,17 +482,17 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return nil } ctx := with(*info.Context, TRACE, "ydb", "driver", "credentials", "get") - l.Log(ctx, "start") + l.Log(ctx, "ydb driver starting get credentials...") start := time.Now() return func(info trace.DriverGetCredentialsDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb driver get credentials done", kv.Latency(start), kv.String("token", info.Token), ) } else { - l.Log(WithLevel(ctx, ERROR), "done", + l.Log(WithLevel(ctx, ERROR), "ydb driver get credentials failed", kv.Error(info.Error), kv.Latency(start), kv.String("token", info.Token), diff --git a/log/query.go b/log/query.go index 1a3c4e296..2a4e120fc 100644 --- a/log/query.go +++ b/log/query.go @@ -24,11 +24,11 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "new") - l.Log(ctx, "start") + l.Log(ctx, "ydb starting create new query client") start := time.Now() return func(info trace.QueryNewDoneInfo) { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "ydb create query client done", kv.Latency(start), ) } @@ -38,12 +38,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb query client starting close...") start := time.Now() return func(info trace.QueryCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query close done", kv.Latency(start), ) } else { @@ -51,7 +51,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query close failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -64,11 +64,11 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "new") - l.Log(ctx, "start") + l.Log(ctx, "ydb query service starting create pool...") start := time.Now() return func(info trace.QueryPoolNewDoneInfo) { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "ydb query service create pool done", kv.Latency(start), kv.Int("Limit", info.Limit), ) @@ -79,12 +79,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb query service starting close pool...") start := time.Now() return func(info trace.QueryPoolCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query service close done", kv.Latency(start), ) } else { @@ -92,7 +92,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query service close failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -105,12 +105,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "try") - l.Log(ctx, "start") + l.Log(ctx, "ydb query service starting pool try attempt...") start := time.Now() return func(info trace.QueryPoolTryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query service pool try done", kv.Latency(start), ) } else { @@ -118,7 +118,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query service pool try failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -131,12 +131,12 @@ func internalQuery( return nil } ctx := with(*info.Context, DEBUG, "ydb", "query", "pool", "with") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query pool with...") start := time.Now() return func(info trace.QueryPoolWithDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query pool with done", kv.Latency(start), kv.Int("Attempts", info.Attempts), ) @@ -145,7 +145,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query pool with failed", kv.Latency(start), kv.Error(info.Error), kv.Int("Attempts", info.Attempts), @@ -159,12 +159,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "put") - l.Log(ctx, "start") + l.Log(ctx, "starting ydb query pool put...") start := time.Now() return func(info trace.QueryPoolPutDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query pool put done", kv.Latency(start), ) } else { @@ -172,7 +172,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query pool put failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -185,12 +185,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "pool", "get") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query pool get...") start := time.Now() return func(info trace.QueryPoolGetDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query pool get done", kv.Latency(start), ) } else { @@ -198,7 +198,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query pool get failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -211,12 +211,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "do") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query do...") start := time.Now() return func(info trace.QueryDoDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query do done", kv.Latency(start), kv.Int("attempts", info.Attempts), ) @@ -225,7 +225,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query do failed", kv.Latency(start), kv.Error(info.Error), kv.Int("attempts", info.Attempts), @@ -239,12 +239,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "do", "tx") - l.Log(ctx, "start") + l.Log(ctx, "starting ydb query doTx...") start := time.Now() return func(info trace.QueryDoTxDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query doTx done", kv.Latency(start), kv.Int("attempts", info.Attempts), ) @@ -253,7 +253,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query doTx failed", kv.Latency(start), kv.Error(info.Error), kv.Int("attempts", info.Attempts), @@ -267,12 +267,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "exec") - l.Log(ctx, "start") + l.Log(ctx, "starting ydb query exec...") start := time.Now() return func(info trace.QueryExecDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query exec done", kv.Latency(start), ) } else { @@ -280,7 +280,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query exec failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -293,12 +293,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "query") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query query...") start := time.Now() return func(info trace.QueryQueryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query done", kv.Latency(start), ) } else { @@ -306,7 +306,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -319,12 +319,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "query", "row") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query row done...") start := time.Now() return func(info trace.QueryQueryRowDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query row done", kv.Latency(start), ) } else { @@ -332,7 +332,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query row failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -345,12 +345,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "query", "result", "set") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query result set...") start := time.Now() return func(info trace.QueryQueryResultSetDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query result set done", kv.Latency(start), ) } else { @@ -358,7 +358,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query result set failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -371,12 +371,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "create") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query session create...") start := time.Now() return func(info trace.QuerySessionCreateDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query session create done", kv.Latency(start), kv.String("session_id", info.Session.ID()), kv.String("session_status", info.Session.Status()), @@ -386,7 +386,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "done", + l.Log(WithLevel(ctx, lvl), "ydb query session create failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -399,7 +399,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "attach") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query session attach...", kv.String("session_id", info.Session.ID()), kv.String("session_status", info.Session.Status()), ) @@ -407,7 +407,7 @@ func internalQuery( return func(info trace.QuerySessionAttachDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query session attach done", kv.Latency(start), ) } else { @@ -415,7 +415,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query session attach failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -428,7 +428,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "delete") - l.Log(ctx, "start", + l.Log(ctx, "starting ydb query session delete...", kv.String("session_id", info.Session.ID()), kv.String("session_status", info.Session.Status()), ) @@ -436,7 +436,7 @@ func internalQuery( return func(info trace.QuerySessionDeleteDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query session delete done", kv.Latency(start), ) } else { @@ -444,7 +444,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query session delete failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -457,7 +457,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "exec") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query session exec...", kv.String("SessionID", info.Session.ID()), kv.String("SessionStatus", info.Session.Status()), kv.String("Query", info.Query), @@ -466,7 +466,7 @@ func internalQuery( return func(info trace.QuerySessionExecDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query session exec done", kv.Latency(start), ) } else { @@ -474,7 +474,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query session exec failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -487,7 +487,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "query") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query session query...", kv.String("SessionID", info.Session.ID()), kv.String("SessionStatus", info.Session.Status()), kv.String("Query", info.Query), @@ -496,7 +496,7 @@ func internalQuery( return func(info trace.QuerySessionQueryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query session query done", kv.Latency(start), ) } else { @@ -504,7 +504,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query session query failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -517,7 +517,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "begin") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query session begin...", kv.String("SessionID", info.Session.ID()), kv.String("SessionStatus", info.Session.Status()), ) @@ -525,7 +525,7 @@ func internalQuery( return func(info trace.QuerySessionBeginDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "done", + l.Log(WithLevel(ctx, DEBUG), "ydb query session begin done", kv.Latency(start), kv.String("TransactionID", info.Tx.ID()), ) @@ -534,7 +534,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query session begin failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -547,7 +547,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "exec") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query transaction exec...", kv.String("SessionID", info.Session.ID()), kv.String("TransactionID", info.Tx.ID()), kv.String("SessionStatus", info.Session.Status()), @@ -556,7 +556,7 @@ func internalQuery( return func(info trace.QueryTxExecDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "done", + l.Log(WithLevel(ctx, DEBUG), "ydb query transaction exec done", kv.Latency(start), ) } else { @@ -564,7 +564,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query transaction exec failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -577,7 +577,7 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "query") - l.Log(ctx, "start", + l.Log(ctx, "staring ydb query transaction query...", kv.String("SessionID", info.Session.ID()), kv.String("TransactionID", info.Tx.ID()), kv.String("SessionStatus", info.Session.Status()), @@ -586,7 +586,7 @@ func internalQuery( return func(info trace.QueryTxQueryDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "done", + l.Log(WithLevel(ctx, DEBUG), "ydb query transaction query done", kv.Latency(start), ) } else { @@ -594,7 +594,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query transaction query failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -607,12 +607,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "result", "new") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query result new...") start := time.Now() return func(info trace.QueryResultNewDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query result new done", kv.Latency(start), ) } else { @@ -620,7 +620,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query result new failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -633,12 +633,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "result", "next", "part") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query result next part...") start := time.Now() return func(info trace.QueryResultNextPartDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query result next part done", kv.Stringer("stats", info.Stats), kv.Latency(start), ) @@ -647,7 +647,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query result next part failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -664,12 +664,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "result", "next", "result", "set") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query result next set...") start := time.Now() return func(info trace.QueryResultNextResultSetDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query result next set done", kv.Latency(start), ) } else { @@ -677,7 +677,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query result next set failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -690,12 +690,12 @@ func internalQuery( return nil } ctx := with(*info.Context, TRACE, "ydb", "query", "result", "close") - l.Log(ctx, "start") + l.Log(ctx, "staring ydb query result close...") start := time.Now() return func(info trace.QueryResultCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb query result close done", kv.Latency(start), ) } else { @@ -703,7 +703,7 @@ func internalQuery( if !xerrors.IsYdb(info.Error) { lvl = DEBUG } - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb query result close failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), diff --git a/log/retry.go b/log/retry.go index 76bd713ed..24421995e 100644 --- a/log/retry.go +++ b/log/retry.go @@ -19,7 +19,7 @@ func internalRetry(l Logger, d trace.Detailer) (t trace.Retry) { if d.Details()&trace.RetryEvents == 0 { return nil } - ctx := with(*info.Context, TRACE, "ydb", "retry") + ctx := with(*info.Context, TRACE, "ydb retrier starting work...", "retry") label := info.Label idempotent := info.Idempotent l.Log(ctx, "start", @@ -30,7 +30,7 @@ func internalRetry(l Logger, d trace.Detailer) (t trace.Retry) { return func(info trace.RetryLoopDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb retries completed successfully", kv.String("label", label), kv.Latency(start), kv.Int("attempts", info.Attempts), @@ -41,7 +41,7 @@ func internalRetry(l Logger, d trace.Detailer) (t trace.Retry) { lvl = DEBUG } m := retry.Check(info.Error) - l.Log(WithLevel(ctx, lvl), "failed", + l.Log(WithLevel(ctx, lvl), "ydb retries failed", kv.Error(info.Error), kv.String("label", label), kv.Latency(start), diff --git a/log/scripting.go b/log/scripting.go index 10611c2dd..6dd0ffc1b 100644 --- a/log/scripting.go +++ b/log/scripting.go @@ -19,18 +19,18 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return nil } ctx := with(*info.Context, TRACE, "ydb", "scripting", "execute") - l.Log(ctx, "start") + l.Log(ctx, "ydb starting script executing...") start := time.Now() return func(info trace.ScriptingExecuteDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb start script done", kv.Latency(start), kv.Int("resultSetCount", info.Result.ResultSetCount()), kv.NamedError("resultSetError", info.Result.Err()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb start script failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -43,17 +43,17 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return nil } ctx := with(*info.Context, TRACE, "ydb", "scripting", "explain") - l.Log(ctx, "start") + l.Log(ctx, "ydb starting script explain...") start := time.Now() return func(info trace.ScriptingExplainDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb script explain done", kv.Latency(start), kv.String("plan", info.Plan), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb script explain failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -73,7 +73,7 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { } ctx := with(*info.Context, TRACE, "ydb", "scripting", "stream", "execute") query := info.Query - l.Log(ctx, "start", + l.Log(ctx, "ydb script stream execute starting...", appendFieldByCondition(l.logQuery, kv.String("query", query), )..., @@ -86,9 +86,9 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { trace.ScriptingStreamExecuteDoneInfo, ) { if info.Error == nil { - l.Log(ctx, "intermediate") + l.Log(ctx, "ydb script stream execute intermediate success") } else { - l.Log(WithLevel(ctx, WARN), "intermediate failed", + l.Log(WithLevel(ctx, WARN), "ydb script stream execute intermediate failed", kv.Error(info.Error), kv.Version(), ) @@ -96,14 +96,14 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return func(info trace.ScriptingStreamExecuteDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb script stream execute done", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Latency(start), )..., ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb script stream execute failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Error(info.Error), @@ -120,16 +120,16 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return nil } ctx := with(*info.Context, TRACE, "ydb", "scripting", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb script close starting...") start := time.Now() return func(info trace.ScriptingCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb script close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb script close failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), diff --git a/log/sql.go b/log/sql.go index 6d13a8ea9..86b486e0d 100644 --- a/log/sql.go +++ b/log/sql.go @@ -25,18 +25,18 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "connector", "connect") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql database connect starting...") start := time.Now() return func(info trace.DatabaseSQLConnectorConnectDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "connected", + l.Log(WithLevel(ctx, DEBUG), "ydb sql database connect done", kv.Latency(start), kv.String("session_id", info.Session.ID()), kv.String("session_status", info.Session.Status()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql database connect failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -50,16 +50,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "ping") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql database ping starting...") start := time.Now() return func(info trace.DatabaseSQLConnPingDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql database ping done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql database ping failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -72,16 +72,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(context.Background(), TRACE, "ydb", "database", "sql", "conn", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql connection close starting...") start := time.Now() return func(info trace.DatabaseSQLConnCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql connection close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb sql connection close failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -94,16 +94,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "begin", "tx") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql transaction begin starting...") start := time.Now() return func(info trace.DatabaseSQLConnBeginDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql transaction begin done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql transaction begin failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -116,7 +116,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "prepare", "stmt") - l.Log(ctx, "start", + l.Log(ctx, "ydb sql prepare starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), )..., @@ -126,11 +126,11 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnPrepareDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql prepare done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql prepare failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Error(info.Error), @@ -146,7 +146,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "exec") - l.Log(ctx, "start", + l.Log(ctx, "ydb sql exec starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), )..., @@ -157,12 +157,12 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnExecDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql exec done", kv.Latency(start), ) } else { m := retry.Check(info.Error) - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql exec failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Bool("retryable", m.MustRetry(idempotent)), @@ -181,7 +181,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "query") - l.Log(ctx, "start", + l.Log(ctx, "ydb sql query starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), )..., @@ -192,12 +192,12 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnQueryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql query done", kv.Latency(start), ) } else { m := retry.Check(info.Error) - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql query failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Bool("retryable", m.MustRetry(idempotent)), @@ -216,16 +216,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "tx", "commit") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql tx commit starting") start := time.Now() return func(info trace.DatabaseSQLTxCommitDoneInfo) { if info.Error == nil { - l.Log(ctx, "committed", + l.Log(ctx, "ydb sql tx commit done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql tx commit failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -238,16 +238,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "tx", "rollback") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql tx rollback starting...") start := time.Now() return func(info trace.DatabaseSQLTxRollbackDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql tx rollback done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb sql tx rollback failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -260,16 +260,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(context.Background(), TRACE, "ydb", "database", "sql", "stmt", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb sql statement close starting...") start := time.Now() return func(info trace.DatabaseSQLStmtCloseDoneInfo) { if info.Error == nil { - l.Log(ctx, "closed", + l.Log(ctx, "ydb sql statement close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "close failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql statement close failed", kv.Error(info.Error), kv.Latency(start), kv.Version(), @@ -282,7 +282,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "stmt", "exec") - l.Log(ctx, "start", + l.Log(ctx, "ydb sql statement exec starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), )..., @@ -292,12 +292,12 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLStmtExecDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql statement exec done", kv.Error(info.Error), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql statement exec failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Error(info.Error), @@ -313,7 +313,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return nil } ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "stmt", "query") - l.Log(ctx, "start", + l.Log(ctx, "ydb sql statement query starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), )..., @@ -323,11 +323,11 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLStmtQueryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb sql statement query done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb sql statement query failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Error(info.Error), diff --git a/log/table.go b/log/table.go index d84e09451..475b0f5b6 100644 --- a/log/table.go +++ b/log/table.go @@ -23,11 +23,11 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return nil } ctx := with(*info.Context, TRACE, "ydb", "table", "init") - l.Log(ctx, "start") + l.Log(ctx, "ydb table init starting...") start := time.Now() return func(info trace.TableInitDoneInfo) { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "ydb table init done", kv.Latency(start), kv.Int("size_max", info.Limit), ) @@ -38,16 +38,16 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return nil } ctx := with(*info.Context, TRACE, "ydb", "table", "close") - l.Log(ctx, "start") + l.Log(ctx, "ydb table close starting...") start := time.Now() return func(info trace.TableCloseDoneInfo) { if info.Error == nil { - l.Log(WithLevel(ctx, INFO), "done", + l.Log(WithLevel(ctx, INFO), "ydb table close done", kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table close failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -66,7 +66,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "do") idempotent := info.Idempotent label := info.Label - l.Log(ctx, "start", + l.Log(ctx, "ydb table do starting...", kv.Bool("idempotent", idempotent), kv.String("label", label), ) @@ -74,7 +74,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableDoDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table do done", kv.Latency(start), kv.Bool("idempotent", idempotent), kv.String("label", label), @@ -86,7 +86,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { lvl = DEBUG } m := retry.Check(info.Error) - l.Log(WithLevel(ctx, lvl), "done", + l.Log(WithLevel(ctx, lvl), "ydb table do failed", kv.Latency(start), kv.Bool("idempotent", idempotent), kv.String("label", label), @@ -111,7 +111,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "do", "tx") idempotent := info.Idempotent label := info.Label - l.Log(ctx, "start", + l.Log(ctx, "ydb table dotx starting...", kv.Bool("idempotent", idempotent), kv.String("label", label), ) @@ -119,7 +119,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableDoTxDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table dotx done", kv.Latency(start), kv.Bool("idempotent", idempotent), kv.String("label", label), @@ -131,7 +131,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { lvl = DEBUG } m := retry.Check(info.Error) - l.Log(WithLevel(ctx, lvl), "done", + l.Log(WithLevel(ctx, lvl), "ydb table dotx failed", kv.Latency(start), kv.Bool("idempotent", idempotent), kv.String("label", label), @@ -154,19 +154,19 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return nil } ctx := with(*info.Context, TRACE, "ydb", "table", "create", "session") - l.Log(ctx, "start") + l.Log(ctx, "ydb table create session starting...") start := time.Now() return func(info trace.TableCreateSessionDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table create session done", kv.Latency(start), kv.Int("attempts", info.Attempts), kv.String("session_id", info.Session.ID()), kv.String("session_status", info.Session.Status()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table create session failed", kv.Latency(start), kv.Int("attempts", info.Attempts), kv.Error(info.Error), @@ -180,24 +180,24 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return nil } ctx := with(*info.Context, TRACE, "ydb", "table", "session", "new") - l.Log(ctx, "start") + l.Log(ctx, "ydb table new session starting") start := time.Now() return func(info trace.TableSessionNewDoneInfo) { if info.Error == nil { if info.Session != nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table new session done", kv.Latency(start), kv.String("id", info.Session.ID()), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb table new session failed without error", kv.Latency(start), kv.Version(), ) } } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb table new session failed", kv.Latency(start), kv.Error(info.Error), kv.Version(), @@ -211,7 +211,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(*info.Context, TRACE, "ydb", "table", "session", "delete") session := info.Session - l.Log(ctx, "start", + l.Log(ctx, "ydb table session delete starting...", kv.String("id", info.Session.ID()), kv.String("status", info.Session.Status()), ) @@ -219,13 +219,13 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableSessionDeleteDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table session delete done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb table session delete failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -241,7 +241,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(*info.Context, TRACE, "ydb", "table", "session", "keep", "alive") session := info.Session - l.Log(ctx, "start", + l.Log(ctx, "ydb table session keepalive starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), ) @@ -249,13 +249,13 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableKeepAliveDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table session keepalive done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb table session keepalive failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -276,7 +276,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "query", "prepare") session := info.Session query := info.Query - l.Log(ctx, "start", + l.Log(ctx, "ydb table session query prepare starting...", appendFieldByCondition(l.logQuery, kv.String("query", info.Query), kv.String("id", session.ID()), @@ -287,7 +287,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TablePrepareDataQueryDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table session query prepare done", appendFieldByCondition(l.logQuery, kv.Stringer("result", info.Result), appendFieldByCondition(l.logQuery, @@ -299,7 +299,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { )..., ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table session query prepare failed", appendFieldByCondition(l.logQuery, kv.String("query", query), kv.Error(info.Error), @@ -323,7 +323,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "query", "execute") session := info.Session query := info.Query - l.Log(ctx, "start", + l.Log(ctx, "ydb table session query execute starting...", appendFieldByCondition(l.logQuery, kv.Stringer("query", info.Query), kv.String("id", session.ID()), @@ -335,7 +335,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableExecuteDataQueryDoneInfo) { if info.Error == nil { tx := info.Tx - l.Log(ctx, "done", + l.Log(ctx, "ydb table session query execute done", appendFieldByCondition(l.logQuery, kv.Stringer("query", query), kv.String("id", session.ID()), @@ -347,7 +347,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { )..., ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table session query execute failed", appendFieldByCondition(l.logQuery, kv.Stringer("query", query), kv.Error(info.Error), @@ -372,7 +372,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "query", "stream", "execute") session := info.Session query := info.Query - l.Log(ctx, "start", + l.Log(ctx, "ydb table session query stream execute starting...", appendFieldByCondition(l.logQuery, kv.Stringer("query", info.Query), kv.String("id", session.ID()), @@ -383,7 +383,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableSessionQueryStreamExecuteDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table session query stream execute done", appendFieldByCondition(l.logQuery, kv.Stringer("query", query), kv.Error(info.Error), @@ -393,7 +393,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { )..., ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table session query stream execute failed", appendFieldByCondition(l.logQuery, kv.Stringer("query", query), kv.Error(info.Error), @@ -416,7 +416,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(*info.Context, TRACE, "ydb", "table", "session", "query", "stream", "read") session := info.Session - l.Log(ctx, "start", + l.Log(ctx, "ydb table session query stream read starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), ) @@ -424,13 +424,13 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableSessionQueryStreamReadDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table session query stream read done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table session query stream read failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -450,7 +450,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(*info.Context, TRACE, "ydb", "table", "session", "tx", "begin") session := info.Session - l.Log(ctx, "start", + l.Log(ctx, "ydb table tx begin starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), ) @@ -458,14 +458,14 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableTxBeginDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table tx begin done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), kv.String("tx", info.Tx.ID()), ) } else { - l.Log(WithLevel(ctx, WARN), "failed", + l.Log(WithLevel(ctx, WARN), "ydb table tx begin failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -482,7 +482,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "tx", "commit") session := info.Session tx := info.Tx - l.Log(ctx, "start", + l.Log(ctx, "ydb table tx commit starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), kv.String("tx", info.Tx.ID()), @@ -491,14 +491,14 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableTxCommitDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table tx commit done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), kv.String("tx", tx.ID()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table tx commit failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -520,7 +520,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "tx", "rollback") session := info.Session tx := info.Tx - l.Log(ctx, "start", + l.Log(ctx, "ydb table tx rollback starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), kv.String("tx", tx.ID()), @@ -529,14 +529,14 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableTxRollbackDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table tx rollback done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), kv.String("tx", tx.ID()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table tx rollback failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -553,7 +553,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(*info.Context, TRACE, "ydb", "table", "pool", "put") session := info.Session - l.Log(ctx, "start", + l.Log(ctx, "ydb table pool put starting...", kv.String("id", session.ID()), kv.String("status", session.Status()), ) @@ -561,13 +561,13 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TablePoolPutDoneInfo) { if info.Error == nil { - l.Log(ctx, "done", + l.Log(ctx, "ydb table pool put done", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), ) } else { - l.Log(WithLevel(ctx, ERROR), "failed", + l.Log(WithLevel(ctx, ERROR), "ydb table pool put failed", kv.Latency(start), kv.String("id", session.ID()), kv.String("status", session.Status()), @@ -582,7 +582,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return nil } ctx := with(*info.Context, TRACE, "ydb", "table", "pool", "get") - l.Log(ctx, "start") + l.Log(ctx, "ydb table pool get starting...") start := time.Now() return func(info trace.TablePoolGetDoneInfo) { @@ -609,7 +609,7 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return } ctx := with(context.Background(), TRACE, "ydb", "table", "pool", "state", "change") - l.Log(WithLevel(ctx, DEBUG), "", + l.Log(WithLevel(ctx, DEBUG), "ydb table session pool state changed", kv.Int("limit", info.Limit), kv.Int("index", info.Index), kv.Int("idle", info.Idle), diff --git a/log/topic.go b/log/topic.go index 99392233d..c142a520f 100644 --- a/log/topic.go +++ b/log/topic.go @@ -27,10 +27,10 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "reconnect") start := time.Now() - l.Log(ctx, "start") + l.Log(ctx, "ydb topic reader reconnect starting...") return func(doneInfo trace.TopicReaderReconnectDoneInfo) { - l.Log(WithLevel(ctx, INFO), "reconnected", + l.Log(WithLevel(ctx, INFO), "ydb topic reader reconnect done", kv.NamedError("reason", info.Reason), kv.Latency(start), ) @@ -41,7 +41,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "reconnect", "request") - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader reconnect request", kv.NamedError("reason", info.Reason), kv.Bool("was_sent", info.WasSent), ) @@ -54,7 +54,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "partition", "read", "start", "response") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader start partition read response starting...", kv.String("topic", info.Topic), kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int64("partition_id", info.PartitionID), @@ -80,9 +80,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) } if doneInfo.Error == nil { - l.Log(WithLevel(ctx, INFO), "read partition response completed", fields...) + l.Log(WithLevel(ctx, INFO), "ydb topic reader start partition read response done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "read partition response completed", + l.Log(WithLevel(ctx, WARN), "ydb topic reader start partition read response failed", append(fields, kv.Error(doneInfo.Error), kv.Version(), @@ -99,7 +99,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "partition", "read", "stop", "response") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader stop partition read response starting...", kv.String("reader_connection_id", info.ReaderConnectionID), kv.String("topic", info.Topic), kv.Int64("partition_id", info.PartitionID), @@ -118,9 +118,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), } if doneInfo.Error == nil { - l.Log(WithLevel(ctx, INFO), "reader partition stopped", fields...) + l.Log(WithLevel(ctx, INFO), "ydb topic reader stop partition read response done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "reader partition stopped", + l.Log(WithLevel(ctx, WARN), "ydb topic reader stop partition read response failed", append(fields, kv.Error(doneInfo.Error), kv.Version(), @@ -135,7 +135,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(*info.RequestContext, TRACE, "ydb", "topic", "reader", "commit") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader commit starting...", kv.String("topic", info.Topic), kv.Int64("partition_id", info.PartitionID), kv.Int64("partition_session_id", info.PartitionSessionID), @@ -153,9 +153,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), } if doneInfo.Error == nil { - l.Log(ctx, "committed", fields...) + l.Log(ctx, "ydb topic reader commit done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "committed", + l.Log(WithLevel(ctx, WARN), "ydb topic reader commit failed", append(fields, kv.Error(doneInfo.Error), kv.Version(), @@ -175,7 +175,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { commitInfo := info.CommitsInfo.GetCommitsInfo() for i := range commitInfo { - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader send commit message starting...", kv.String("topic", commitInfo[i].Topic), kv.Int64("partitions_id", commitInfo[i].PartitionID), kv.Int64("partitions_session_id", commitInfo[i].PartitionSessionID), @@ -195,9 +195,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), } if doneInfo.Error == nil { - l.Log(ctx, "done", fields...) + l.Log(ctx, "ydb topic reader send commit message done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "commit message sent", + l.Log(WithLevel(ctx, WARN), "ydb topic reader send commit message failed", append(fields, kv.Error(doneInfo.Error), kv.Version(), @@ -212,7 +212,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "committed", "notify") - l.Log(ctx, "ack", + l.Log(ctx, "ydb topic reader received commit ack", kv.String("reader_connection_id", info.ReaderConnectionID), kv.String("topic", info.Topic), kv.Int64("partition_id", info.PartitionID), @@ -226,7 +226,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "close") start := time.Now() - l.Log(ctx, "done", + l.Log(ctx, "ydb topic reader close starting...", kv.String("reader_connection_id", info.ReaderConnectionID), kv.NamedError("close_reason", info.CloseReason), ) @@ -237,9 +237,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), } if doneInfo.CloseError == nil { - l.Log(ctx, "closed", fields...) + l.Log(ctx, "ydb topic reader close done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "closed", + l.Log(WithLevel(ctx, WARN), "ydb topic reader close failed", append(fields, kv.Error(doneInfo.CloseError), kv.Version(), @@ -255,7 +255,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "init") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic reader init starting...", kv.String("pre_init_reader_connection_id", info.PreInitReaderConnectionID), kv.String("consumer", info.InitRequestInfo.GetConsumer()), kv.Strings("topics", info.InitRequestInfo.GetTopics()), @@ -269,9 +269,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), } if doneInfo.Error == nil { - l.Log(ctx, "topic reader stream initialized", fields...) + l.Log(ctx, "ydb topic reader init done", fields...) } else { - l.Log(WithLevel(ctx, WARN), "topic reader stream initialized", + l.Log(WithLevel(ctx, WARN), "ydb topic reader init failed", append(fields, kv.Error(doneInfo.Error), kv.Version(), @@ -285,7 +285,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "error") - l.Log(WithLevel(ctx, INFO), "stream error", + l.Log(WithLevel(ctx, INFO), "ydb topic reader has grpc stream error", kv.Error(info.Error), kv.String("reader_connection_id", info.ReaderConnectionID), kv.Version(), @@ -301,7 +301,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "update", "token") start := time.Now() - l.Log(ctx, "token updating...", + l.Log(ctx, "ydb topic reader token update starting...", kv.String("reader_connection_id", info.ReaderConnectionID), ) @@ -309,13 +309,13 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { updateTokenInfo trace.OnReadUpdateTokenMiddleTokenReceivedInfo, ) func(doneInfo trace.OnReadStreamUpdateTokenDoneInfo) { if updateTokenInfo.Error == nil { - l.Log(ctx, "got token", + l.Log(ctx, "ydb topic reader token update: got token done", kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("token_len", updateTokenInfo.TokenLen), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "got token", + l.Log(WithLevel(ctx, WARN), "ydb topic reader token update: got token failed", kv.Error(updateTokenInfo.Error), kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("token_len", updateTokenInfo.TokenLen), @@ -326,13 +326,13 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.OnReadStreamUpdateTokenDoneInfo) { if doneInfo.Error == nil { - l.Log(ctx, "token updated on stream", + l.Log(ctx, "ydb topic reader token update done", kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("token_len", updateTokenInfo.TokenLen), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "token updated on stream", + l.Log(WithLevel(ctx, WARN), "ydb topic reader token update failed", kv.Error(doneInfo.Error), kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("token_len", updateTokenInfo.TokenLen), @@ -348,7 +348,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "sent", "data", "request") - l.Log(ctx, "sent data request", + l.Log(ctx, "ydb topic reader sent data request", kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("request_bytes", info.RequestBytes), kv.Int("local_capacity", info.LocalBufferSizeAfterSent), @@ -363,7 +363,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "receive", "data", "response") start := time.Now() partitionsCount, batchesCount, messagesCount := info.DataResponse.GetPartitionBatchMessagesCounts() - l.Log(ctx, "data response received, process starting...", + l.Log(ctx, "ydb topic reader data response received, process starting...", kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("received_bytes", info.DataResponse.GetBytesSize()), kv.Int("local_capacity", info.LocalBufferSizeAfterReceive), @@ -374,7 +374,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderReceiveDataResponseDoneInfo) { if doneInfo.Error == nil { - l.Log(ctx, "data response received and processed", + l.Log(ctx, "ydb topic reader data response received and process done", kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("received_bytes", info.DataResponse.GetBytesSize()), kv.Int("local_capacity", info.LocalBufferSizeAfterReceive), @@ -384,7 +384,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "data response received and processed", + l.Log(WithLevel(ctx, WARN), "ydb topic reader data response received and process failed", kv.Error(doneInfo.Error), kv.String("reader_connection_id", info.ReaderConnectionID), kv.Int("received_bytes", info.DataResponse.GetBytesSize()), @@ -406,7 +406,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(*info.RequestContext, TRACE, "ydb", "topic", "reader", "read", "messages") start := time.Now() - l.Log(ctx, "read messages called, waiting...", + l.Log(ctx, "ydb topic read messages, waiting...", kv.Int("min_count", info.MinCount), kv.Int("max_count", info.MaxCount), kv.Int("local_capacity_before", info.FreeBufferCapacity), @@ -414,14 +414,14 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderReadMessagesDoneInfo) { if doneInfo.Error == nil { - l.Log(ctx, "read messages returned", + l.Log(ctx, "ydb topic read messages done", kv.Int("min_count", info.MinCount), kv.Int("max_count", info.MaxCount), kv.Int("local_capacity_before", info.FreeBufferCapacity), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "read messages returned", + l.Log(WithLevel(ctx, WARN), "ydb topic read messages failed", kv.Error(doneInfo.Error), kv.Int("min_count", info.MinCount), kv.Int("max_count", info.MaxCount), @@ -437,7 +437,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "unknown", "grpc", "message") - l.Log(WithLevel(ctx, INFO), "received unknown message", + l.Log(WithLevel(ctx, INFO), "ydb topic reader received unknown grpc message", kv.Error(info.Error), kv.String("reader_connection_id", info.ReaderConnectionID), ) @@ -452,7 +452,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "customer", "popbatchtx") - l.Log(WithLevel(ctx, TRACE), "starting pop batch tx", + l.Log(WithLevel(ctx, TRACE), "ydb topic reader pop batch tx starting...", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -461,7 +461,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderPopBatchTxDoneInfo) { if doneInfo.Error == nil { l.Log( - WithLevel(ctx, DEBUG), "pop batch done", + WithLevel(ctx, DEBUG), "ydb topic reader pop batch tx done", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -473,7 +473,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) } else { l.Log( - WithLevel(ctx, WARN), "pop batch failed", + WithLevel(ctx, WARN), "ydb topic reader pop batch tx failed", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -496,7 +496,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "popbatchtx_on_stream") - l.Log(WithLevel(ctx, TRACE), "starting pop batch tx", + l.Log(WithLevel(ctx, TRACE), "ydb topic reader pop batch tx on stream level starting...", kv.Int64("reader_id", startInfo.ReaderID), kv.String("reader_connection_id", startInfo.ReaderConnectionID), kv.String("transaction_session_id", startInfo.TransactionSessionID), @@ -507,7 +507,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderStreamPopBatchTxDoneInfo) { if doneInfo.Error == nil { l.Log( - WithLevel(ctx, DEBUG), "pop batch on stream done", + WithLevel(ctx, DEBUG), "ydb topic reader pop batch tx on stream level done", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -516,7 +516,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) } else { l.Log( - WithLevel(ctx, WARN), "pop batch on stream failed", + WithLevel(ctx, WARN), "ydb topic reader pop batch tx on stream level failed", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -539,7 +539,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") - l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", + l.Log(WithLevel(ctx, TRACE), "update offsets in transaction starting...", kv.Int64("reader_id", startInfo.ReaderID), kv.String("reader_connection_id", startInfo.ReaderConnectionID), kv.String("transaction_session_id", startInfo.TransactionSessionID), @@ -550,7 +550,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderOnUpdateOffsetsInTransactionDoneInfo) { if doneInfo.Error == nil { l.Log( - WithLevel(ctx, DEBUG), "pop batch on stream done", + WithLevel(ctx, DEBUG), "update offsets in transaction starting done", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -559,7 +559,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) } else { l.Log( - WithLevel(ctx, WARN), "pop batch on stream failed", + WithLevel(ctx, WARN), "update offsets in transaction starting failed", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -582,7 +582,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") - l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", + l.Log(WithLevel(ctx, TRACE), "ydb topic reader rollback transaction starting...", kv.Int64("reader_id", startInfo.ReaderID), kv.String("reader_connection_id", startInfo.ReaderConnectionID), kv.String("transaction_session_id", startInfo.TransactionSessionID), @@ -593,7 +593,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderTransactionRollbackDoneInfo) { if doneInfo.RollbackError == nil { l.Log( - WithLevel(ctx, DEBUG), "pop batch on stream done", + WithLevel(ctx, DEBUG), "ydb topic reader rollback transaction done", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -602,7 +602,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) } else { l.Log( - WithLevel(ctx, WARN), "pop batch on stream failed", + WithLevel(ctx, WARN), "ydb topic reader rollback transaction failed", kv.Int64("reader_id", startInfo.ReaderID), kv.String("transaction_session_id", startInfo.TransactionSessionID), kv.String("transaction_id", startInfo.Tx.ID()), @@ -628,7 +628,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderTransactionCompletedDoneInfo) { ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") - l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", + l.Log(WithLevel(ctx, TRACE), "ydb topic reader transaction completed", kv.Int64("reader_id", startInfo.ReaderID), kv.String("reader_connection_id", startInfo.ReaderConnectionID), kv.String("transaction_session_id", startInfo.TransactionSessionID), @@ -696,7 +696,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "stream", "init") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic writer init stream starting...", kv.String("topic", info.Topic), kv.String("producer_id", info.ProducerID), kv.String("writer_instance_id", info.WriterInstanceID), @@ -704,7 +704,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicWriterInitStreamDoneInfo) { if doneInfo.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "init stream completed", + l.Log(WithLevel(ctx, DEBUG), "ydb topic writer init stream done", kv.Error(doneInfo.Error), kv.String("topic", info.Topic), kv.String("producer_id", info.ProducerID), @@ -713,7 +713,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.String("session_id", doneInfo.SessionID), ) } else { - l.Log(WithLevel(ctx, WARN), "init stream completed", + l.Log(WithLevel(ctx, WARN), "ydb topic writer init stream failed", kv.Error(doneInfo.Error), kv.String("topic", info.Topic), kv.String("producer_id", info.ProducerID), @@ -735,7 +735,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicOnWriterBeforeCommitTransactionDoneInfo) { ctx := with(*info.Ctx, TRACE, "ydb", "topic", "writer", "beforecommit") - l.Log(ctx, "wait of flush messages before commit transaction", + l.Log(ctx, "ydb topic writer wait of flush messages before commit transaction", kv.String("kqp_session_id", info.KqpSessionID), kv.String("topic_session_id_start", info.TopicSessionID), kv.String("topic_session_id_finish", doneInfo.TopicSessionID), @@ -751,7 +751,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicOnWriterAfterFinishTransactionDoneInfo) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "beforecommit") - l.Log(ctx, "close writer after transaction finished", + l.Log(ctx, "ydb topic writer close writer after transaction finished", kv.String("kqp_session_id", info.SessionID), kv.String("tx_id", info.TransactionID), kv.Latency(start), @@ -764,21 +764,21 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "close") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic writer close starting...", kv.String("writer_instance_id", info.WriterInstanceID), kv.NamedError("reason", info.Reason), ) return func(doneInfo trace.TopicWriterCloseDoneInfo) { if doneInfo.Error == nil { - l.Log(WithLevel(ctx, DEBUG), "close topic writer completed", + l.Log(WithLevel(ctx, DEBUG), "ydb topic writer close done", kv.Error(doneInfo.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.NamedError("reason", info.Reason), kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "close topic writer completed", + l.Log(WithLevel(ctx, WARN), "ydb topic writer close failed", kv.Error(doneInfo.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.NamedError("reason", info.Reason), @@ -795,7 +795,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "compress", "messages") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic writer compress messages starting...", kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), kv.Any("reason", info.Reason), @@ -806,7 +806,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicWriterCompressMessagesDoneInfo) { if doneInfo.Error == nil { - l.Log(ctx, "compress message completed", + l.Log(ctx, "ydb topic writer compress messages done", kv.Error(doneInfo.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), @@ -817,7 +817,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, ERROR), "compress message completed", + l.Log(WithLevel(ctx, ERROR), "ydb topic writer compress messages failed", kv.Error(doneInfo.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), @@ -838,7 +838,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "send", "messages") start := time.Now() - l.Log(ctx, "start", + l.Log(ctx, "ydb topic writer send messages starting...", kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), kv.Any("codec", info.Codec), @@ -848,7 +848,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicWriterSendMessagesDoneInfo) { if doneInfo.Error == nil { - l.Log(ctx, "writing messages to grpc buffer completed", + l.Log(ctx, "ydb topic writer send messages done", kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), kv.Any("codec", info.Codec), @@ -857,7 +857,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { kv.Latency(start), ) } else { - l.Log(WithLevel(ctx, WARN), "writing messages to grpc buffer completed", + l.Log(WithLevel(ctx, WARN), "ydb topic writer send messages failed", kv.Error(doneInfo.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), @@ -875,7 +875,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } acks := info.Acks.GetAcks() ctx := with(context.Background(), DEBUG, "ydb", "topic", "writer", "receive", "result") - l.Log(ctx, "topic writer receive result from server", + l.Log(ctx, "ydb topic writer received result from server", kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID), kv.Int("acks_count", acks.AcksCount), @@ -927,7 +927,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return } ctx := with(context.Background(), DEBUG, "ydb", "topic", "writer", "read", "unknown", "grpc", "message") - l.Log(ctx, "topic writer receive unknown message from server", + l.Log(ctx, "topic writer receive unknown grpc message from server", kv.Error(info.Error), kv.String("writer_instance_id", info.WriterInstanceID), kv.String("session_id", info.SessionID),