Line data Source code
1 : /*-------------------------------------------------------------------------
2 : *
3 : * fe-trace.c
4 : * functions for libpq protocol tracing
5 : *
6 : * Portions Copyright (c) 1996-2025, 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 18 : PQtrace(PGconn *conn, FILE *debug_port)
36 : {
37 18 : if (conn == NULL)
38 0 : return;
39 18 : PQuntrace(conn);
40 18 : if (debug_port == NULL)
41 0 : return;
42 :
43 18 : conn->Pfdebug = debug_port;
44 18 : conn->traceFlags = 0;
45 : }
46 :
47 : /* Disable tracing */
48 : void
49 18 : PQuntrace(PGconn *conn)
50 : {
51 18 : if (conn == NULL)
52 0 : return;
53 18 : if (conn->Pfdebug)
54 : {
55 0 : fflush(conn->Pfdebug);
56 0 : conn->Pfdebug = NULL;
57 : }
58 :
59 18 : conn->traceFlags = 0;
60 : }
61 :
62 : /* Set flags for current tracing session */
63 : void
64 18 : PQsetTraceFlags(PGconn *conn, int flags)
65 : {
66 18 : if (conn == NULL)
67 0 : return;
68 : /* If PQtrace() failed, do nothing. */
69 18 : if (conn->Pfdebug == NULL)
70 0 : return;
71 18 : 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 310 : pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor)
108 : {
109 310 : 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 310 : if (!isprint((unsigned char) *v))
116 20 : fprintf(pfdebug, " \\x%02x", *v);
117 : else
118 290 : fprintf(pfdebug, " %c", *v);
119 310 : *cursor += 1;
120 310 : }
121 :
122 : /*
123 : * pqTraceOutputInt16: output a 2-byte integer message to the log
124 : */
125 : static int
126 696 : pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor)
127 : {
128 : uint16 tmp;
129 : int result;
130 :
131 696 : memcpy(&tmp, data + *cursor, 2);
132 696 : *cursor += 2;
133 696 : result = (int) pg_ntoh16(tmp);
134 696 : fprintf(pfdebug, " %d", result);
135 :
136 696 : 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 390 : pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress)
146 : {
147 : int result;
148 :
149 390 : memcpy(&result, data + *cursor, 4);
150 390 : *cursor += 4;
151 390 : result = (int) pg_ntoh32(result);
152 390 : if (suppress)
153 148 : fprintf(pfdebug, " NNNN");
154 : else
155 242 : fprintf(pfdebug, " %d", result);
156 :
157 390 : 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 746 : pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
167 : {
168 : int len;
169 :
170 746 : if (suppress)
171 : {
172 60 : fprintf(pfdebug, " \"SSSS\"");
173 60 : *cursor += strlen(data + *cursor) + 1;
174 : }
175 : else
176 : {
177 686 : 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 686 : *cursor += (len - 3 + 1);
184 : }
185 746 : }
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 106 : pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
194 : {
195 : int i,
196 : next; /* first char not yet printed */
197 106 : const char *v = data + *cursor;
198 :
199 106 : if (suppress)
200 : {
201 0 : fprintf(pfdebug, " 'BBBB'");
202 0 : *cursor += len;
203 0 : return;
204 : }
205 :
206 106 : fprintf(pfdebug, " \'");
207 :
208 1548 : for (next = i = 0; i < len; ++i)
209 : {
210 1442 : if (isprint((unsigned char) v[i]))
211 1442 : continue;
212 : else
213 : {
214 0 : fwrite(v + next, 1, i - next, pfdebug);
215 0 : fprintf(pfdebug, "\\x%02x", v[i]);
216 0 : next = i + 1;
217 : }
218 : }
219 106 : if (next < len)
220 106 : fwrite(v + next, 1, len - next, pfdebug);
221 :
222 106 : fprintf(pfdebug, "\'");
223 106 : *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 72 : pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
241 : {
242 : int nparams;
243 :
244 72 : fprintf(f, "Bind\t");
245 72 : pqTraceOutputString(f, message, cursor, false);
246 72 : pqTraceOutputString(f, message, cursor, false);
247 72 : nparams = pqTraceOutputInt16(f, message, cursor);
248 :
249 72 : for (int i = 0; i < nparams; i++)
250 0 : pqTraceOutputInt16(f, message, cursor);
251 :
252 72 : nparams = pqTraceOutputInt16(f, message, cursor);
253 :
254 94 : for (int i = 0; i < nparams; i++)
255 : {
256 : int nbytes;
257 :
258 22 : nbytes = pqTraceOutputInt32(f, message, cursor, false);
259 22 : if (nbytes == -1)
260 0 : continue;
261 22 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
262 : }
263 :
264 72 : nparams = pqTraceOutputInt16(f, message, cursor);
265 144 : for (int i = 0; i < nparams; i++)
266 72 : pqTraceOutputInt16(f, message, cursor);
267 72 : }
268 :
269 : static void
270 8 : pqTraceOutput_Close(FILE *f, const char *message, int *cursor)
271 : {
272 8 : fprintf(f, "Close\t");
273 8 : pqTraceOutputByte1(f, message, cursor);
274 8 : pqTraceOutputString(f, message, cursor, false);
275 8 : }
276 :
277 : static void
278 74 : pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
279 : {
280 74 : fprintf(f, "CommandComplete\t");
281 74 : pqTraceOutputString(f, message, cursor, false);
282 74 : }
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 84 : pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
294 : {
295 : int nfields;
296 : int len;
297 : int i;
298 :
299 84 : fprintf(f, "DataRow\t");
300 84 : nfields = pqTraceOutputInt16(f, message, cursor);
301 168 : for (i = 0; i < nfields; i++)
302 : {
303 84 : len = pqTraceOutputInt32(f, message, cursor, false);
304 84 : if (len == -1)
305 0 : continue;
306 84 : pqTraceOutputNchar(f, len, message, cursor, false);
307 : }
308 84 : }
309 :
310 : static void
311 80 : pqTraceOutput_Describe(FILE *f, const char *message, int *cursor)
312 : {
313 80 : fprintf(f, "Describe\t");
314 80 : pqTraceOutputByte1(f, message, cursor);
315 80 : pqTraceOutputString(f, message, cursor, false);
316 80 : }
317 :
318 : /* shared code NoticeResponse / ErrorResponse */
319 : static void
320 20 : pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor,
321 : bool regress)
322 : {
323 20 : fprintf(f, "%s\t", type);
324 : for (;;)
325 144 : {
326 : char field;
327 : bool suppress;
328 :
329 164 : pqTraceOutputByte1(f, message, cursor);
330 164 : field = message[*cursor - 1];
331 164 : if (field == '\0')
332 20 : break;
333 :
334 144 : suppress = regress && (field == 'L' || field == 'F' || field == 'R');
335 144 : pqTraceOutputString(f, message, cursor, suppress);
336 : }
337 20 : }
338 :
339 : static void
340 14 : pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress)
341 : {
342 14 : pqTraceOutputNR(f, "ErrorResponse", message, cursor, regress);
343 14 : }
344 :
345 : static void
346 6 : pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress)
347 : {
348 6 : pqTraceOutputNR(f, "NoticeResponse", message, cursor, regress);
349 6 : }
350 :
351 : static void
352 72 : pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress)
353 : {
354 72 : fprintf(f, "Execute\t");
355 72 : pqTraceOutputString(f, message, cursor, false);
356 72 : pqTraceOutputInt32(f, message, cursor, false);
357 72 : }
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, bool regress)
456 : {
457 0 : fprintf(f, "BackendKeyData\t");
458 0 : pqTraceOutputInt32(f, message, cursor, regress);
459 0 : pqTraceOutputInt32(f, message, cursor, regress);
460 0 : }
461 :
462 : static void
463 72 : pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
464 : {
465 : int nparams;
466 :
467 72 : fprintf(f, "Parse\t");
468 72 : pqTraceOutputString(f, message, cursor, false);
469 72 : pqTraceOutputString(f, message, cursor, false);
470 72 : nparams = pqTraceOutputInt16(f, message, cursor);
471 :
472 90 : for (int i = 0; i < nparams; i++)
473 18 : pqTraceOutputInt32(f, message, cursor, regress);
474 72 : }
475 :
476 : static void
477 16 : pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
478 : {
479 16 : fprintf(f, "Query\t");
480 16 : pqTraceOutputString(f, message, cursor, false);
481 16 : }
482 :
483 : static void
484 0 : pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor,
485 : int length, bool suppress)
486 : {
487 0 : int authType = 0;
488 :
489 0 : memcpy(&authType, message + *cursor, 4);
490 0 : authType = (int) pg_ntoh32(authType);
491 0 : *cursor += 4;
492 0 : switch (authType)
493 : {
494 0 : case AUTH_REQ_OK:
495 0 : fprintf(f, "AuthenticationOk");
496 0 : break;
497 : /* AUTH_REQ_KRB4 not supported */
498 : /* AUTH_REQ_KRB5 not supported */
499 0 : case AUTH_REQ_PASSWORD:
500 0 : fprintf(f, "AuthenticationCleartextPassword");
501 0 : break;
502 : /* AUTH_REQ_CRYPT not supported */
503 0 : case AUTH_REQ_MD5:
504 0 : fprintf(f, "AuthenticationMD5Password");
505 0 : break;
506 0 : case AUTH_REQ_GSS:
507 0 : fprintf(f, "AuthenticationGSS");
508 0 : break;
509 0 : case AUTH_REQ_GSS_CONT:
510 0 : fprintf(f, "AuthenticationGSSContinue\t");
511 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
512 : suppress);
513 0 : break;
514 0 : case AUTH_REQ_SSPI:
515 0 : fprintf(f, "AuthenticationSSPI");
516 0 : break;
517 0 : case AUTH_REQ_SASL:
518 0 : fprintf(f, "AuthenticationSASL\t");
519 0 : while (message[*cursor] != '\0')
520 0 : pqTraceOutputString(f, message, cursor, false);
521 0 : pqTraceOutputString(f, message, cursor, false);
522 0 : break;
523 0 : case AUTH_REQ_SASL_CONT:
524 0 : fprintf(f, "AuthenticationSASLContinue\t");
525 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
526 : suppress);
527 0 : break;
528 0 : case AUTH_REQ_SASL_FIN:
529 0 : fprintf(f, "AuthenticationSASLFinal\t");
530 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
531 : suppress);
532 0 : break;
533 0 : default:
534 0 : fprintf(f, "Unknown authentication message %d", authType);
535 : }
536 0 : }
537 :
538 : static void
539 0 : pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor)
540 : {
541 0 : fprintf(f, "ParameterStatus\t");
542 0 : pqTraceOutputString(f, message, cursor, false);
543 0 : pqTraceOutputString(f, message, cursor, false);
544 0 : }
545 :
546 : static void
547 2 : pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
548 : {
549 : int nfields;
550 :
551 2 : fprintf(f, "ParameterDescription\t");
552 2 : nfields = pqTraceOutputInt16(f, message, cursor);
553 :
554 4 : for (int i = 0; i < nfields; i++)
555 2 : pqTraceOutputInt32(f, message, cursor, regress);
556 2 : }
557 :
558 : static void
559 58 : pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
560 : {
561 : int nfields;
562 :
563 58 : fprintf(f, "RowDescription\t");
564 58 : nfields = pqTraceOutputInt16(f, message, cursor);
565 :
566 122 : for (int i = 0; i < nfields; i++)
567 : {
568 64 : pqTraceOutputString(f, message, cursor, false);
569 64 : pqTraceOutputInt32(f, message, cursor, regress);
570 64 : pqTraceOutputInt16(f, message, cursor);
571 64 : pqTraceOutputInt32(f, message, cursor, regress);
572 64 : pqTraceOutputInt16(f, message, cursor);
573 64 : pqTraceOutputInt32(f, message, cursor, false);
574 64 : pqTraceOutputInt16(f, message, cursor);
575 : }
576 58 : }
577 :
578 : static void
579 0 : pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
580 : {
581 : int nparams;
582 :
583 0 : fprintf(f, "NegotiateProtocolVersion\t");
584 0 : pqTraceOutputInt32(f, message, cursor, false);
585 0 : nparams = pqTraceOutputInt32(f, message, cursor, false);
586 0 : for (int i = 0; i < nparams; i++)
587 : {
588 0 : pqTraceOutputString(f, message, cursor, false);
589 : }
590 0 : }
591 :
592 : static void
593 0 : pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
594 : {
595 : int len;
596 :
597 0 : fprintf(f, "FunctionCallResponse\t");
598 0 : len = pqTraceOutputInt32(f, message, cursor, false);
599 0 : if (len != -1)
600 0 : pqTraceOutputNchar(f, len, message, cursor, false);
601 0 : }
602 :
603 : static void
604 0 : pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
605 : {
606 0 : fprintf(f, "CopyBothResponse\t");
607 0 : pqTraceOutputByte1(f, message, cursor);
608 :
609 0 : while (length > *cursor)
610 0 : pqTraceOutputInt16(f, message, cursor);
611 0 : }
612 :
613 : static void
614 58 : pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
615 : {
616 58 : fprintf(f, "ReadyForQuery\t");
617 58 : pqTraceOutputByte1(f, message, cursor);
618 58 : }
619 :
620 : /*
621 : * Print the given message to the trace output stream.
622 : */
623 : void
624 828 : pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
625 : {
626 : char id;
627 : int length;
628 828 : char *prefix = toServer ? "F" : "B";
629 828 : int logCursor = 0;
630 : bool regress;
631 :
632 828 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
633 : {
634 : char timestr[128];
635 :
636 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
637 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
638 : }
639 828 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
640 :
641 828 : id = message[logCursor++];
642 :
643 828 : memcpy(&length, message + logCursor, 4);
644 828 : length = (int) pg_ntoh32(length);
645 828 : logCursor += 4;
646 :
647 : /*
648 : * In regress mode, suppress the length of ErrorResponse and
649 : * NoticeResponse. The F (file name), L (line number) and R (routine
650 : * name) fields can change as server code is modified, and if their
651 : * lengths differ from the originals, that would break tests.
652 : */
653 828 : if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
654 20 : fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
655 : else
656 808 : fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
657 :
658 828 : switch (id)
659 : {
660 62 : case PqMsg_ParseComplete:
661 62 : fprintf(conn->Pfdebug, "ParseComplete");
662 : /* No message content */
663 62 : break;
664 58 : case PqMsg_BindComplete:
665 58 : fprintf(conn->Pfdebug, "BindComplete");
666 : /* No message content */
667 58 : break;
668 8 : case PqMsg_CloseComplete:
669 8 : fprintf(conn->Pfdebug, "CloseComplete");
670 : /* No message content */
671 8 : break;
672 0 : case PqMsg_NotificationResponse:
673 0 : pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
674 0 : break;
675 72 : case PqMsg_Bind:
676 72 : pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
677 72 : break;
678 0 : case PqMsg_CopyDone:
679 0 : fprintf(conn->Pfdebug, "CopyDone");
680 : /* No message content */
681 0 : break;
682 82 : case PqMsg_CommandComplete:
683 : /* Close(F) and CommandComplete(B) use the same identifier. */
684 : Assert(PqMsg_Close == PqMsg_CommandComplete);
685 82 : if (toServer)
686 8 : pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
687 : else
688 74 : pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
689 82 : break;
690 0 : case PqMsg_CopyData:
691 0 : pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
692 : length, regress);
693 0 : break;
694 164 : case PqMsg_Describe:
695 : /* Describe(F) and DataRow(B) use the same identifier. */
696 : Assert(PqMsg_Describe == PqMsg_DataRow);
697 164 : if (toServer)
698 80 : pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
699 : else
700 84 : pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
701 164 : break;
702 86 : case PqMsg_Execute:
703 : /* Execute(F) and ErrorResponse(B) use the same identifier. */
704 : Assert(PqMsg_Execute == PqMsg_ErrorResponse);
705 86 : if (toServer)
706 72 : pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
707 : else
708 14 : pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
709 86 : break;
710 0 : case PqMsg_CopyFail:
711 0 : pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
712 0 : break;
713 0 : case PqMsg_GSSResponse:
714 : Assert(PqMsg_GSSResponse == PqMsg_PasswordMessage);
715 : Assert(PqMsg_GSSResponse == PqMsg_SASLInitialResponse);
716 : Assert(PqMsg_GSSResponse == PqMsg_SASLResponse);
717 :
718 : /*
719 : * These messages share a common type byte, so we discriminate by
720 : * having the code store the auth type separately.
721 : */
722 0 : switch (conn->current_auth_response)
723 : {
724 0 : case AUTH_RESPONSE_GSS:
725 0 : pqTraceOutput_GSSResponse(conn->Pfdebug, message,
726 : &logCursor, length, regress);
727 0 : break;
728 0 : case AUTH_RESPONSE_PASSWORD:
729 0 : pqTraceOutput_PasswordMessage(conn->Pfdebug, message,
730 : &logCursor);
731 0 : break;
732 0 : case AUTH_RESPONSE_SASL_INITIAL:
733 0 : pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message,
734 : &logCursor, regress);
735 0 : break;
736 0 : case AUTH_RESPONSE_SASL:
737 0 : pqTraceOutput_SASLResponse(conn->Pfdebug, message,
738 : &logCursor, length, regress);
739 0 : break;
740 0 : default:
741 0 : fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
742 0 : break;
743 : }
744 0 : conn->current_auth_response = '\0';
745 0 : break;
746 0 : case PqMsg_FunctionCall:
747 0 : pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
748 0 : break;
749 0 : case PqMsg_CopyInResponse:
750 0 : pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
751 0 : break;
752 14 : case PqMsg_Flush:
753 : /* Flush(F) and CopyOutResponse(B) use the same identifier */
754 : Assert(PqMsg_CopyOutResponse == PqMsg_Flush);
755 14 : if (toServer)
756 14 : fprintf(conn->Pfdebug, "Flush"); /* no message content */
757 : else
758 0 : pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
759 14 : break;
760 0 : case PqMsg_EmptyQueryResponse:
761 0 : fprintf(conn->Pfdebug, "EmptyQueryResponse");
762 : /* No message content */
763 0 : break;
764 0 : case PqMsg_BackendKeyData:
765 0 : pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
766 0 : break;
767 10 : case PqMsg_NoData:
768 10 : fprintf(conn->Pfdebug, "NoData");
769 : /* No message content */
770 10 : break;
771 6 : case PqMsg_NoticeResponse:
772 6 : pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
773 6 : break;
774 72 : case PqMsg_Parse:
775 72 : pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
776 72 : break;
777 16 : case PqMsg_Query:
778 16 : pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
779 16 : break;
780 0 : case PqMsg_AuthenticationRequest:
781 0 : pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
782 : length, regress);
783 0 : break;
784 0 : case PqMsg_PortalSuspended:
785 0 : fprintf(conn->Pfdebug, "PortalSuspended");
786 : /* No message content */
787 0 : break;
788 42 : case PqMsg_Sync:
789 : /* ParameterStatus(B) and Sync(F) use the same identifier */
790 : Assert(PqMsg_ParameterStatus == PqMsg_Sync);
791 42 : if (toServer)
792 42 : fprintf(conn->Pfdebug, "Sync"); /* no message content */
793 : else
794 0 : pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
795 42 : break;
796 2 : case PqMsg_ParameterDescription:
797 2 : pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
798 2 : break;
799 58 : case PqMsg_RowDescription:
800 58 : pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
801 58 : break;
802 0 : case PqMsg_NegotiateProtocolVersion:
803 0 : pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
804 0 : break;
805 0 : case PqMsg_FunctionCallResponse:
806 0 : pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
807 0 : break;
808 0 : case PqMsg_CopyBothResponse:
809 0 : pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
810 0 : break;
811 18 : case PqMsg_Terminate:
812 18 : fprintf(conn->Pfdebug, "Terminate");
813 : /* No message content */
814 18 : break;
815 58 : case PqMsg_ReadyForQuery:
816 58 : pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
817 58 : break;
818 0 : default:
819 0 : fprintf(conn->Pfdebug, "Unknown message: %02x", id);
820 0 : break;
821 : }
822 :
823 828 : fputc('\n', conn->Pfdebug);
824 :
825 : /*
826 : * Verify the printing routine did it right. Note that the one-byte
827 : * message identifier is not included in the length, but our cursor does
828 : * include it.
829 : */
830 828 : if (logCursor - 1 != length)
831 0 : fprintf(conn->Pfdebug,
832 : "mismatched message length: consumed %d, expected %d\n",
833 : logCursor - 1, length);
834 828 : }
835 :
836 : /*
837 : * Print special messages (those containing no type byte) to the trace output
838 : * stream.
839 : */
840 : void
841 0 : pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
842 : {
843 : int length;
844 : int version;
845 : bool regress;
846 0 : int logCursor = 0;
847 :
848 0 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
849 :
850 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
851 : {
852 : char timestr[128];
853 :
854 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
855 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
856 : }
857 :
858 0 : memcpy(&length, message + logCursor, 4);
859 0 : length = (int) pg_ntoh32(length);
860 0 : logCursor += 4;
861 :
862 0 : fprintf(conn->Pfdebug, "F\t%d\t", length);
863 :
864 0 : if (length < 8)
865 : {
866 0 : fprintf(conn->Pfdebug, "Unknown message\n");
867 0 : return;
868 : }
869 :
870 0 : memcpy(&version, message + logCursor, 4);
871 0 : version = (int) pg_ntoh32(version);
872 :
873 0 : if (version == CANCEL_REQUEST_CODE && length >= 16)
874 : {
875 0 : fprintf(conn->Pfdebug, "CancelRequest\t");
876 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
877 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
878 0 : pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
879 0 : pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
880 : }
881 0 : else if (version == NEGOTIATE_SSL_CODE)
882 : {
883 0 : fprintf(conn->Pfdebug, "SSLRequest\t");
884 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
885 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
886 : }
887 0 : else if (version == NEGOTIATE_GSS_CODE)
888 : {
889 0 : fprintf(conn->Pfdebug, "GSSENCRequest\t");
890 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
891 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
892 : }
893 : else
894 : {
895 0 : fprintf(conn->Pfdebug, "StartupMessage\t");
896 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
897 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
898 0 : while (message[logCursor] != '\0')
899 : {
900 : /* XXX should we suppress anything in regress mode? */
901 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
902 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
903 : }
904 : }
905 :
906 0 : fputc('\n', conn->Pfdebug);
907 : }
908 :
909 : /*
910 : * Trace a single-byte backend response received for a known request
911 : * type the frontend previously sent. Only useful for the simplest of
912 : * FE/BE interaction workflows such as SSL/GSS encryption requests.
913 : */
914 : void
915 0 : pqTraceOutputCharResponse(PGconn *conn, const char *responseType,
916 : char response)
917 : {
918 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
919 : {
920 : char timestr[128];
921 :
922 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
923 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
924 : }
925 :
926 0 : fprintf(conn->Pfdebug, "B\t1\t%s\t %c\n", responseType, response);
927 0 : }
|
