Branch data Line data Source code
1 : : /*-------------------------------------------------------------------------
2 : : *
3 : : * fe-trace.c
4 : : * functions for libpq protocol tracing
5 : : *
6 : : * Portions Copyright (c) 1996-2026, PostgreSQL Global Development Group
7 : : * Portions Copyright (c) 1994, Regents of the University of California
8 : : *
9 : : * IDENTIFICATION
10 : : * src/interfaces/libpq/fe-trace.c
11 : : *
12 : : *-------------------------------------------------------------------------
13 : : */
14 : :
15 : : #include "postgres_fe.h"
16 : :
17 : : #include <ctype.h>
18 : : #include <limits.h>
19 : : #include <sys/time.h>
20 : : #include <time.h>
21 : :
22 : : #ifdef WIN32
23 : : #include "win32.h"
24 : : #else
25 : : #include <unistd.h>
26 : : #endif
27 : :
28 : : #include "libpq-fe.h"
29 : : #include "libpq-int.h"
30 : : #include "port/pg_bswap.h"
31 : :
32 : :
33 : : /* Enable tracing */
34 : : void
35 : 9 : PQtrace(PGconn *conn, FILE *debug_port)
36 : : {
37 [ - + ]: 9 : if (conn == NULL)
38 : 0 : return;
39 : 9 : PQuntrace(conn);
40 [ - + ]: 9 : if (debug_port == NULL)
41 : 0 : return;
42 : :
43 : 9 : conn->Pfdebug = debug_port;
44 : 9 : conn->traceFlags = 0;
45 : : }
46 : :
47 : : /* Disable tracing */
48 : : void
49 : 9 : PQuntrace(PGconn *conn)
50 : : {
51 [ - + ]: 9 : if (conn == NULL)
52 : 0 : return;
53 [ - + ]: 9 : if (conn->Pfdebug)
54 : : {
55 : 0 : fflush(conn->Pfdebug);
56 : 0 : conn->Pfdebug = NULL;
57 : : }
58 : :
59 : 9 : conn->traceFlags = 0;
60 : : }
61 : :
62 : : /* Set flags for current tracing session */
63 : : void
64 : 9 : PQsetTraceFlags(PGconn *conn, int flags)
65 : : {
66 [ - + ]: 9 : if (conn == NULL)
67 : 0 : return;
68 : : /* If PQtrace() failed, do nothing. */
69 [ - + ]: 9 : if (conn->Pfdebug == NULL)
70 : 0 : return;
71 : 9 : conn->traceFlags = flags;
72 : : }
73 : :
74 : : /*
75 : : * Print the current time, with microseconds, into a caller-supplied
76 : : * buffer.
77 : : * Cribbed from get_formatted_log_time, but much simpler.
78 : : */
79 : : static void
80 : 0 : pqTraceFormatTimestamp(char *timestr, size_t ts_len)
81 : : {
82 : : struct timeval tval;
83 : : time_t now;
84 : : struct tm tmbuf;
85 : :
86 : 0 : gettimeofday(&tval, NULL);
87 : :
88 : : /*
89 : : * MSVC's implementation of timeval uses a long for tv_sec, however,
90 : : * localtime() expects a time_t pointer. Here we'll assign tv_sec to a
91 : : * local time_t variable so that we pass localtime() the correct pointer
92 : : * type.
93 : : */
94 : 0 : now = tval.tv_sec;
95 : 0 : strftime(timestr, ts_len,
96 : : "%Y-%m-%d %H:%M:%S",
97 : 0 : localtime_r(&now, &tmbuf));
98 : : /* append microseconds */
99 : 0 : snprintf(timestr + strlen(timestr), ts_len - strlen(timestr),
100 : 0 : ".%06u", (unsigned int) (tval.tv_usec));
101 : 0 : }
102 : :
103 : : /*
104 : : * pqTraceOutputByte1: output a 1-char message to the log
105 : : */
106 : : static void
107 : 155 : pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor)
108 : : {
109 : 155 : const char *v = data + *cursor;
110 : :
111 : : /*
112 : : * Show non-printable data in hex format, including the terminating \0
113 : : * that completes ErrorResponse and NoticeResponse messages.
114 : : */
115 [ + + ]: 155 : if (!isprint((unsigned char) *v))
116 : 10 : fprintf(pfdebug, " \\x%02x", (unsigned char) *v);
117 : : else
118 : 145 : fprintf(pfdebug, " %c", *v);
119 : 155 : *cursor += 1;
120 : 155 : }
121 : :
122 : : /*
123 : : * pqTraceOutputInt16: output a 2-byte integer message to the log
124 : : */
125 : : static int
126 : 348 : pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor)
127 : : {
128 : : uint16 tmp;
129 : : int result;
130 : :
131 : 348 : memcpy(&tmp, data + *cursor, 2);
132 : 348 : *cursor += 2;
133 : 348 : result = (int) pg_ntoh16(tmp);
134 : 348 : fprintf(pfdebug, " %d", result);
135 : :
136 : 348 : return result;
137 : : }
138 : :
139 : : /*
140 : : * pqTraceOutputInt32: output a 4-byte integer message to the log
141 : : *
142 : : * If 'suppress' is true, print a literal NNNN instead of the actual number.
143 : : */
144 : : static int
145 : 195 : pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress)
146 : : {
147 : : int result;
148 : :
149 : 195 : memcpy(&result, data + *cursor, 4);
150 : 195 : *cursor += 4;
151 : 195 : result = (int) pg_ntoh32(result);
152 [ + + ]: 195 : if (suppress)
153 : 74 : fprintf(pfdebug, " NNNN");
154 : : else
155 : 121 : fprintf(pfdebug, " %d", result);
156 : :
157 : 195 : return result;
158 : : }
159 : :
160 : : /*
161 : : * pqTraceOutputString: output a string message to the log
162 : : *
163 : : * If 'suppress' is true, print a literal "SSSS" instead of the actual string.
164 : : */
165 : : static void
166 : 373 : pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
167 : : {
168 : : int len;
169 : :
170 [ + + ]: 373 : if (suppress)
171 : : {
172 : 30 : fprintf(pfdebug, " \"SSSS\"");
173 : 30 : *cursor += strlen(data + *cursor) + 1;
174 : : }
175 : : else
176 : : {
177 : 343 : len = fprintf(pfdebug, " \"%s\"", data + *cursor);
178 : :
179 : : /*
180 : : * This is a null-terminated string. So add 1 after subtracting 3
181 : : * which is the double quotes and space length from len.
182 : : */
183 : 343 : *cursor += (len - 3 + 1);
184 : : }
185 : 373 : }
186 : :
187 : : /*
188 : : * pqTraceOutputNchar: output a string of exactly len bytes message to the log
189 : : *
190 : : * If 'suppress' is true, print a literal 'BBBB' instead of the actual bytes.
191 : : */
192 : : static void
193 : 53 : pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
194 : : {
195 : : int i,
196 : : next; /* first char not yet printed */
197 : 53 : const char *v = data + *cursor;
198 : :
199 [ - + ]: 53 : if (suppress)
200 : : {
201 : 0 : fprintf(pfdebug, " 'BBBB'");
202 : 0 : *cursor += len;
203 : 0 : return;
204 : : }
205 : :
206 : 53 : fprintf(pfdebug, " \'");
207 : :
208 [ + + ]: 774 : for (next = i = 0; i < len; ++i)
209 : : {
210 [ + - ]: 721 : if (isprint((unsigned char) v[i]))
211 : 721 : continue;
212 : : else
213 : : {
214 : 0 : fwrite(v + next, 1, i - next, pfdebug);
215 : 0 : fprintf(pfdebug, "\\x%02x", (unsigned char) v[i]);
216 : 0 : next = i + 1;
217 : : }
218 : : }
219 [ + - ]: 53 : if (next < len)
220 : 53 : fwrite(v + next, 1, len - next, pfdebug);
221 : :
222 : 53 : fprintf(pfdebug, "\'");
223 : 53 : *cursor += len;
224 : : }
225 : :
226 : : /*
227 : : * Output functions by protocol message type
228 : : */
229 : :
230 : : static void
231 : 0 : pqTraceOutput_NotificationResponse(FILE *f, const char *message, int *cursor, bool regress)
232 : : {
233 : 0 : fprintf(f, "NotificationResponse\t");
234 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
235 : 0 : pqTraceOutputString(f, message, cursor, false);
236 : 0 : pqTraceOutputString(f, message, cursor, false);
237 : 0 : }
238 : :
239 : : static void
240 : 36 : pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
241 : : {
242 : : int nparams;
243 : :
244 : 36 : fprintf(f, "Bind\t");
245 : 36 : pqTraceOutputString(f, message, cursor, false);
246 : 36 : pqTraceOutputString(f, message, cursor, false);
247 : 36 : nparams = pqTraceOutputInt16(f, message, cursor);
248 : :
249 [ - + ]: 36 : for (int i = 0; i < nparams; i++)
250 : 0 : pqTraceOutputInt16(f, message, cursor);
251 : :
252 : 36 : nparams = pqTraceOutputInt16(f, message, cursor);
253 : :
254 [ + + ]: 47 : for (int i = 0; i < nparams; i++)
255 : : {
256 : : int nbytes;
257 : :
258 : 11 : nbytes = pqTraceOutputInt32(f, message, cursor, false);
259 [ - + ]: 11 : if (nbytes == -1)
260 : 0 : continue;
261 : 11 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
262 : : }
263 : :
264 : 36 : nparams = pqTraceOutputInt16(f, message, cursor);
265 [ + + ]: 72 : for (int i = 0; i < nparams; i++)
266 : 36 : pqTraceOutputInt16(f, message, cursor);
267 : 36 : }
268 : :
269 : : static void
270 : 4 : pqTraceOutput_Close(FILE *f, const char *message, int *cursor)
271 : : {
272 : 4 : fprintf(f, "Close\t");
273 : 4 : pqTraceOutputByte1(f, message, cursor);
274 : 4 : pqTraceOutputString(f, message, cursor, false);
275 : 4 : }
276 : :
277 : : static void
278 : 37 : pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
279 : : {
280 : 37 : fprintf(f, "CommandComplete\t");
281 : 37 : pqTraceOutputString(f, message, cursor, false);
282 : 37 : }
283 : :
284 : : static void
285 : 0 : pqTraceOutput_CopyData(FILE *f, const char *message, int *cursor, int length,
286 : : bool suppress)
287 : : {
288 : 0 : fprintf(f, "CopyData\t");
289 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, suppress);
290 : 0 : }
291 : :
292 : : static void
293 : 42 : pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
294 : : {
295 : : int nfields;
296 : : int len;
297 : : int i;
298 : :
299 : 42 : fprintf(f, "DataRow\t");
300 : 42 : nfields = pqTraceOutputInt16(f, message, cursor);
301 [ + + ]: 84 : for (i = 0; i < nfields; i++)
302 : : {
303 : 42 : len = pqTraceOutputInt32(f, message, cursor, false);
304 [ - + ]: 42 : if (len == -1)
305 : 0 : continue;
306 : 42 : pqTraceOutputNchar(f, len, message, cursor, false);
307 : : }
308 : 42 : }
309 : :
310 : : static void
311 : 40 : pqTraceOutput_Describe(FILE *f, const char *message, int *cursor)
312 : : {
313 : 40 : fprintf(f, "Describe\t");
314 : 40 : pqTraceOutputByte1(f, message, cursor);
315 : 40 : pqTraceOutputString(f, message, cursor, false);
316 : 40 : }
317 : :
318 : : /* shared code NoticeResponse / ErrorResponse */
319 : : static void
320 : 10 : pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor,
321 : : bool regress)
322 : : {
323 : 10 : fprintf(f, "%s\t", type);
324 : : for (;;)
325 : 72 : {
326 : : char field;
327 : : bool suppress;
328 : :
329 : 82 : pqTraceOutputByte1(f, message, cursor);
330 : 82 : field = message[*cursor - 1];
331 [ + + ]: 82 : if (field == '\0')
332 : 10 : break;
333 : :
334 [ + - + + : 72 : suppress = regress && (field == 'L' || field == 'F' || field == 'R');
+ + + + ]
335 : 72 : pqTraceOutputString(f, message, cursor, suppress);
336 : : }
337 : 10 : }
338 : :
339 : : static void
340 : 7 : pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress)
341 : : {
342 : 7 : pqTraceOutputNR(f, "ErrorResponse", message, cursor, regress);
343 : 7 : }
344 : :
345 : : static void
346 : 3 : pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress)
347 : : {
348 : 3 : pqTraceOutputNR(f, "NoticeResponse", message, cursor, regress);
349 : 3 : }
350 : :
351 : : static void
352 : 36 : pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress)
353 : : {
354 : 36 : fprintf(f, "Execute\t");
355 : 36 : pqTraceOutputString(f, message, cursor, false);
356 : 36 : pqTraceOutputInt32(f, message, cursor, false);
357 : 36 : }
358 : :
359 : : static void
360 : 0 : pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor)
361 : : {
362 : 0 : fprintf(f, "CopyFail\t");
363 : 0 : pqTraceOutputString(f, message, cursor, false);
364 : 0 : }
365 : :
366 : : static void
367 : 0 : pqTraceOutput_GSSResponse(FILE *f, const char *message, int *cursor,
368 : : int length, bool regress)
369 : : {
370 : 0 : fprintf(f, "GSSResponse\t");
371 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
372 : 0 : }
373 : :
374 : : static void
375 : 0 : pqTraceOutput_PasswordMessage(FILE *f, const char *message, int *cursor)
376 : : {
377 : 0 : fprintf(f, "PasswordMessage\t");
378 : 0 : pqTraceOutputString(f, message, cursor, false);
379 : 0 : }
380 : :
381 : : static void
382 : 0 : pqTraceOutput_SASLInitialResponse(FILE *f, const char *message, int *cursor,
383 : : bool regress)
384 : : {
385 : : int initialResponse;
386 : :
387 : 0 : fprintf(f, "SASLInitialResponse\t");
388 : 0 : pqTraceOutputString(f, message, cursor, false);
389 : 0 : initialResponse = pqTraceOutputInt32(f, message, cursor, false);
390 [ # # ]: 0 : if (initialResponse != -1)
391 : 0 : pqTraceOutputNchar(f, initialResponse, message, cursor, regress);
392 : 0 : }
393 : :
394 : : static void
395 : 0 : pqTraceOutput_SASLResponse(FILE *f, const char *message, int *cursor,
396 : : int length, bool regress)
397 : : {
398 : 0 : fprintf(f, "SASLResponse\t");
399 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
400 : 0 : }
401 : :
402 : : static void
403 : 0 : pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regress)
404 : : {
405 : : int nfields;
406 : : int nbytes;
407 : :
408 : 0 : fprintf(f, "FunctionCall\t");
409 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
410 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
411 : :
412 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
413 : 0 : pqTraceOutputInt16(f, message, cursor);
414 : :
415 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
416 : :
417 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
418 : : {
419 : 0 : nbytes = pqTraceOutputInt32(f, message, cursor, false);
420 [ # # ]: 0 : if (nbytes == -1)
421 : 0 : continue;
422 : 0 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
423 : : }
424 : :
425 : 0 : pqTraceOutputInt16(f, message, cursor);
426 : 0 : }
427 : :
428 : : static void
429 : 0 : pqTraceOutput_CopyInResponse(FILE *f, const char *message, int *cursor)
430 : : {
431 : : int nfields;
432 : :
433 : 0 : fprintf(f, "CopyInResponse\t");
434 : 0 : pqTraceOutputByte1(f, message, cursor);
435 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
436 : :
437 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
438 : 0 : pqTraceOutputInt16(f, message, cursor);
439 : 0 : }
440 : :
441 : : static void
442 : 0 : pqTraceOutput_CopyOutResponse(FILE *f, const char *message, int *cursor)
443 : : {
444 : : int nfields;
445 : :
446 : 0 : fprintf(f, "CopyOutResponse\t");
447 : 0 : pqTraceOutputByte1(f, message, cursor);
448 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
449 : :
450 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
451 : 0 : pqTraceOutputInt16(f, message, cursor);
452 : 0 : }
453 : :
454 : : static void
455 : 0 : pqTraceOutput_BackendKeyData(FILE *f, const char *message, int *cursor, int length,
456 : : bool regress)
457 : : {
458 : 0 : fprintf(f, "BackendKeyData\t");
459 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
460 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
461 : 0 : }
462 : :
463 : : static void
464 : 36 : pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
465 : : {
466 : : int nparams;
467 : :
468 : 36 : fprintf(f, "Parse\t");
469 : 36 : pqTraceOutputString(f, message, cursor, false);
470 : 36 : pqTraceOutputString(f, message, cursor, false);
471 : 36 : nparams = pqTraceOutputInt16(f, message, cursor);
472 : :
473 [ + + ]: 45 : for (int i = 0; i < nparams; i++)
474 : 9 : pqTraceOutputInt32(f, message, cursor, regress);
475 : 36 : }
476 : :
477 : : static void
478 : 8 : pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
479 : : {
480 : 8 : fprintf(f, "Query\t");
481 : 8 : pqTraceOutputString(f, message, cursor, false);
482 : 8 : }
483 : :
484 : : static void
485 : 0 : pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor,
486 : : int length, bool suppress)
487 : : {
488 : 0 : int authType = 0;
489 : :
490 : 0 : memcpy(&authType, message + *cursor, 4);
491 : 0 : authType = (int) pg_ntoh32(authType);
492 : 0 : *cursor += 4;
493 [ # # # # : 0 : switch (authType)
# # # # #
# ]
494 : : {
495 : 0 : case AUTH_REQ_OK:
496 : 0 : fprintf(f, "AuthenticationOk");
497 : 0 : break;
498 : : /* AUTH_REQ_KRB4 not supported */
499 : : /* AUTH_REQ_KRB5 not supported */
500 : 0 : case AUTH_REQ_PASSWORD:
501 : 0 : fprintf(f, "AuthenticationCleartextPassword");
502 : 0 : break;
503 : : /* AUTH_REQ_CRYPT not supported */
504 : 0 : case AUTH_REQ_MD5:
505 : 0 : fprintf(f, "AuthenticationMD5Password");
506 : 0 : break;
507 : 0 : case AUTH_REQ_GSS:
508 : 0 : fprintf(f, "AuthenticationGSS");
509 : 0 : break;
510 : 0 : case AUTH_REQ_GSS_CONT:
511 : 0 : fprintf(f, "AuthenticationGSSContinue\t");
512 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
513 : : suppress);
514 : 0 : break;
515 : 0 : case AUTH_REQ_SSPI:
516 : 0 : fprintf(f, "AuthenticationSSPI");
517 : 0 : break;
518 : 0 : case AUTH_REQ_SASL:
519 : 0 : fprintf(f, "AuthenticationSASL\t");
520 [ # # ]: 0 : while (message[*cursor] != '\0')
521 : 0 : pqTraceOutputString(f, message, cursor, false);
522 : 0 : pqTraceOutputString(f, message, cursor, false);
523 : 0 : break;
524 : 0 : case AUTH_REQ_SASL_CONT:
525 : 0 : fprintf(f, "AuthenticationSASLContinue\t");
526 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
527 : : suppress);
528 : 0 : break;
529 : 0 : case AUTH_REQ_SASL_FIN:
530 : 0 : fprintf(f, "AuthenticationSASLFinal\t");
531 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
532 : : suppress);
533 : 0 : break;
534 : 0 : default:
535 : 0 : fprintf(f, "Unknown authentication message %d", authType);
536 : : }
537 : 0 : }
538 : :
539 : : static void
540 : 0 : pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor)
541 : : {
542 : 0 : fprintf(f, "ParameterStatus\t");
543 : 0 : pqTraceOutputString(f, message, cursor, false);
544 : 0 : pqTraceOutputString(f, message, cursor, false);
545 : 0 : }
546 : :
547 : : static void
548 : 1 : pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
549 : : {
550 : : int nfields;
551 : :
552 : 1 : fprintf(f, "ParameterDescription\t");
553 : 1 : nfields = pqTraceOutputInt16(f, message, cursor);
554 : :
555 [ + + ]: 2 : for (int i = 0; i < nfields; i++)
556 : 1 : pqTraceOutputInt32(f, message, cursor, regress);
557 : 1 : }
558 : :
559 : : static void
560 : 29 : pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
561 : : {
562 : : int nfields;
563 : :
564 : 29 : fprintf(f, "RowDescription\t");
565 : 29 : nfields = pqTraceOutputInt16(f, message, cursor);
566 : :
567 [ + + ]: 61 : for (int i = 0; i < nfields; i++)
568 : : {
569 : 32 : pqTraceOutputString(f, message, cursor, false);
570 : 32 : pqTraceOutputInt32(f, message, cursor, regress);
571 : 32 : pqTraceOutputInt16(f, message, cursor);
572 : 32 : pqTraceOutputInt32(f, message, cursor, regress);
573 : 32 : pqTraceOutputInt16(f, message, cursor);
574 : 32 : pqTraceOutputInt32(f, message, cursor, false);
575 : 32 : pqTraceOutputInt16(f, message, cursor);
576 : : }
577 : 29 : }
578 : :
579 : : static void
580 : 0 : pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
581 : : {
582 : : int nparams;
583 : :
584 : 0 : fprintf(f, "NegotiateProtocolVersion\t");
585 : 0 : pqTraceOutputInt32(f, message, cursor, false);
586 : 0 : nparams = pqTraceOutputInt32(f, message, cursor, false);
587 [ # # ]: 0 : for (int i = 0; i < nparams; i++)
588 : : {
589 : 0 : pqTraceOutputString(f, message, cursor, false);
590 : : }
591 : 0 : }
592 : :
593 : : static void
594 : 0 : pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
595 : : {
596 : : int len;
597 : :
598 : 0 : fprintf(f, "FunctionCallResponse\t");
599 : 0 : len = pqTraceOutputInt32(f, message, cursor, false);
600 [ # # ]: 0 : if (len != -1)
601 : 0 : pqTraceOutputNchar(f, len, message, cursor, false);
602 : 0 : }
603 : :
604 : : static void
605 : 0 : pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
606 : : {
607 : 0 : fprintf(f, "CopyBothResponse\t");
608 : 0 : pqTraceOutputByte1(f, message, cursor);
609 : :
610 [ # # ]: 0 : while (length > *cursor)
611 : 0 : pqTraceOutputInt16(f, message, cursor);
612 : 0 : }
613 : :
614 : : static void
615 : 29 : pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
616 : : {
617 : 29 : fprintf(f, "ReadyForQuery\t");
618 : 29 : pqTraceOutputByte1(f, message, cursor);
619 : 29 : }
620 : :
621 : : /*
622 : : * Print the given message to the trace output stream.
623 : : */
624 : : void
625 : 414 : pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
626 : : {
627 : : char id;
628 : : int length;
629 [ + + ]: 414 : char *prefix = toServer ? "F" : "B";
630 : 414 : int logCursor = 0;
631 : : bool regress;
632 : :
633 [ - + ]: 414 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
634 : : {
635 : : char timestr[128];
636 : :
637 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
638 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
639 : : }
640 : 414 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
641 : :
642 : 414 : id = message[logCursor++];
643 : :
644 : 414 : memcpy(&length, message + logCursor, 4);
645 : 414 : length = (int) pg_ntoh32(length);
646 : 414 : logCursor += 4;
647 : :
648 : : /*
649 : : * In regress mode, suppress the length of ErrorResponse and
650 : : * NoticeResponse. The F (file name), L (line number) and R (routine
651 : : * name) fields can change as server code is modified, and if their
652 : : * lengths differ from the originals, that would break tests.
653 : : */
654 [ + - + + : 414 : if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
+ + + + ]
655 : 10 : fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
656 : : else
657 : 404 : fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
658 : :
659 [ + + + - : 414 : switch (id)
+ - + - +
+ - - - -
+ - - + +
+ + - - +
+ + - - -
+ + - ]
660 : : {
661 : 31 : case PqMsg_ParseComplete:
662 : 31 : fprintf(conn->Pfdebug, "ParseComplete");
663 : : /* No message content */
664 : 31 : break;
665 : 29 : case PqMsg_BindComplete:
666 : 29 : fprintf(conn->Pfdebug, "BindComplete");
667 : : /* No message content */
668 : 29 : break;
669 : 4 : case PqMsg_CloseComplete:
670 : 4 : fprintf(conn->Pfdebug, "CloseComplete");
671 : : /* No message content */
672 : 4 : break;
673 : 0 : case PqMsg_NotificationResponse:
674 : 0 : pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
675 : 0 : break;
676 : 36 : case PqMsg_Bind:
677 : 36 : pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
678 : 36 : break;
679 : 0 : case PqMsg_CopyDone:
680 : 0 : fprintf(conn->Pfdebug, "CopyDone");
681 : : /* No message content */
682 : 0 : break;
683 : 41 : case PqMsg_CommandComplete:
684 : : /* Close(F) and CommandComplete(B) use the same identifier. */
685 : : Assert(PqMsg_Close == PqMsg_CommandComplete);
686 [ + + ]: 41 : if (toServer)
687 : 4 : pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
688 : : else
689 : 37 : pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
690 : 41 : break;
691 : 0 : case PqMsg_CopyData:
692 : 0 : pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
693 : : length, regress);
694 : 0 : break;
695 : 82 : case PqMsg_Describe:
696 : : /* Describe(F) and DataRow(B) use the same identifier. */
697 : : Assert(PqMsg_Describe == PqMsg_DataRow);
698 [ + + ]: 82 : if (toServer)
699 : 40 : pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
700 : : else
701 : 42 : pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
702 : 82 : break;
703 : 43 : case PqMsg_Execute:
704 : : /* Execute(F) and ErrorResponse(B) use the same identifier. */
705 : : Assert(PqMsg_Execute == PqMsg_ErrorResponse);
706 [ + + ]: 43 : if (toServer)
707 : 36 : pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
708 : : else
709 : 7 : pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
710 : 43 : break;
711 : 0 : case PqMsg_CopyFail:
712 : 0 : pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
713 : 0 : break;
714 : 0 : case PqMsg_GSSResponse:
715 : : Assert(PqMsg_GSSResponse == PqMsg_PasswordMessage);
716 : : Assert(PqMsg_GSSResponse == PqMsg_SASLInitialResponse);
717 : : Assert(PqMsg_GSSResponse == PqMsg_SASLResponse);
718 : :
719 : : /*
720 : : * These messages share a common type byte, so we discriminate by
721 : : * having the code store the auth type separately.
722 : : */
723 [ # # # # : 0 : switch (conn->current_auth_response)
# ]
724 : : {
725 : 0 : case AUTH_RESPONSE_GSS:
726 : 0 : pqTraceOutput_GSSResponse(conn->Pfdebug, message,
727 : : &logCursor, length, regress);
728 : 0 : break;
729 : 0 : case AUTH_RESPONSE_PASSWORD:
730 : 0 : pqTraceOutput_PasswordMessage(conn->Pfdebug, message,
731 : : &logCursor);
732 : 0 : break;
733 : 0 : case AUTH_RESPONSE_SASL_INITIAL:
734 : 0 : pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message,
735 : : &logCursor, regress);
736 : 0 : break;
737 : 0 : case AUTH_RESPONSE_SASL:
738 : 0 : pqTraceOutput_SASLResponse(conn->Pfdebug, message,
739 : : &logCursor, length, regress);
740 : 0 : break;
741 : 0 : default:
742 : 0 : fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
743 : 0 : break;
744 : : }
745 : 0 : conn->current_auth_response = '\0';
746 : 0 : break;
747 : 0 : case PqMsg_FunctionCall:
748 : 0 : pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
749 : 0 : break;
750 : 0 : case PqMsg_CopyInResponse:
751 : 0 : pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
752 : 0 : break;
753 : 7 : case PqMsg_Flush:
754 : : /* Flush(F) and CopyOutResponse(B) use the same identifier */
755 : : Assert(PqMsg_CopyOutResponse == PqMsg_Flush);
756 [ + - ]: 7 : if (toServer)
757 : 7 : fprintf(conn->Pfdebug, "Flush"); /* no message content */
758 : : else
759 : 0 : pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
760 : 7 : break;
761 : 0 : case PqMsg_EmptyQueryResponse:
762 : 0 : fprintf(conn->Pfdebug, "EmptyQueryResponse");
763 : : /* No message content */
764 : 0 : break;
765 : 0 : case PqMsg_BackendKeyData:
766 : 0 : pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor,
767 : : length, regress);
768 : 0 : break;
769 : 5 : case PqMsg_NoData:
770 : 5 : fprintf(conn->Pfdebug, "NoData");
771 : : /* No message content */
772 : 5 : break;
773 : 3 : case PqMsg_NoticeResponse:
774 : 3 : pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
775 : 3 : break;
776 : 36 : case PqMsg_Parse:
777 : 36 : pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
778 : 36 : break;
779 : 8 : case PqMsg_Query:
780 : 8 : pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
781 : 8 : break;
782 : 0 : case PqMsg_AuthenticationRequest:
783 : 0 : pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
784 : : length, regress);
785 : 0 : break;
786 : 0 : case PqMsg_PortalSuspended:
787 : 0 : fprintf(conn->Pfdebug, "PortalSuspended");
788 : : /* No message content */
789 : 0 : break;
790 : 21 : case PqMsg_Sync:
791 : : /* ParameterStatus(B) and Sync(F) use the same identifier */
792 : : Assert(PqMsg_ParameterStatus == PqMsg_Sync);
793 [ + - ]: 21 : if (toServer)
794 : 21 : fprintf(conn->Pfdebug, "Sync"); /* no message content */
795 : : else
796 : 0 : pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
797 : 21 : break;
798 : 1 : case PqMsg_ParameterDescription:
799 : 1 : pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
800 : 1 : break;
801 : 29 : case PqMsg_RowDescription:
802 : 29 : pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
803 : 29 : break;
804 : 0 : case PqMsg_NegotiateProtocolVersion:
805 : 0 : pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
806 : 0 : break;
807 : 0 : case PqMsg_FunctionCallResponse:
808 : 0 : pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
809 : 0 : break;
810 : 0 : case PqMsg_CopyBothResponse:
811 : 0 : pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
812 : 0 : break;
813 : 9 : case PqMsg_Terminate:
814 : 9 : fprintf(conn->Pfdebug, "Terminate");
815 : : /* No message content */
816 : 9 : break;
817 : 29 : case PqMsg_ReadyForQuery:
818 : 29 : pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
819 : 29 : break;
820 : 0 : default:
821 : 0 : fprintf(conn->Pfdebug, "Unknown message: %02x", id);
822 : 0 : break;
823 : : }
824 : :
825 : 414 : fputc('\n', conn->Pfdebug);
826 : :
827 : : /*
828 : : * Verify the printing routine did it right. Note that the one-byte
829 : : * message identifier is not included in the length, but our cursor does
830 : : * include it.
831 : : */
832 [ - + ]: 414 : if (logCursor - 1 != length)
833 : 0 : fprintf(conn->Pfdebug,
834 : : "mismatched message length: consumed %d, expected %d\n",
835 : : logCursor - 1, length);
836 : 414 : }
837 : :
838 : : /*
839 : : * Print special messages (those containing no type byte) to the trace output
840 : : * stream.
841 : : */
842 : : void
843 : 0 : pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
844 : : {
845 : : int length;
846 : : int version;
847 : : bool regress;
848 : 0 : int logCursor = 0;
849 : :
850 : 0 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
851 : :
852 [ # # ]: 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
853 : : {
854 : : char timestr[128];
855 : :
856 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
857 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
858 : : }
859 : :
860 : 0 : memcpy(&length, message + logCursor, 4);
861 : 0 : length = (int) pg_ntoh32(length);
862 : 0 : logCursor += 4;
863 : :
864 : 0 : fprintf(conn->Pfdebug, "F\t%d\t", length);
865 : :
866 [ # # ]: 0 : if (length < 8)
867 : : {
868 : 0 : fprintf(conn->Pfdebug, "Unknown message\n");
869 : 0 : return;
870 : : }
871 : :
872 : 0 : memcpy(&version, message + logCursor, 4);
873 : 0 : version = (int) pg_ntoh32(version);
874 : :
875 [ # # # # ]: 0 : if (version == CANCEL_REQUEST_CODE && length >= 16)
876 : : {
877 : 0 : fprintf(conn->Pfdebug, "CancelRequest\t");
878 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
879 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
880 : 0 : pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
881 : 0 : pqTraceOutputNchar(conn->Pfdebug, length - logCursor, message,
882 : : &logCursor, regress);
883 : : }
884 [ # # ]: 0 : else if (version == NEGOTIATE_SSL_CODE)
885 : : {
886 : 0 : fprintf(conn->Pfdebug, "SSLRequest\t");
887 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
888 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
889 : : }
890 [ # # ]: 0 : else if (version == NEGOTIATE_GSS_CODE)
891 : : {
892 : 0 : fprintf(conn->Pfdebug, "GSSENCRequest\t");
893 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
894 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
895 : : }
896 : : else
897 : : {
898 : 0 : fprintf(conn->Pfdebug, "StartupMessage\t");
899 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
900 : 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
901 [ # # ]: 0 : while (message[logCursor] != '\0')
902 : : {
903 : : /* XXX should we suppress anything in regress mode? */
904 : 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
905 : 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
906 : : }
907 : : }
908 : :
909 : 0 : fputc('\n', conn->Pfdebug);
910 : : }
911 : :
912 : : /*
913 : : * Trace a single-byte backend response received for a known request
914 : : * type the frontend previously sent. Only useful for the simplest of
915 : : * FE/BE interaction workflows such as SSL/GSS encryption requests.
916 : : */
917 : : void
918 : 0 : pqTraceOutputCharResponse(PGconn *conn, const char *responseType,
919 : : char response)
920 : : {
921 [ # # ]: 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
922 : : {
923 : : char timestr[128];
924 : :
925 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
926 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
927 : : }
928 : :
929 : 0 : fprintf(conn->Pfdebug, "B\t1\t%s\t %c\n", responseType, response);
930 : 0 : }
|
