Skip to content

Commit e62888a

Browse files
SpencerTorresSpencerTorres
committed
enhance debug logging
1 parent 8799b7d commit e62888a

File tree

4 files changed

+48
-19
lines changed

4 files changed

+48
-19
lines changed

‎clickhouse.go‎

Lines changed: 29 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -150,7 +150,7 @@ func (ch *clickhouse) Query(ctx context.Context, query string, args ...any) (row
150150
if err != nil {
151151
return nil, err
152152
}
153-
conn.debugf("[acquired] connection [%d]", conn.connID())
153+
conn.debugf("[query] \"%s\"", query)
154154
return conn.query(ctx, ch.release, query, args...)
155155
}
156156

@@ -161,7 +161,8 @@ func (ch *clickhouse) QueryRow(ctx context.Context, query string, args ...any) d
161161
err: err,
162162
}
163163
}
164-
conn.debugf("[acquired] connection [%d]", conn.connID())
164+
165+
conn.debugf("[query row] \"%s\"", query)
165166
return conn.queryRow(ctx, ch.release, query, args...)
166167
}
167168

@@ -170,8 +171,7 @@ func (ch *clickhouse) Exec(ctx context.Context, query string, args ...any) error
170171
if err != nil {
171172
return err
172173
}
173-
conn.debugf("[acquired] connection [%d]", conn.connID())
174-
174+
conn.debugf("[exec] \"%s\"", query)
175175
if err := conn.exec(ctx, query, args...); err != nil {
176176
ch.release(conn, err)
177177
return err
@@ -185,6 +185,7 @@ func (ch *clickhouse) PrepareBatch(ctx context.Context, query string, opts ...dr
185185
if err != nil {
186186
return nil, err
187187
}
188+
conn.debugf("[prepare batch] \"%s\"", query)
188189
batch, err := conn.prepareBatch(ctx, ch.release, ch.acquire, query, getPrepareBatchOptions(opts...))
189190
if err != nil {
190191
return nil, err
@@ -207,6 +208,7 @@ func (ch *clickhouse) AsyncInsert(ctx context.Context, query string, wait bool,
207208
if err != nil {
208209
return err
209210
}
211+
conn.debugf("[async insert] \"%s\"", query)
210212
if err := conn.asyncInsert(ctx, query, wait, args...); err != nil {
211213
ch.release(conn, err)
212214
return err
@@ -220,6 +222,7 @@ func (ch *clickhouse) Ping(ctx context.Context) (err error) {
220222
if err != nil {
221223
return err
222224
}
225+
conn.debugf("[ping]")
223226
if err := conn.ping(ctx); err != nil {
224227
ch.release(conn, err)
225228
return err
@@ -324,6 +327,7 @@ func (ch *clickhouse) acquire(ctx context.Context) (conn nativeTransport, err er
324327
}
325328
}
326329
conn.setReleased(false)
330+
conn.debugf("[acquired from pool]")
327331
return conn, nil
328332
default:
329333
}
@@ -334,6 +338,7 @@ func (ch *clickhouse) acquire(ctx context.Context) (conn nativeTransport, err er
334338
}
335339
return nil, err
336340
}
341+
conn.debugf("[acquired new]")
337342
return conn, nil
338343
}
339344

@@ -377,31 +382,47 @@ func (ch *clickhouse) release(conn nativeTransport, err error) {
377382
return
378383
}
379384
conn.setReleased(true)
380-
conn.debugf("[released] connection [%d]", conn.connID())
385+
386+
if err != nil {
387+
conn.debugf("[released with error]")
388+
} else {
389+
conn.debugf("[released]")
390+
}
381391

382392
select {
383393
case <-ch.open:
384394
default:
385395
}
386-
if err != nil || time.Since(conn.connectedAtTime()) >= ch.opt.ConnMaxLifetime {
396+
397+
if err != nil {
398+
conn.debugf("[close: error] %s", err.Error())
399+
conn.close()
400+
return
401+
} else if time.Since(conn.connectedAtTime()) >= ch.opt.ConnMaxLifetime {
402+
conn.debugf("[close: lifetime expired]")
387403
conn.close()
388404
return
389405
}
406+
390407
if ch.opt.FreeBufOnConnRelease {
408+
conn.debugf("[free buffer]")
391409
conn.freeBuffer()
392410
}
411+
393412
select {
394413
case ch.idle <- conn:
395414
default:
415+
conn.debugf("[close: idle pool full %d/%d]", len(ch.idle), cap(ch.idle))
396416
conn.close()
397417
}
398418
}
399419

400420
func (ch *clickhouse) Close() error {
401421
for {
402422
select {
403-
case c := <-ch.idle:
404-
c.close()
423+
case conn := <-ch.idle:
424+
conn.debugf("[close: closing pool]")
425+
conn.close()
405426
default:
406427
// In rare cases, close may be called multiple times, don't block
407428
//TODO: add proper close flag to indicate this pool is unusable after Close

‎conn.go‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -64,12 +64,12 @@ func dial(ctx context.Context, addr string, num int, opt *Options) (*connect, er
6464
if opt.Debugf != nil {
6565
debugf = func(format string, v ...any) {
6666
opt.Debugf(
67-
"[clickhouse][conn=%d][%s] "+format,
68-
append([]interface{}{num, conn.RemoteAddr()}, v...)...,
67+
"[clickhouse][%s][id=%d] "+format,
68+
append([]interface{}{conn.RemoteAddr(), num}, v...)...,
6969
)
7070
}
7171
} else {
72-
debugf = log.New(os.Stdout, fmt.Sprintf("[clickhouse][conn=%d][%s]", num, conn.RemoteAddr()), 0).Printf
72+
debugf = log.New(os.Stdout, fmt.Sprintf("[clickhouse][%s][id=%d]", conn.RemoteAddr(), num), 0).Printf
7373
}
7474
}
7575

‎conn_http.go‎

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -165,12 +165,12 @@ func dialHttp(ctx context.Context, addr string, num int, opt *Options) (*httpCon
165165
if opt.Debugf != nil {
166166
debugf = func(format string, v ...any) {
167167
opt.Debugf(
168-
"[clickhouse-http][conn=%d][%s] "+format,
169-
append([]interface{}{num, addr}, v...)...,
168+
"[clickhouse-http][%s][id=%d] "+format,
169+
append([]interface{}{addr, num}, v...)...,
170170
)
171171
}
172172
} else {
173-
debugf = log.New(os.Stdout, fmt.Sprintf("[clickhouse-http][conn=%d][%s]", num, addr), 0).Printf
173+
debugf = log.New(os.Stdout, fmt.Sprintf("[clickhouse-http][%s][id=%d]", addr, num), 0).Printf
174174
}
175175
}
176176

@@ -333,6 +333,7 @@ func (h *httpConnect) isBad() bool {
333333
}
334334

335335
func (h *httpConnect) queryHello(ctx context.Context, release nativeTransportRelease) (proto.ServerHandshake, error) {
336+
h.debugf("[query hello]")
336337
ctx = Context(ctx, ignoreExternalTables())
337338
query := "SELECT displayName(), version(), revision(), timezone()"
338339
rows, err := h.query(ctx, release, query)
@@ -446,7 +447,7 @@ func (h *httpConnect) readData(reader *chproto.Reader, timezone *time.Location)
446447
defer reader.DisableCompression()
447448
}
448449
if err := block.Decode(reader, h.handshake.Revision); err != nil {
449-
return nil, err
450+
return nil, fmt.Errorf("block decode: %w", err)
450451
}
451452
return &block, nil
452453
}
@@ -597,11 +598,12 @@ func (h *httpConnect) executeRequest(req *http.Request) (*http.Response, error)
597598

598599
if resp.StatusCode != http.StatusOK {
599600
defer discardAndClose(resp.Body)
600-
msg, err := h.readRawResponse(resp)
601+
msgBytes, err := h.readRawResponse(resp)
601602
if err != nil {
602-
return nil, fmt.Errorf("clickhouse [execute]:: %d code: failed to read the response: %w", resp.StatusCode, err)
603+
return nil, fmt.Errorf("[HTTP %d] failed to read response: %w", resp.StatusCode, err)
603604
}
604-
return nil, fmt.Errorf("clickhouse [execute]:: %d code: %s", resp.StatusCode, string(msg))
605+
606+
return nil, fmt.Errorf("[HTTP %d] response body: \"%s\"", resp.StatusCode, string(msgBytes))
605607
}
606608
return resp, nil
607609
}

‎conn_http_query.go‎

Lines changed: 7 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ package clickhouse
2020
import (
2121
"context"
2222
"errors"
23+
"fmt"
2324
"io"
2425

2526
chproto "github.com/ClickHouse/ch-go/proto"
@@ -28,9 +29,11 @@ import (
2829

2930
// release is ignored, because http used by std with empty release function
3031
func (h *httpConnect) query(ctx context.Context, release nativeTransportRelease, query string, args ...any) (*rows, error) {
32+
h.debugf("[query] %s", query)
3133
options := queryOptions(ctx)
3234
query, err := bindQueryOrAppendParameters(true, &options, query, h.handshake.Timezone, args...)
3335
if err != nil {
36+
err = fmt.Errorf("bindQueryOrAppendParameters: %w", err)
3437
release(h, err)
3538
return nil, err
3639
}
@@ -45,6 +48,7 @@ func (h *httpConnect) query(ctx context.Context, release nativeTransportRelease,
4548

4649
res, err := h.sendQuery(ctx, query, &options, headers)
4750
if err != nil {
51+
err = fmt.Errorf("sendQuery: %w", err)
4852
release(h, err)
4953
return nil, err
5054
}
@@ -68,6 +72,7 @@ func (h *httpConnect) query(ctx context.Context, release nativeTransportRelease,
6872
// automatically as they might not have permissions.
6973
reader, err := rw.NewReader(res)
7074
if err != nil {
75+
err = fmt.Errorf("NewReader: %w", err)
7176
discardAndClose(res.Body)
7277
h.compressionPool.Put(rw)
7378
release(h, err)
@@ -76,6 +81,7 @@ func (h *httpConnect) query(ctx context.Context, release nativeTransportRelease,
7681
chReader := chproto.NewReader(reader)
7782
block, err := h.readData(chReader, options.userLocation)
7883
if err != nil && !errors.Is(err, io.EOF) {
84+
err = fmt.Errorf("readData: %w", err)
7985
discardAndClose(res.Body)
8086
h.compressionPool.Put(rw)
8187
release(h, err)
@@ -97,7 +103,7 @@ func (h *httpConnect) query(ctx context.Context, release nativeTransportRelease,
97103
if err != nil {
98104
// ch-go wraps EOF errors
99105
if !errors.Is(err, io.EOF) {
100-
errCh <- err
106+
errCh <- fmt.Errorf("readData stream: %w", err)
101107
}
102108
break
103109
}

0 commit comments

Comments
 (0)