Line data Source code
1 : /*-------------------------------------------------------------------------
2 : *
3 : * fe-trace.c
4 : * functions for libpq protocol tracing
5 : *
6 : * Portions Copyright (c) 1996-2024, 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 0 : fprintf(f, "NegotiateProtocolVersion\t");
582 0 : pqTraceOutputInt32(f, message, cursor, false);
583 0 : pqTraceOutputInt32(f, message, cursor, false);
584 0 : }
585 :
586 : static void
587 0 : pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
588 : {
589 : int len;
590 :
591 0 : fprintf(f, "FunctionCallResponse\t");
592 0 : len = pqTraceOutputInt32(f, message, cursor, false);
593 0 : if (len != -1)
594 0 : pqTraceOutputNchar(f, len, message, cursor, false);
595 0 : }
596 :
597 : static void
598 0 : pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
599 : {
600 0 : fprintf(f, "CopyBothResponse\t");
601 0 : pqTraceOutputByte1(f, message, cursor);
602 :
603 0 : while (length > *cursor)
604 0 : pqTraceOutputInt16(f, message, cursor);
605 0 : }
606 :
607 : static void
608 58 : pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
609 : {
610 58 : fprintf(f, "ReadyForQuery\t");
611 58 : pqTraceOutputByte1(f, message, cursor);
612 58 : }
613 :
614 : /*
615 : * Print the given message to the trace output stream.
616 : */
617 : void
618 828 : pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
619 : {
620 : char id;
621 : int length;
622 828 : char *prefix = toServer ? "F" : "B";
623 828 : int logCursor = 0;
624 : bool regress;
625 :
626 828 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
627 : {
628 : char timestr[128];
629 :
630 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
631 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
632 : }
633 828 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
634 :
635 828 : id = message[logCursor++];
636 :
637 828 : memcpy(&length, message + logCursor, 4);
638 828 : length = (int) pg_ntoh32(length);
639 828 : logCursor += 4;
640 :
641 : /*
642 : * In regress mode, suppress the length of ErrorResponse and
643 : * NoticeResponse. The F (file name), L (line number) and R (routine
644 : * name) fields can change as server code is modified, and if their
645 : * lengths differ from the originals, that would break tests.
646 : */
647 828 : if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
648 20 : fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
649 : else
650 808 : fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
651 :
652 828 : switch (id)
653 : {
654 62 : case PqMsg_ParseComplete:
655 62 : fprintf(conn->Pfdebug, "ParseComplete");
656 : /* No message content */
657 62 : break;
658 58 : case PqMsg_BindComplete:
659 58 : fprintf(conn->Pfdebug, "BindComplete");
660 : /* No message content */
661 58 : break;
662 8 : case PqMsg_CloseComplete:
663 8 : fprintf(conn->Pfdebug, "CloseComplete");
664 : /* No message content */
665 8 : break;
666 0 : case PqMsg_NotificationResponse:
667 0 : pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
668 0 : break;
669 72 : case PqMsg_Bind:
670 72 : pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
671 72 : break;
672 0 : case PqMsg_CopyDone:
673 0 : fprintf(conn->Pfdebug, "CopyDone");
674 : /* No message content */
675 0 : break;
676 82 : case PqMsg_CommandComplete:
677 : /* Close(F) and CommandComplete(B) use the same identifier. */
678 : Assert(PqMsg_Close == PqMsg_CommandComplete);
679 82 : if (toServer)
680 8 : pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
681 : else
682 74 : pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
683 82 : break;
684 0 : case PqMsg_CopyData:
685 0 : pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
686 : length, regress);
687 0 : break;
688 164 : case PqMsg_Describe:
689 : /* Describe(F) and DataRow(B) use the same identifier. */
690 : Assert(PqMsg_Describe == PqMsg_DataRow);
691 164 : if (toServer)
692 80 : pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
693 : else
694 84 : pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
695 164 : break;
696 86 : case PqMsg_Execute:
697 : /* Execute(F) and ErrorResponse(B) use the same identifier. */
698 : Assert(PqMsg_Execute == PqMsg_ErrorResponse);
699 86 : if (toServer)
700 72 : pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
701 : else
702 14 : pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
703 86 : break;
704 0 : case PqMsg_CopyFail:
705 0 : pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
706 0 : break;
707 0 : case PqMsg_GSSResponse:
708 : Assert(PqMsg_GSSResponse == PqMsg_PasswordMessage);
709 : Assert(PqMsg_GSSResponse == PqMsg_SASLInitialResponse);
710 : Assert(PqMsg_GSSResponse == PqMsg_SASLResponse);
711 :
712 : /*
713 : * These messages share a common type byte, so we discriminate by
714 : * having the code store the auth type separately.
715 : */
716 0 : switch (conn->current_auth_response)
717 : {
718 0 : case AUTH_RESPONSE_GSS:
719 0 : pqTraceOutput_GSSResponse(conn->Pfdebug, message,
720 : &logCursor, length, regress);
721 0 : break;
722 0 : case AUTH_RESPONSE_PASSWORD:
723 0 : pqTraceOutput_PasswordMessage(conn->Pfdebug, message,
724 : &logCursor);
725 0 : break;
726 0 : case AUTH_RESPONSE_SASL_INITIAL:
727 0 : pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message,
728 : &logCursor, regress);
729 0 : break;
730 0 : case AUTH_RESPONSE_SASL:
731 0 : pqTraceOutput_SASLResponse(conn->Pfdebug, message,
732 : &logCursor, length, regress);
733 0 : break;
734 0 : default:
735 0 : fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
736 0 : break;
737 : }
738 0 : conn->current_auth_response = '\0';
739 0 : break;
740 0 : case PqMsg_FunctionCall:
741 0 : pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
742 0 : break;
743 0 : case PqMsg_CopyInResponse:
744 0 : pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
745 0 : break;
746 14 : case PqMsg_Flush:
747 : /* Flush(F) and CopyOutResponse(B) use the same identifier */
748 : Assert(PqMsg_CopyOutResponse == PqMsg_Flush);
749 14 : if (toServer)
750 14 : fprintf(conn->Pfdebug, "Flush"); /* no message content */
751 : else
752 0 : pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
753 14 : break;
754 0 : case PqMsg_EmptyQueryResponse:
755 0 : fprintf(conn->Pfdebug, "EmptyQueryResponse");
756 : /* No message content */
757 0 : break;
758 0 : case PqMsg_BackendKeyData:
759 0 : pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
760 0 : break;
761 10 : case PqMsg_NoData:
762 10 : fprintf(conn->Pfdebug, "NoData");
763 : /* No message content */
764 10 : break;
765 6 : case PqMsg_NoticeResponse:
766 6 : pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
767 6 : break;
768 72 : case PqMsg_Parse:
769 72 : pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
770 72 : break;
771 16 : case PqMsg_Query:
772 16 : pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
773 16 : break;
774 0 : case PqMsg_AuthenticationRequest:
775 0 : pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
776 : length, regress);
777 0 : break;
778 0 : case PqMsg_PortalSuspended:
779 0 : fprintf(conn->Pfdebug, "PortalSuspended");
780 : /* No message content */
781 0 : break;
782 42 : case PqMsg_Sync:
783 : /* ParameterStatus(B) and Sync(F) use the same identifier */
784 : Assert(PqMsg_ParameterStatus == PqMsg_Sync);
785 42 : if (toServer)
786 42 : fprintf(conn->Pfdebug, "Sync"); /* no message content */
787 : else
788 0 : pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
789 42 : break;
790 2 : case PqMsg_ParameterDescription:
791 2 : pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
792 2 : break;
793 58 : case PqMsg_RowDescription:
794 58 : pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
795 58 : break;
796 0 : case PqMsg_NegotiateProtocolVersion:
797 0 : pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
798 0 : break;
799 0 : case PqMsg_FunctionCallResponse:
800 0 : pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
801 0 : break;
802 0 : case PqMsg_CopyBothResponse:
803 0 : pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
804 0 : break;
805 18 : case PqMsg_Terminate:
806 18 : fprintf(conn->Pfdebug, "Terminate");
807 : /* No message content */
808 18 : break;
809 58 : case PqMsg_ReadyForQuery:
810 58 : pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
811 58 : break;
812 0 : default:
813 0 : fprintf(conn->Pfdebug, "Unknown message: %02x", id);
814 0 : break;
815 : }
816 :
817 828 : fputc('\n', conn->Pfdebug);
818 :
819 : /*
820 : * Verify the printing routine did it right. Note that the one-byte
821 : * message identifier is not included in the length, but our cursor does
822 : * include it.
823 : */
824 828 : if (logCursor - 1 != length)
825 0 : fprintf(conn->Pfdebug,
826 : "mismatched message length: consumed %d, expected %d\n",
827 : logCursor - 1, length);
828 828 : }
829 :
830 : /*
831 : * Print special messages (those containing no type byte) to the trace output
832 : * stream.
833 : */
834 : void
835 0 : pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
836 : {
837 : int length;
838 : int version;
839 : bool regress;
840 0 : int logCursor = 0;
841 :
842 0 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
843 :
844 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
845 : {
846 : char timestr[128];
847 :
848 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
849 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
850 : }
851 :
852 0 : memcpy(&length, message + logCursor, 4);
853 0 : length = (int) pg_ntoh32(length);
854 0 : logCursor += 4;
855 :
856 0 : fprintf(conn->Pfdebug, "F\t%d\t", length);
857 :
858 0 : if (length < 8)
859 : {
860 0 : fprintf(conn->Pfdebug, "Unknown message\n");
861 0 : return;
862 : }
863 :
864 0 : memcpy(&version, message + logCursor, 4);
865 0 : version = (int) pg_ntoh32(version);
866 :
867 0 : if (version == CANCEL_REQUEST_CODE && length >= 16)
868 : {
869 0 : fprintf(conn->Pfdebug, "CancelRequest\t");
870 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
871 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
872 0 : pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
873 0 : pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
874 : }
875 0 : else if (version == NEGOTIATE_SSL_CODE)
876 : {
877 0 : fprintf(conn->Pfdebug, "SSLRequest\t");
878 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
879 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
880 : }
881 0 : else if (version == NEGOTIATE_GSS_CODE)
882 : {
883 0 : fprintf(conn->Pfdebug, "GSSENCRequest\t");
884 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
885 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
886 : }
887 : else
888 : {
889 0 : fprintf(conn->Pfdebug, "StartupMessage\t");
890 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
891 0 : pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
892 0 : while (message[logCursor] != '\0')
893 : {
894 : /* XXX should we suppress anything in regress mode? */
895 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
896 0 : pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
897 : }
898 : }
899 :
900 0 : fputc('\n', conn->Pfdebug);
901 : }
902 :
903 : /*
904 : * Trace a single-byte backend response received for a known request
905 : * type the frontend previously sent. Only useful for the simplest of
906 : * FE/BE interaction workflows such as SSL/GSS encryption requests.
907 : */
908 : void
909 0 : pqTraceOutputCharResponse(PGconn *conn, const char *responseType,
910 : char response)
911 : {
912 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
913 : {
914 : char timestr[128];
915 :
916 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
917 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
918 : }
919 :
920 0 : fprintf(conn->Pfdebug, "B\t1\t%s\t %c\n", responseType, response);
921 0 : }
|
