Skip to content

Commit e2799d1

Browse files
rekbyrekby
authored
Merge pull request improve logging
2 parents 9b55771 + 581a213 commit e2799d1

File tree

11 files changed

+340
-339
lines changed

11 files changed

+340
-339
lines changed

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
* Massive changed log messages - those have more details now.
12
* Fixed sometime panic on stats receive in query service
23

34
## v3.99.7

‎internal/topic/topicwriterinternal/writer_single_stream.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -126,7 +126,7 @@ func (w *SingleStreamWriter) start() {
126126

127127
func (w *SingleStreamWriter) initStream() (err error) {
128128
traceOnDone := trace.TopicOnWriterInitStream(w.cfg.Tracer, w.cfg.reconnectorInstanceID, w.cfg.topic, w.cfg.producerID)
129-
defer traceOnDone(w.SessionID, err)
129+
defer func() { traceOnDone(w.SessionID, err) }()
130130

131131
req := w.createInitRequest()
132132
if err = w.cfg.stream.Send(&req); err != nil {

‎log/coordination.go‎

Lines changed: 36 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -25,11 +25,11 @@ func internalCoordination(
2525
return nil
2626
}
2727
ctx := with(*info.Context, TRACE, "ydb", "coordination", "new")
28-
l.Log(ctx, "start")
28+
l.Log(ctx, "coordination client starting...")
2929
start := time.Now()
3030

3131
return func(info trace.CoordinationNewDoneInfo) {
32-
l.Log(WithLevel(ctx, INFO), "done",
32+
l.Log(WithLevel(ctx, INFO), "coordination client start done",
3333
kv.Latency(start),
3434
kv.Version(),
3535
)
@@ -40,18 +40,18 @@ func internalCoordination(
4040
return nil
4141
}
4242
ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "create")
43-
l.Log(ctx, "start",
43+
l.Log(ctx, "coordination node create starting...",
4444
kv.String("path", info.Path),
4545
)
4646
start := time.Now()
4747

4848
return func(info trace.CoordinationCreateNodeDoneInfo) {
4949
if info.Error == nil {
50-
l.Log(WithLevel(ctx, INFO), "done",
50+
l.Log(WithLevel(ctx, INFO), "coordination node create done",
5151
kv.Latency(start),
5252
)
5353
} else {
54-
l.Log(WithLevel(ctx, ERROR), "fail",
54+
l.Log(WithLevel(ctx, ERROR), "coordination node create failed",
5555
kv.Latency(start),
5656
kv.Version(),
5757
)
@@ -63,18 +63,18 @@ func internalCoordination(
6363
return nil
6464
}
6565
ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "alter")
66-
l.Log(ctx, "start",
66+
l.Log(ctx, "coordination alter node starting...",
6767
kv.String("path", info.Path),
6868
)
6969
start := time.Now()
7070

7171
return func(info trace.CoordinationAlterNodeDoneInfo) {
7272
if info.Error == nil {
73-
l.Log(WithLevel(ctx, INFO), "done",
73+
l.Log(WithLevel(ctx, INFO), "coordination alter node done",
7474
kv.Latency(start),
7575
)
7676
} else {
77-
l.Log(WithLevel(ctx, ERROR), "fail",
77+
l.Log(WithLevel(ctx, ERROR), "coordination alter node failed",
7878
kv.Latency(start),
7979
kv.Version(),
8080
)
@@ -86,18 +86,18 @@ func internalCoordination(
8686
return nil
8787
}
8888
ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "drop")
89-
l.Log(ctx, "start",
89+
l.Log(ctx, "drop coordination node starting...",
9090
kv.String("path", info.Path),
9191
)
9292
start := time.Now()
9393

9494
return func(info trace.CoordinationDropNodeDoneInfo) {
9595
if info.Error == nil {
96-
l.Log(WithLevel(ctx, INFO), "done",
96+
l.Log(WithLevel(ctx, INFO), "drop coordination node done",
9797
kv.Latency(start),
9898
)
9999
} else {
100-
l.Log(WithLevel(ctx, ERROR), "fail",
100+
l.Log(WithLevel(ctx, ERROR), "drop coordination node failed",
101101
kv.Latency(start),
102102
kv.Version(),
103103
)
@@ -109,18 +109,18 @@ func internalCoordination(
109109
return nil
110110
}
111111
ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "describe")
112-
l.Log(ctx, "start",
112+
l.Log(ctx, "describe coordination node starting...",
113113
kv.String("path", info.Path),
114114
)
115115
start := time.Now()
116116

117117
return func(info trace.CoordinationDescribeNodeDoneInfo) {
118118
if info.Error == nil {
119-
l.Log(WithLevel(ctx, INFO), "done",
119+
l.Log(WithLevel(ctx, INFO), "describe coordination node done",
120120
kv.Latency(start),
121121
)
122122
} else {
123-
l.Log(WithLevel(ctx, ERROR), "fail",
123+
l.Log(WithLevel(ctx, ERROR), "describe coordination node failed",
124124
kv.Latency(start),
125125
kv.Version(),
126126
)
@@ -132,16 +132,16 @@ func internalCoordination(
132132
return nil
133133
}
134134
ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "describe")
135-
l.Log(ctx, "start")
135+
l.Log(ctx, "create coordination session starting...")
136136
start := time.Now()
137137

138138
return func(info trace.CoordinationSessionDoneInfo) {
139139
if info.Error == nil {
140-
l.Log(WithLevel(ctx, INFO), "done",
140+
l.Log(WithLevel(ctx, INFO), "create coordination session done",
141141
kv.Latency(start),
142142
)
143143
} else {
144-
l.Log(WithLevel(ctx, ERROR), "fail",
144+
l.Log(WithLevel(ctx, ERROR), "create coordination session failed",
145145
kv.Latency(start),
146146
kv.Version(),
147147
)
@@ -153,16 +153,16 @@ func internalCoordination(
153153
return nil
154154
}
155155
ctx := with(*info.Context, TRACE, "ydb", "coordination", "close")
156-
l.Log(ctx, "start")
156+
l.Log(ctx, "close coordination client starting...")
157157
start := time.Now()
158158

159159
return func(info trace.CoordinationCloseDoneInfo) {
160160
if info.Error == nil {
161-
l.Log(WithLevel(ctx, INFO), "done",
161+
l.Log(WithLevel(ctx, INFO), "close coordination client done",
162162
kv.Latency(start),
163163
)
164164
} else {
165-
l.Log(WithLevel(ctx, ERROR), "fail",
165+
l.Log(WithLevel(ctx, ERROR), "close coordination client failed",
166166
kv.Latency(start),
167167
kv.Version(),
168168
)
@@ -178,11 +178,11 @@ func internalCoordination(
178178
return nil
179179
}
180180
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stream", "new")
181-
l.Log(ctx, "stream")
181+
l.Log(ctx, "new coordination session stream starting...")
182182
start := time.Now()
183183

184184
return func(info trace.CoordinationSessionNewStreamDoneInfo) {
185-
l.Log(ctx, "done",
185+
l.Log(ctx, "new coordination session stream done",
186186
kv.Latency(start),
187187
kv.Error(info.Error),
188188
kv.Version(),
@@ -194,7 +194,7 @@ func internalCoordination(
194194
return
195195
}
196196
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "started")
197-
l.Log(ctx, "",
197+
l.Log(ctx, "coordination session started",
198198
kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)),
199199
kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)),
200200
)
@@ -204,7 +204,7 @@ func internalCoordination(
204204
return
205205
}
206206
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "start", "timeout")
207-
l.Log(ctx, "",
207+
l.Log(ctx, "coordination session start timeout",
208208
kv.Stringer("timeout", info.Timeout),
209209
)
210210
},
@@ -213,7 +213,7 @@ func internalCoordination(
213213
return
214214
}
215215
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "keepAlive", "timeout")
216-
l.Log(ctx, "",
216+
l.Log(ctx, "coordination session keep alive timeout",
217217
kv.Stringer("timeout", info.Timeout),
218218
kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime),
219219
)
@@ -223,7 +223,7 @@ func internalCoordination(
223223
return
224224
}
225225
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stopped")
226-
l.Log(ctx, "",
226+
l.Log(ctx, "coordination session stopped",
227227
kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)),
228228
kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)),
229229
)
@@ -233,7 +233,7 @@ func internalCoordination(
233233
return
234234
}
235235
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop", "timeout")
236-
l.Log(ctx, "",
236+
l.Log(ctx, "coordination session stop timeout",
237237
kv.Stringer("timeout", info.Timeout),
238238
)
239239
},
@@ -242,7 +242,7 @@ func internalCoordination(
242242
return
243243
}
244244
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "client", "timeout")
245-
l.Log(ctx, "",
245+
l.Log(ctx, "coordination session client timeout",
246246
kv.Stringer("timeout", info.Timeout),
247247
kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime),
248248
)
@@ -252,7 +252,7 @@ func internalCoordination(
252252
return
253253
}
254254
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "expire")
255-
l.Log(ctx, "",
255+
l.Log(ctx, "coordination session server expire",
256256
kv.Stringer("failure", info.Failure),
257257
)
258258
},
@@ -261,7 +261,7 @@ func internalCoordination(
261261
return
262262
}
263263
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "error")
264-
l.Log(ctx, "",
264+
l.Log(ctx, "coordination session server error",
265265
kv.Stringer("failure", info.Failure),
266266
)
267267
},
@@ -274,11 +274,11 @@ func internalCoordination(
274274
return nil
275275
}
276276
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "receive")
277-
l.Log(ctx, "receive")
277+
l.Log(ctx, "coordination session receive starting...")
278278
start := time.Now()
279279

280280
return func(info trace.CoordinationSessionReceiveDoneInfo) {
281-
l.Log(ctx, "done",
281+
l.Log(ctx, "coordination session receive done",
282282
kv.Latency(start),
283283
kv.Error(info.Error),
284284
kv.Stringer("response", info.Response),
@@ -291,7 +291,7 @@ func internalCoordination(
291291
return
292292
}
293293
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "receive", "unexpected")
294-
l.Log(ctx, "",
294+
l.Log(ctx, "coordination session received unexpected",
295295
kv.Stringer("response", info.Response),
296296
)
297297
},
@@ -300,7 +300,7 @@ func internalCoordination(
300300
return
301301
}
302302
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop")
303-
l.Log(ctx, "",
303+
l.Log(ctx, "coordination session stopped",
304304
kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)),
305305
)
306306
},
@@ -313,11 +313,11 @@ func internalCoordination(
313313
return nil
314314
}
315315
ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "start")
316-
l.Log(ctx, "start")
316+
l.Log(ctx, "coordination session start starting...")
317317
start := time.Now()
318318

319319
return func(info trace.CoordinationSessionStartDoneInfo) {
320-
l.Log(ctx, "done",
320+
l.Log(ctx, "coordination session start done",
321321
kv.Latency(start),
322322
kv.Error(info.Error),
323323
kv.Version(),

‎log/discovery.go‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -18,20 +18,20 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) {
1818
return nil
1919
}
2020
ctx := with(*info.Context, DEBUG, "ydb", "discovery", "list", "endpoints")
21-
l.Log(ctx, "start",
21+
l.Log(ctx, "discovery starting...",
2222
kv.String("address", info.Address),
2323
kv.String("database", info.Database),
2424
)
2525
start := time.Now()
2626

2727
return func(info trace.DiscoveryDiscoverDoneInfo) {
2828
if info.Error == nil {
29-
l.Log(WithLevel(ctx, INFO), "done",
29+
l.Log(WithLevel(ctx, INFO), "discovery done",
3030
kv.Latency(start),
3131
kv.Stringer("endpoints", kv.Endpoints(info.Endpoints)),
3232
)
3333
} else {
34-
l.Log(WithLevel(ctx, ERROR), "failed",
34+
l.Log(WithLevel(ctx, ERROR), "discovery failed",
3535
kv.Error(info.Error),
3636
kv.Latency(start),
3737
kv.Version(),
@@ -44,18 +44,18 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) {
4444
return nil
4545
}
4646
ctx := with(*info.Context, TRACE, "ydb", "discovery", "whoAmI")
47-
l.Log(ctx, "start")
47+
l.Log(ctx, "discovery whoami starting...")
4848
start := time.Now()
4949

5050
return func(info trace.DiscoveryWhoAmIDoneInfo) {
5151
if info.Error == nil {
52-
l.Log(ctx, "done",
52+
l.Log(ctx, "discovery whoami done",
5353
kv.Latency(start),
5454
kv.String("user", info.User),
5555
kv.Strings("groups", info.Groups),
5656
)
5757
} else {
58-
l.Log(WithLevel(ctx, WARN), "failed",
58+
l.Log(WithLevel(ctx, WARN), "discovery whoami failed",
5959
kv.Error(info.Error),
6060
kv.Latency(start),
6161
kv.Version(),

0 commit comments

Comments
 (0)