1 package tracelog_test
2
3 import (
4 "bytes"
5 "context"
6 "log"
7 "os"
8 "strings"
9 "testing"
10 "time"
11
12 "github.com/jackc/pgx/v5"
13 "github.com/jackc/pgx/v5/pgxtest"
14 "github.com/jackc/pgx/v5/tracelog"
15 "github.com/stretchr/testify/assert"
16 "github.com/stretchr/testify/require"
17 )
18
19 var defaultConnTestRunner pgxtest.ConnTestRunner
20
21 func init() {
22 defaultConnTestRunner = pgxtest.DefaultConnTestRunner()
23 defaultConnTestRunner.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
24 config, err := pgx.ParseConfig(os.Getenv("PGX_TEST_DATABASE"))
25 require.NoError(t, err)
26 return config
27 }
28 }
29
30 type testLog struct {
31 lvl tracelog.LogLevel
32 msg string
33 data map[string]any
34 }
35
36 type testLogger struct {
37 logs []testLog
38 }
39
40 func (l *testLogger) Log(ctx context.Context, level tracelog.LogLevel, msg string, data map[string]any) {
41 data["ctxdata"] = ctx.Value("ctxdata")
42 l.logs = append(l.logs, testLog{lvl: level, msg: msg, data: data})
43 }
44
45 func (l *testLogger) Clear() {
46 l.logs = l.logs[0:0]
47 }
48
49 func (l *testLogger) FilterByMsg(msg string) (res []testLog) {
50 for _, log := range l.logs {
51 if log.msg == msg {
52 res = append(res, log)
53 }
54 }
55
56 return res
57 }
58
59 func TestContextGetsPassedToLogMethod(t *testing.T) {
60 t.Parallel()
61
62 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
63 defer cancel()
64
65 logger := &testLogger{}
66 tracer := &tracelog.TraceLog{
67 Logger: logger,
68 LogLevel: tracelog.LogLevelTrace,
69 }
70
71 ctr := defaultConnTestRunner
72 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
73 config := defaultConnTestRunner.CreateConfig(ctx, t)
74 config.Tracer = tracer
75 return config
76 }
77
78 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
79 logger.Clear()
80
81 ctx = context.WithValue(ctx, "ctxdata", "foo")
82 _, err := conn.Exec(ctx, `;`)
83 require.NoError(t, err)
84 require.Len(t, logger.logs, 1)
85 require.Equal(t, "foo", logger.logs[0].data["ctxdata"])
86 })
87 }
88
89 func TestLoggerFunc(t *testing.T) {
90 t.Parallel()
91
92 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
93 defer cancel()
94
95 const testMsg = "foo"
96
97 buf := bytes.Buffer{}
98 logger := log.New(&buf, "", 0)
99
100 createAdapterFn := func(logger *log.Logger) tracelog.LoggerFunc {
101 return func(ctx context.Context, level tracelog.LogLevel, msg string, data map[string]interface{}) {
102 logger.Printf("%s", testMsg)
103 }
104 }
105
106 config := defaultConnTestRunner.CreateConfig(ctx, t)
107 config.Tracer = &tracelog.TraceLog{
108 Logger: createAdapterFn(logger),
109 LogLevel: tracelog.LogLevelTrace,
110 }
111
112 conn, err := pgx.ConnectConfig(ctx, config)
113 require.NoError(t, err)
114 defer conn.Close(ctx)
115
116 buf.Reset()
117
118 if _, err := conn.Exec(context.TODO(), ";"); err != nil {
119 t.Fatal(err)
120 }
121
122 if strings.TrimSpace(buf.String()) != testMsg {
123 t.Errorf("Expected logger function to return '%s', but it was '%s'", testMsg, buf.String())
124 }
125 }
126
127 func TestLogQuery(t *testing.T) {
128 t.Parallel()
129
130 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
131 defer cancel()
132
133 logger := &testLogger{}
134 tracer := &tracelog.TraceLog{
135 Logger: logger,
136 LogLevel: tracelog.LogLevelTrace,
137 }
138
139 ctr := defaultConnTestRunner
140 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
141 config := defaultConnTestRunner.CreateConfig(ctx, t)
142 config.Tracer = tracer
143 return config
144 }
145
146 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
147 logger.Clear()
148
149 _, err := conn.Exec(ctx, `select $1::text`, "testing")
150 require.NoError(t, err)
151
152 logs := logger.FilterByMsg("Query")
153 require.Len(t, logs, 1)
154 require.Equal(t, tracelog.LogLevelInfo, logs[0].lvl)
155
156 logger.Clear()
157
158 _, err = conn.Exec(ctx, `foo`, "testing")
159 require.Error(t, err)
160
161 logs = logger.FilterByMsg("Query")
162 require.Len(t, logs, 1)
163 require.Equal(t, tracelog.LogLevelError, logs[0].lvl)
164 require.Equal(t, err, logs[0].data["err"])
165 })
166 }
167
168
169 func TestLogQueryArgsHandlesUTF8(t *testing.T) {
170 t.Parallel()
171
172 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
173 defer cancel()
174
175 logger := &testLogger{}
176 tracer := &tracelog.TraceLog{
177 Logger: logger,
178 LogLevel: tracelog.LogLevelTrace,
179 }
180
181 ctr := defaultConnTestRunner
182 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
183 config := defaultConnTestRunner.CreateConfig(ctx, t)
184 config.Tracer = tracer
185 return config
186 }
187
188 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
189 logger.Clear()
190
191 var s string
192 for i := 0; i < 63; i++ {
193 s += "0"
194 }
195 s += "😊"
196
197 _, err := conn.Exec(ctx, `select $1::text`, s)
198 require.NoError(t, err)
199
200 logs := logger.FilterByMsg("Query")
201 require.Len(t, logs, 1)
202 require.Equal(t, tracelog.LogLevelInfo, logs[0].lvl)
203 require.Equal(t, s, logs[0].data["args"].([]any)[0])
204
205 logger.Clear()
206
207 _, err = conn.Exec(ctx, `select $1::text`, s+"000")
208 require.NoError(t, err)
209
210 logs = logger.FilterByMsg("Query")
211 require.Len(t, logs, 1)
212 require.Equal(t, tracelog.LogLevelInfo, logs[0].lvl)
213 require.Equal(t, s+" (truncated 3 bytes)", logs[0].data["args"].([]any)[0])
214 })
215 }
216
217 func TestLogCopyFrom(t *testing.T) {
218 t.Parallel()
219
220 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
221 defer cancel()
222
223 logger := &testLogger{}
224 tracer := &tracelog.TraceLog{
225 Logger: logger,
226 LogLevel: tracelog.LogLevelTrace,
227 }
228
229 ctr := defaultConnTestRunner
230 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
231 config := defaultConnTestRunner.CreateConfig(ctx, t)
232 config.Tracer = tracer
233 return config
234 }
235
236 pgxtest.RunWithQueryExecModes(ctx, t, ctr, pgxtest.KnownOIDQueryExecModes, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
237 _, err := conn.Exec(ctx, `create temporary table foo(a int4)`)
238 require.NoError(t, err)
239
240 logger.Clear()
241
242 inputRows := [][]any{
243 {int32(1)},
244 {nil},
245 }
246
247 copyCount, err := conn.CopyFrom(ctx, pgx.Identifier{"foo"}, []string{"a"}, pgx.CopyFromRows(inputRows))
248 require.NoError(t, err)
249 require.EqualValues(t, len(inputRows), copyCount)
250
251 logs := logger.FilterByMsg("CopyFrom")
252 require.Len(t, logs, 1)
253 require.Equal(t, tracelog.LogLevelInfo, logs[0].lvl)
254
255 logger.Clear()
256
257 inputRows = [][]any{
258 {"not an integer"},
259 {nil},
260 }
261
262 copyCount, err = conn.CopyFrom(ctx, pgx.Identifier{"foo"}, []string{"a"}, pgx.CopyFromRows(inputRows))
263 require.Error(t, err)
264 require.EqualValues(t, 0, copyCount)
265
266 logs = logger.FilterByMsg("CopyFrom")
267 require.Len(t, logs, 1)
268 require.Equal(t, tracelog.LogLevelError, logs[0].lvl)
269 })
270 }
271
272 func TestLogConnect(t *testing.T) {
273 t.Parallel()
274
275 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
276 defer cancel()
277
278 logger := &testLogger{}
279 tracer := &tracelog.TraceLog{
280 Logger: logger,
281 LogLevel: tracelog.LogLevelTrace,
282 }
283
284 config := defaultConnTestRunner.CreateConfig(ctx, t)
285 config.Tracer = tracer
286
287 conn1, err := pgx.ConnectConfig(ctx, config)
288 require.NoError(t, err)
289 defer conn1.Close(ctx)
290 require.Len(t, logger.logs, 1)
291 require.Equal(t, "Connect", logger.logs[0].msg)
292 require.Equal(t, tracelog.LogLevelInfo, logger.logs[0].lvl)
293
294 logger.Clear()
295
296 config, err = pgx.ParseConfig("host=/invalid")
297 require.NoError(t, err)
298 config.Tracer = tracer
299
300 conn2, err := pgx.ConnectConfig(ctx, config)
301 require.Nil(t, conn2)
302 require.Error(t, err)
303 require.Len(t, logger.logs, 1)
304 require.Equal(t, "Connect", logger.logs[0].msg)
305 require.Equal(t, tracelog.LogLevelError, logger.logs[0].lvl)
306 }
307
308 func TestLogBatchStatementsOnExec(t *testing.T) {
309 t.Parallel()
310
311 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
312 defer cancel()
313
314 logger := &testLogger{}
315 tracer := &tracelog.TraceLog{
316 Logger: logger,
317 LogLevel: tracelog.LogLevelTrace,
318 }
319
320 ctr := defaultConnTestRunner
321 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
322 config := defaultConnTestRunner.CreateConfig(ctx, t)
323 config.Tracer = tracer
324 return config
325 }
326
327 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
328 logger.Clear()
329
330 batch := &pgx.Batch{}
331 batch.Queue("create table foo (id bigint)")
332 batch.Queue("drop table foo")
333
334 br := conn.SendBatch(ctx, batch)
335
336 _, err := br.Exec()
337 require.NoError(t, err)
338
339 _, err = br.Exec()
340 require.NoError(t, err)
341
342 err = br.Close()
343 require.NoError(t, err)
344
345 require.Len(t, logger.logs, 3)
346 assert.Equal(t, "BatchQuery", logger.logs[0].msg)
347 assert.Equal(t, "create table foo (id bigint)", logger.logs[0].data["sql"])
348 assert.Equal(t, "BatchQuery", logger.logs[1].msg)
349 assert.Equal(t, "drop table foo", logger.logs[1].data["sql"])
350 assert.Equal(t, "BatchClose", logger.logs[2].msg)
351
352 })
353 }
354
355 func TestLogBatchStatementsOnBatchResultClose(t *testing.T) {
356 t.Parallel()
357
358 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
359 defer cancel()
360
361 logger := &testLogger{}
362 tracer := &tracelog.TraceLog{
363 Logger: logger,
364 LogLevel: tracelog.LogLevelTrace,
365 }
366
367 ctr := defaultConnTestRunner
368 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
369 config := defaultConnTestRunner.CreateConfig(ctx, t)
370 config.Tracer = tracer
371 return config
372 }
373
374 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
375 logger.Clear()
376
377 batch := &pgx.Batch{}
378 batch.Queue("select generate_series(1,$1)", 100)
379 batch.Queue("select 1 = 1;")
380
381 br := conn.SendBatch(ctx, batch)
382 err := br.Close()
383 require.NoError(t, err)
384
385 require.Len(t, logger.logs, 3)
386 assert.Equal(t, "BatchQuery", logger.logs[0].msg)
387 assert.Equal(t, "select generate_series(1,$1)", logger.logs[0].data["sql"])
388 assert.Equal(t, "BatchQuery", logger.logs[1].msg)
389 assert.Equal(t, "select 1 = 1;", logger.logs[1].data["sql"])
390 assert.Equal(t, "BatchClose", logger.logs[2].msg)
391 })
392 }
393
394 func TestLogPrepare(t *testing.T) {
395 t.Parallel()
396
397 ctx, cancel := context.WithTimeout(context.Background(), 120*time.Second)
398 defer cancel()
399
400 logger := &testLogger{}
401 tracer := &tracelog.TraceLog{
402 Logger: logger,
403 LogLevel: tracelog.LogLevelTrace,
404 }
405
406 ctr := defaultConnTestRunner
407 ctr.CreateConfig = func(ctx context.Context, t testing.TB) *pgx.ConnConfig {
408 config := defaultConnTestRunner.CreateConfig(ctx, t)
409 config.Tracer = tracer
410 return config
411 }
412
413 pgxtest.RunWithQueryExecModes(ctx, t, ctr, []pgx.QueryExecMode{
414 pgx.QueryExecModeCacheStatement,
415 pgx.QueryExecModeCacheDescribe,
416 pgx.QueryExecModeDescribeExec,
417 }, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
418 logger.Clear()
419
420 _, err := conn.Exec(ctx, `select $1::text`, "testing")
421 require.NoError(t, err)
422
423 logs := logger.FilterByMsg("Prepare")
424 require.Len(t, logs, 1)
425 require.Equal(t, tracelog.LogLevelInfo, logs[0].lvl)
426
427 logger.Clear()
428
429 _, err = conn.Exec(ctx, `foo aaaa`, "testing")
430 require.Error(t, err)
431
432 logs = logger.FilterByMsg("Prepare")
433 require.Len(t, logs, 1)
434 require.Equal(t, err, logs[0].data["err"])
435 })
436
437 ctx, cancel = context.WithTimeout(ctx, 30*time.Second)
438 defer cancel()
439
440 pgxtest.RunWithQueryExecModes(ctx, t, ctr, nil, func(ctx context.Context, t testing.TB, conn *pgx.Conn) {
441 logger.Clear()
442
443 _, err := conn.Prepare(ctx, "test_query_1", `select $1::int`)
444 require.NoError(t, err)
445
446 require.Len(t, logger.logs, 1)
447 require.Equal(t, "Prepare", logger.logs[0].msg)
448 require.Equal(t, tracelog.LogLevelInfo, logger.logs[0].lvl)
449
450 logger.Clear()
451
452 _, err = conn.Prepare(ctx, `test_query_2`, "foo aaaa")
453 require.Error(t, err)
454
455 require.Len(t, logger.logs, 1)
456 require.Equal(t, "Prepare", logger.logs[0].msg)
457 require.Equal(t, err, logger.logs[0].data["err"])
458 })
459 }
460
View as plain text