initial logging improve

ydb-platform · Jan 28, 2025 · 311abba · 311abba
1 parent 9780940
commit 311abba
Show file tree

Hide file tree

Showing 3 changed files with 43 additions and 43 deletions.
diff --git 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
@@ -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 completed",
 						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 completed",
 					kv.Latency(start),
 					kv.Error(info.Error),
 					kv.Version(),

diff --git a/log/discovery.go b/log/discovery.go
@@ -18,20 +18,20 @@ 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),
 		)
 		start := time.Now()
 
 		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, "done discovery whoami",
 					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), "failed discovery whoami",
 					kv.Error(info.Error),
 					kv.Latency(start),
 					kv.Version(),