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 : 0 : PQtrace(PGconn *conn, FILE *debug_port)
36 : : {
37 [ # # ]: 0 : if (conn == NULL)
38 : 0 : return;
39 : 0 : PQuntrace(conn);
40 [ # # ]: 0 : if (debug_port == NULL)
41 : 0 : return;
42 : :
43 : 0 : conn->Pfdebug = debug_port;
44 : 0 : conn->traceFlags = 0;
45 : 0 : }
46 : :
47 : : /* Disable tracing */
48 : : void
49 : 0 : PQuntrace(PGconn *conn)
50 : : {
51 [ # # ]: 0 : if (conn == NULL)
52 : 0 : return;
53 [ # # ]: 0 : if (conn->Pfdebug)
54 : : {
55 : 0 : fflush(conn->Pfdebug);
56 : 0 : conn->Pfdebug = NULL;
57 : 0 : }
58 : :
59 : 0 : conn->traceFlags = 0;
60 : 0 : }
61 : :
62 : : /* Set flags for current tracing session */
63 : : void
64 : 0 : PQsetTraceFlags(PGconn *conn, int flags)
65 : : {
66 [ # # ]: 0 : if (conn == NULL)
67 : 0 : return;
68 : : /* If PQtrace() failed, do nothing. */
69 [ # # ]: 0 : if (conn->Pfdebug == NULL)
70 : 0 : return;
71 : 0 : conn->traceFlags = flags;
72 : 0 : }
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 : 0 : struct timeval tval;
83 : 0 : time_t now;
84 : 0 : 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 : 0 : pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor)
108 : : {
109 : 0 : 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 [ # # ]: 0 : if (!isprint((unsigned char) *v))
116 : 0 : fprintf(pfdebug, " \\x%02x", (unsigned char) *v);
117 : : else
118 : 0 : fprintf(pfdebug, " %c", *v);
119 : 0 : *cursor += 1;
120 : 0 : }
121 : :
122 : : /*
123 : : * pqTraceOutputInt16: output a 2-byte integer message to the log
124 : : */
125 : : static int
126 : 0 : pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor)
127 : : {
128 : 0 : uint16 tmp;
129 : 0 : int result;
130 : :
131 : 0 : memcpy(&tmp, data + *cursor, 2);
132 : 0 : *cursor += 2;
133 : 0 : result = (int) pg_ntoh16(tmp);
134 : 0 : fprintf(pfdebug, " %d", result);
135 : :
136 : 0 : return result;
137 : 0 : }
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 : 0 : pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress)
146 : : {
147 : 0 : int result;
148 : :
149 : 0 : memcpy(&result, data + *cursor, 4);
150 : 0 : *cursor += 4;
151 : 0 : result = (int) pg_ntoh32(result);
152 [ # # ]: 0 : if (suppress)
153 : 0 : fprintf(pfdebug, " NNNN");
154 : : else
155 : 0 : fprintf(pfdebug, " %d", result);
156 : :
157 : 0 : return result;
158 : 0 : }
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 : 0 : pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
167 : : {
168 : 0 : int len;
169 : :
170 [ # # ]: 0 : if (suppress)
171 : : {
172 : 0 : fprintf(pfdebug, " \"SSSS\"");
173 : 0 : *cursor += strlen(data + *cursor) + 1;
174 : 0 : }
175 : : else
176 : : {
177 : 0 : 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 : 0 : *cursor += (len - 3 + 1);
184 : : }
185 : 0 : }
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 : 0 : pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
194 : : {
195 : 0 : int i,
196 : : next; /* first char not yet printed */
197 : 0 : const char *v = data + *cursor;
198 : :
199 [ # # ]: 0 : if (suppress)
200 : : {
201 : 0 : fprintf(pfdebug, " 'BBBB'");
202 : 0 : *cursor += len;
203 : 0 : return;
204 : : }
205 : :
206 : 0 : fprintf(pfdebug, " \'");
207 : :
208 [ # # ]: 0 : for (next = i = 0; i < len; ++i)
209 : : {
210 [ # # ]: 0 : if (isprint((unsigned char) v[i]))
211 : 0 : 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 : 0 : }
219 [ # # ]: 0 : if (next < len)
220 : 0 : fwrite(v + next, 1, len - next, pfdebug);
221 : :
222 : 0 : fprintf(pfdebug, "\'");
223 : 0 : *cursor += len;
224 [ # # ]: 0 : }
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 : 0 : pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
241 : : {
242 : 0 : int nparams;
243 : :
244 : 0 : fprintf(f, "Bind\t");
245 : 0 : pqTraceOutputString(f, message, cursor, false);
246 : 0 : pqTraceOutputString(f, message, cursor, false);
247 : 0 : nparams = pqTraceOutputInt16(f, message, cursor);
248 : :
249 [ # # ]: 0 : for (int i = 0; i < nparams; i++)
250 : 0 : pqTraceOutputInt16(f, message, cursor);
251 : :
252 : 0 : nparams = pqTraceOutputInt16(f, message, cursor);
253 : :
254 [ # # ]: 0 : for (int i = 0; i < nparams; i++)
255 : : {
256 : 0 : int nbytes;
257 : :
258 : 0 : nbytes = pqTraceOutputInt32(f, message, cursor, false);
259 [ # # ]: 0 : if (nbytes == -1)
260 : 0 : continue;
261 : 0 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
262 [ # # # ]: 0 : }
263 : :
264 : 0 : nparams = pqTraceOutputInt16(f, message, cursor);
265 [ # # ]: 0 : for (int i = 0; i < nparams; i++)
266 : 0 : pqTraceOutputInt16(f, message, cursor);
267 : 0 : }
268 : :
269 : : static void
270 : 0 : pqTraceOutput_Close(FILE *f, const char *message, int *cursor)
271 : : {
272 : 0 : fprintf(f, "Close\t");
273 : 0 : pqTraceOutputByte1(f, message, cursor);
274 : 0 : pqTraceOutputString(f, message, cursor, false);
275 : 0 : }
276 : :
277 : : static void
278 : 0 : pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
279 : : {
280 : 0 : fprintf(f, "CommandComplete\t");
281 : 0 : pqTraceOutputString(f, message, cursor, false);
282 : 0 : }
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 : 0 : pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
294 : : {
295 : 0 : int nfields;
296 : 0 : int len;
297 : 0 : int i;
298 : :
299 : 0 : fprintf(f, "DataRow\t");
300 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
301 [ # # ]: 0 : for (i = 0; i < nfields; i++)
302 : : {
303 : 0 : len = pqTraceOutputInt32(f, message, cursor, false);
304 [ # # ]: 0 : if (len == -1)
305 : 0 : continue;
306 : 0 : pqTraceOutputNchar(f, len, message, cursor, false);
307 : 0 : }
308 : 0 : }
309 : :
310 : : static void
311 : 0 : pqTraceOutput_Describe(FILE *f, const char *message, int *cursor)
312 : : {
313 : 0 : fprintf(f, "Describe\t");
314 : 0 : pqTraceOutputByte1(f, message, cursor);
315 : 0 : pqTraceOutputString(f, message, cursor, false);
316 : 0 : }
317 : :
318 : : /* shared code NoticeResponse / ErrorResponse */
319 : : static void
320 : 0 : pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor,
321 : : bool regress)
322 : : {
323 : 0 : fprintf(f, "%s\t", type);
324 : 0 : for (;;)
325 : : {
326 : 0 : char field;
327 : 0 : bool suppress;
328 : :
329 : 0 : pqTraceOutputByte1(f, message, cursor);
330 : 0 : field = message[*cursor - 1];
331 [ # # ]: 0 : if (field == '\0')
332 : 0 : break;
333 : :
334 [ # # # # : 0 : suppress = regress && (field == 'L' || field == 'F' || field == 'R');
# # ]
335 : 0 : pqTraceOutputString(f, message, cursor, suppress);
336 [ # # # ]: 0 : }
337 : 0 : }
338 : :
339 : : static void
340 : 0 : pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress)
341 : : {
342 : 0 : pqTraceOutputNR(f, "ErrorResponse", message, cursor, regress);
343 : 0 : }
344 : :
345 : : static void
346 : 0 : pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress)
347 : : {
348 : 0 : pqTraceOutputNR(f, "NoticeResponse", message, cursor, regress);
349 : 0 : }
350 : :
351 : : static void
352 : 0 : pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress)
353 : : {
354 : 0 : fprintf(f, "Execute\t");
355 : 0 : pqTraceOutputString(f, message, cursor, false);
356 : 0 : pqTraceOutputInt32(f, message, cursor, false);
357 : 0 : }
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 : 0 : 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 : 0 : int nfields;
406 : 0 : 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 : 0 : }
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 : 0 : 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 : 0 : 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 : 0 : pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
464 : : {
465 : 0 : int nparams;
466 : :
467 : 0 : fprintf(f, "Parse\t");
468 : 0 : pqTraceOutputString(f, message, cursor, false);
469 : 0 : pqTraceOutputString(f, message, cursor, false);
470 : 0 : nparams = pqTraceOutputInt16(f, message, cursor);
471 : :
472 [ # # ]: 0 : for (int i = 0; i < nparams; i++)
473 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
474 : 0 : }
475 : :
476 : : static void
477 : 0 : pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
478 : : {
479 : 0 : fprintf(f, "Query\t");
480 : 0 : pqTraceOutputString(f, message, cursor, false);
481 : 0 : }
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 : : 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 : : case AUTH_REQ_PASSWORD:
500 : 0 : fprintf(f, "AuthenticationCleartextPassword");
501 : 0 : break;
502 : : /* AUTH_REQ_CRYPT not supported */
503 : : case AUTH_REQ_MD5:
504 : 0 : fprintf(f, "AuthenticationMD5Password");
505 : 0 : break;
506 : : case AUTH_REQ_GSS:
507 : 0 : fprintf(f, "AuthenticationGSS");
508 : 0 : break;
509 : : case AUTH_REQ_GSS_CONT:
510 : 0 : fprintf(f, "AuthenticationGSSContinue\t");
511 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
512 : 0 : suppress);
513 : 0 : break;
514 : : case AUTH_REQ_SSPI:
515 : 0 : fprintf(f, "AuthenticationSSPI");
516 : 0 : break;
517 : : 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 : : case AUTH_REQ_SASL_CONT:
524 : 0 : fprintf(f, "AuthenticationSASLContinue\t");
525 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
526 : 0 : suppress);
527 : 0 : break;
528 : : case AUTH_REQ_SASL_FIN:
529 : 0 : fprintf(f, "AuthenticationSASLFinal\t");
530 : 0 : pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
531 : 0 : suppress);
532 : 0 : break;
533 : : default:
534 : 0 : fprintf(f, "Unknown authentication message %d", authType);
535 : 0 : }
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 : 0 : pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
548 : : {
549 : 0 : int nfields;
550 : :
551 : 0 : fprintf(f, "ParameterDescription\t");
552 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
553 : :
554 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
555 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
556 : 0 : }
557 : :
558 : : static void
559 : 0 : pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
560 : : {
561 : 0 : int nfields;
562 : :
563 : 0 : fprintf(f, "RowDescription\t");
564 : 0 : nfields = pqTraceOutputInt16(f, message, cursor);
565 : :
566 [ # # ]: 0 : for (int i = 0; i < nfields; i++)
567 : : {
568 : 0 : pqTraceOutputString(f, message, cursor, false);
569 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
570 : 0 : pqTraceOutputInt16(f, message, cursor);
571 : 0 : pqTraceOutputInt32(f, message, cursor, regress);
572 : 0 : pqTraceOutputInt16(f, message, cursor);
573 : 0 : pqTraceOutputInt32(f, message, cursor, false);
574 : 0 : pqTraceOutputInt16(f, message, cursor);
575 : 0 : }
576 : 0 : }
577 : :
578 : : static void
579 : 0 : pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
580 : : {
581 : 0 : 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 : 0 : }
590 : 0 : }
591 : :
592 : : static void
593 : 0 : pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
594 : : {
595 : 0 : 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 : 0 : pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
615 : : {
616 : 0 : fprintf(f, "ReadyForQuery\t");
617 : 0 : pqTraceOutputByte1(f, message, cursor);
618 : 0 : }
619 : :
620 : : /*
621 : : * Print the given message to the trace output stream.
622 : : */
623 : : void
624 : 0 : pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
625 : : {
626 : 0 : char id;
627 : 0 : int length;
628 : 0 : char *prefix = toServer ? "F" : "B";
629 : 0 : int logCursor = 0;
630 : 0 : bool regress;
631 : :
632 [ # # ]: 0 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
633 : : {
634 : 0 : char timestr[128];
635 : :
636 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
637 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
638 : 0 : }
639 : 0 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
640 : :
641 : 0 : id = message[logCursor++];
642 : :
643 : 0 : memcpy(&length, message + logCursor, 4);
644 : 0 : length = (int) pg_ntoh32(length);
645 : 0 : 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 [ # # # # : 0 : if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
# # # # ]
654 : 0 : fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
655 : : else
656 : 0 : fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
657 : :
658 [ # # # # : 0 : switch (id)
# # # # #
# # # # #
# # # # #
# # # # #
# # # # #
# # # ]
659 : : {
660 : : case PqMsg_ParseComplete:
661 : 0 : fprintf(conn->Pfdebug, "ParseComplete");
662 : : /* No message content */
663 : 0 : break;
664 : : case PqMsg_BindComplete:
665 : 0 : fprintf(conn->Pfdebug, "BindComplete");
666 : : /* No message content */
667 : 0 : break;
668 : : case PqMsg_CloseComplete:
669 : 0 : fprintf(conn->Pfdebug, "CloseComplete");
670 : : /* No message content */
671 : 0 : break;
672 : : case PqMsg_NotificationResponse:
673 : 0 : pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
674 : 0 : break;
675 : : case PqMsg_Bind:
676 : 0 : pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
677 : 0 : break;
678 : : case PqMsg_CopyDone:
679 : 0 : fprintf(conn->Pfdebug, "CopyDone");
680 : : /* No message content */
681 : 0 : break;
682 : : case PqMsg_CommandComplete:
683 : : /* Close(F) and CommandComplete(B) use the same identifier. */
684 : : Assert(PqMsg_Close == PqMsg_CommandComplete);
685 [ # # ]: 0 : if (toServer)
686 : 0 : pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
687 : : else
688 : 0 : pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
689 : 0 : break;
690 : : case PqMsg_CopyData:
691 : 0 : pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
692 : 0 : length, regress);
693 : 0 : break;
694 : : case PqMsg_Describe:
695 : : /* Describe(F) and DataRow(B) use the same identifier. */
696 : : Assert(PqMsg_Describe == PqMsg_DataRow);
697 [ # # ]: 0 : if (toServer)
698 : 0 : pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
699 : : else
700 : 0 : pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
701 : 0 : break;
702 : : case PqMsg_Execute:
703 : : /* Execute(F) and ErrorResponse(B) use the same identifier. */
704 : : Assert(PqMsg_Execute == PqMsg_ErrorResponse);
705 [ # # ]: 0 : if (toServer)
706 : 0 : pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
707 : : else
708 : 0 : pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
709 : 0 : break;
710 : : case PqMsg_CopyFail:
711 : 0 : pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
712 : 0 : break;
713 : : 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 : : case AUTH_RESPONSE_GSS:
725 : 0 : pqTraceOutput_GSSResponse(conn->Pfdebug, message,
726 : 0 : &logCursor, length, regress);
727 : 0 : break;
728 : : case AUTH_RESPONSE_PASSWORD:
729 : 0 : pqTraceOutput_PasswordMessage(conn->Pfdebug, message,
730 : : &logCursor);
731 : 0 : break;
732 : : case AUTH_RESPONSE_SASL_INITIAL:
733 : 0 : pqTraceOutput_SASLInitialResponse(conn->Pfdebug, message,
734 : 0 : &logCursor, regress);
735 : 0 : break;
736 : : case AUTH_RESPONSE_SASL:
737 : 0 : pqTraceOutput_SASLResponse(conn->Pfdebug, message,
738 : 0 : &logCursor, length, regress);
739 : 0 : break;
740 : : default:
741 : 0 : fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
742 : 0 : break;
743 : : }
744 : 0 : conn->current_auth_response = '\0';
745 : 0 : break;
746 : : case PqMsg_FunctionCall:
747 : 0 : pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
748 : 0 : break;
749 : : case PqMsg_CopyInResponse:
750 : 0 : pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
751 : 0 : break;
752 : : case PqMsg_Flush:
753 : : /* Flush(F) and CopyOutResponse(B) use the same identifier */
754 : : Assert(PqMsg_CopyOutResponse == PqMsg_Flush);
755 [ # # ]: 0 : if (toServer)
756 : 0 : fprintf(conn->Pfdebug, "Flush"); /* no message content */
757 : : else
758 : 0 : pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
759 : 0 : break;
760 : : case PqMsg_EmptyQueryResponse:
761 : 0 : fprintf(conn->Pfdebug, "EmptyQueryResponse");
762 : : /* No message content */
763 : 0 : break;
764 : : case PqMsg_BackendKeyData:
765 : 0 : pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
766 : 0 : break;
767 : : case PqMsg_NoData:
768 : 0 : fprintf(conn->Pfdebug, "NoData");
769 : : /* No message content */
770 : 0 : break;
771 : : case PqMsg_NoticeResponse:
772 : 0 : pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
773 : 0 : break;
774 : : case PqMsg_Parse:
775 : 0 : pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
776 : 0 : break;
777 : : case PqMsg_Query:
778 : 0 : pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
779 : 0 : break;
780 : : case PqMsg_AuthenticationRequest:
781 : 0 : pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
782 : 0 : length, regress);
783 : 0 : break;
784 : : case PqMsg_PortalSuspended:
785 : 0 : fprintf(conn->Pfdebug, "PortalSuspended");
786 : : /* No message content */
787 : 0 : break;
788 : : case PqMsg_Sync:
789 : : /* ParameterStatus(B) and Sync(F) use the same identifier */
790 : : Assert(PqMsg_ParameterStatus == PqMsg_Sync);
791 [ # # ]: 0 : if (toServer)
792 : 0 : fprintf(conn->Pfdebug, "Sync"); /* no message content */
793 : : else
794 : 0 : pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
795 : 0 : break;
796 : : case PqMsg_ParameterDescription:
797 : 0 : pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
798 : 0 : break;
799 : : case PqMsg_RowDescription:
800 : 0 : pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
801 : 0 : break;
802 : : case PqMsg_NegotiateProtocolVersion:
803 : 0 : pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
804 : 0 : break;
805 : : case PqMsg_FunctionCallResponse:
806 : 0 : pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
807 : 0 : break;
808 : : case PqMsg_CopyBothResponse:
809 : 0 : pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
810 : 0 : break;
811 : : case PqMsg_Terminate:
812 : 0 : fprintf(conn->Pfdebug, "Terminate");
813 : : /* No message content */
814 : 0 : break;
815 : : case PqMsg_ReadyForQuery:
816 : 0 : pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
817 : 0 : break;
818 : : default:
819 : 0 : fprintf(conn->Pfdebug, "Unknown message: %02x", id);
820 : 0 : break;
821 : : }
822 : :
823 : 0 : 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 [ # # ]: 0 : if (logCursor - 1 != length)
831 : 0 : fprintf(conn->Pfdebug,
832 : : "mismatched message length: consumed %d, expected %d\n",
833 : 0 : logCursor - 1, length);
834 : 0 : }
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 : 0 : int length;
844 : 0 : int version;
845 : 0 : 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 : 0 : char timestr[128];
853 : :
854 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
855 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
856 : 0 : }
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 : 0 : }
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 : 0 : }
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 : 0 : }
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 [ # # ]: 0 : }
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 : 0 : char timestr[128];
921 : :
922 : 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
923 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
924 : 0 : }
925 : :
926 : 0 : fprintf(conn->Pfdebug, "B\t1\t%s\t %c\n", responseType, response);
927 : 0 : }
|
