Age Owner Branch data TLA 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
1621 alvherre@alvh.no-ip. 35 :CBC 9 : PQtrace(PGconn *conn, FILE *debug_port)
36 : : {
37 [ - + ]: 9 : if (conn == NULL)
1621 alvherre@alvh.no-ip. 38 :UBC 0 : return;
1621 alvherre@alvh.no-ip. 39 :CBC 9 : PQuntrace(conn);
40 [ - + ]: 9 : if (debug_port == NULL)
1621 alvherre@alvh.no-ip. 41 :UBC 0 : return;
42 : :
1621 alvherre@alvh.no-ip. 43 :CBC 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)
1621 alvherre@alvh.no-ip. 52 :UBC 0 : return;
1621 alvherre@alvh.no-ip. 53 [ - + ]:CBC 9 : if (conn->Pfdebug)
54 : : {
1621 alvherre@alvh.no-ip. 55 :UBC 0 : fflush(conn->Pfdebug);
56 : 0 : conn->Pfdebug = NULL;
57 : : }
58 : :
1621 alvherre@alvh.no-ip. 59 :CBC 9 : conn->traceFlags = 0;
60 : : }
61 : :
62 : : /* Set flags for current tracing session */
63 : : void
1549 noah@leadboat.com 64 : 9 : PQsetTraceFlags(PGconn *conn, int flags)
65 : : {
1621 alvherre@alvh.no-ip. 66 [ - + ]: 9 : if (conn == NULL)
1621 alvherre@alvh.no-ip. 67 :UBC 0 : return;
68 : : /* If PQtrace() failed, do nothing. */
1621 alvherre@alvh.no-ip. 69 [ - + ]:CBC 9 : if (conn->Pfdebug == NULL)
1621 alvherre@alvh.no-ip. 70 :UBC 0 : return;
1621 alvherre@alvh.no-ip. 71 :CBC 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
1621 alvherre@alvh.no-ip. 80 :UBC 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 : : */
1614 drowley@postgresql.o 94 : 0 : now = tval.tv_sec;
1621 alvherre@alvh.no-ip. 95 : 0 : strftime(timestr, ts_len,
96 : : "%Y-%m-%d %H:%M:%S",
379 peter@eisentraut.org 97 : 0 : localtime_r(&now, &tmbuf));
98 : : /* append microseconds */
1620 tgl@sss.pgh.pa.us 99 : 0 : snprintf(timestr + strlen(timestr), ts_len - strlen(timestr),
100 : 0 : ".%06u", (unsigned int) (tval.tv_usec));
1621 alvherre@alvh.no-ip. 101 : 0 : }
102 : :
103 : : /*
104 : : * pqTraceOutputByte1: output a 1-char message to the log
105 : : */
106 : : static void
1621 alvherre@alvh.no-ip. 107 :CBC 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 : : */
1620 tgl@sss.pgh.pa.us 115 [ + + ]: 155 : if (!isprint((unsigned char) *v))
3 michael@paquier.xyz 116 : 10 : fprintf(pfdebug, " \\x%02x", (unsigned char) *v);
117 : : else
1621 alvherre@alvh.no-ip. 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
394 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 */
1621 197 : 53 : const char *v = data + *cursor;
198 : :
394 199 [ - + ]: 53 : if (suppress)
200 : : {
394 alvherre@alvh.no-ip. 201 :UBC 0 : fprintf(pfdebug, " 'BBBB'");
202 : 0 : *cursor += len;
203 : 0 : return;
204 : : }
205 : :
1621 alvherre@alvh.no-ip. 206 :CBC 53 : fprintf(pfdebug, " \'");
207 : :
208 [ + + ]: 774 : for (next = i = 0; i < len; ++i)
209 : : {
1620 tgl@sss.pgh.pa.us 210 [ + - ]: 721 : if (isprint((unsigned char) v[i]))
1621 alvherre@alvh.no-ip. 211 : 721 : continue;
212 : : else
213 : : {
1621 alvherre@alvh.no-ip. 214 :UBC 0 : fwrite(v + next, 1, i - next, pfdebug);
3 michael@paquier.xyz 215 : 0 : fprintf(pfdebug, "\\x%02x", (unsigned char) v[i]);
1621 alvherre@alvh.no-ip. 216 : 0 : next = i + 1;
217 : : }
218 : : }
1621 alvherre@alvh.no-ip. 219 [ + - ]:CBC 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
492 peter@eisentraut.org 231 :UBC 0 : pqTraceOutput_NotificationResponse(FILE *f, const char *message, int *cursor, bool regress)
232 : : {
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 240 :CBC 36 : pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
241 : : {
242 : : int nparams;
243 : :
1621 alvherre@alvh.no-ip. 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++)
1621 alvherre@alvh.no-ip. 250 :UBC 0 : pqTraceOutputInt16(f, message, cursor);
251 : :
1621 alvherre@alvh.no-ip. 252 :CBC 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)
1621 alvherre@alvh.no-ip. 260 :UBC 0 : continue;
394 alvherre@alvh.no-ip. 261 :CBC 11 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
262 : : }
263 : :
1621 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
492 peter@eisentraut.org 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);
1621 alvherre@alvh.no-ip. 282 : 37 : }
283 : :
284 : : static void
386 alvherre@alvh.no-ip. 285 :UBC 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
492 peter@eisentraut.org 293 :CBC 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)
492 peter@eisentraut.org 305 :UBC 0 : continue;
394 alvherre@alvh.no-ip. 306 :CBC 42 : pqTraceOutputNchar(f, len, message, cursor, false);
307 : : }
492 peter@eisentraut.org 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);
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 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);
1621 alvherre@alvh.no-ip. 349 : 3 : }
350 : :
351 : : static void
492 peter@eisentraut.org 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
492 peter@eisentraut.org 360 :UBC 0 : pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor)
361 : : {
1621 alvherre@alvh.no-ip. 362 : 0 : fprintf(f, "CopyFail\t");
363 : 0 : pqTraceOutputString(f, message, cursor, false);
364 : 0 : }
365 : :
366 : : static void
390 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
492 peter@eisentraut.org 403 : 0 : pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regress)
404 : : {
405 : : int nfields;
406 : : int nbytes;
407 : :
1621 alvherre@alvh.no-ip. 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;
394 422 : 0 : pqTraceOutputNchar(f, nbytes, message, cursor, false);
423 : : }
424 : :
1621 425 : 0 : pqTraceOutputInt16(f, message, cursor);
426 : 0 : }
427 : :
428 : : static void
492 peter@eisentraut.org 429 : 0 : pqTraceOutput_CopyInResponse(FILE *f, const char *message, int *cursor)
430 : : {
431 : : int nfields;
432 : :
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 442 : 0 : pqTraceOutput_CopyOutResponse(FILE *f, const char *message, int *cursor)
443 : : {
444 : : int nfields;
445 : :
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 455 : 0 : pqTraceOutput_BackendKeyData(FILE *f, const char *message, int *cursor, bool regress)
456 : : {
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 463 :CBC 36 : pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
464 : : {
465 : : int nparams;
466 : :
1621 alvherre@alvh.no-ip. 467 : 36 : fprintf(f, "Parse\t");
468 : 36 : pqTraceOutputString(f, message, cursor, false);
469 : 36 : pqTraceOutputString(f, message, cursor, false);
470 : 36 : nparams = pqTraceOutputInt16(f, message, cursor);
471 : :
472 [ + + ]: 45 : for (int i = 0; i < nparams; i++)
473 : 9 : pqTraceOutputInt32(f, message, cursor, regress);
474 : 36 : }
475 : :
476 : : static void
492 peter@eisentraut.org 477 : 8 : pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
478 : : {
1621 alvherre@alvh.no-ip. 479 : 8 : fprintf(f, "Query\t");
480 : 8 : pqTraceOutputString(f, message, cursor, false);
481 : 8 : }
482 : :
483 : : static void
386 alvherre@alvh.no-ip. 484 :UBC 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 : : }
1621 536 : 0 : }
537 : :
538 : : static void
492 peter@eisentraut.org 539 : 0 : pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor)
540 : : {
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 547 :CBC 1 : pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
548 : : {
549 : : int nfields;
550 : :
1621 alvherre@alvh.no-ip. 551 : 1 : fprintf(f, "ParameterDescription\t");
552 : 1 : nfields = pqTraceOutputInt16(f, message, cursor);
553 : :
554 [ + + ]: 2 : for (int i = 0; i < nfields; i++)
555 : 1 : pqTraceOutputInt32(f, message, cursor, regress);
556 : 1 : }
557 : :
558 : : static void
492 peter@eisentraut.org 559 : 29 : pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
560 : : {
561 : : int nfields;
562 : :
1621 alvherre@alvh.no-ip. 563 : 29 : fprintf(f, "RowDescription\t");
564 : 29 : nfields = pqTraceOutputInt16(f, message, cursor);
565 : :
566 [ + + ]: 61 : for (int i = 0; i < nfields; i++)
567 : : {
568 : 32 : pqTraceOutputString(f, message, cursor, false);
569 : 32 : pqTraceOutputInt32(f, message, cursor, regress);
570 : 32 : pqTraceOutputInt16(f, message, cursor);
571 : 32 : pqTraceOutputInt32(f, message, cursor, regress);
572 : 32 : pqTraceOutputInt16(f, message, cursor);
573 : 32 : pqTraceOutputInt32(f, message, cursor, false);
574 : 32 : pqTraceOutputInt16(f, message, cursor);
575 : : }
576 : 29 : }
577 : :
578 : : static void
492 peter@eisentraut.org 579 :UBC 0 : pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
580 : : {
581 : : int nparams;
582 : :
1621 alvherre@alvh.no-ip. 583 : 0 : fprintf(f, "NegotiateProtocolVersion\t");
584 : 0 : pqTraceOutputInt32(f, message, cursor, false);
194 rhaas@postgresql.org 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 : : }
1621 alvherre@alvh.no-ip. 590 : 0 : }
591 : :
592 : : static void
492 peter@eisentraut.org 593 : 0 : pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
594 : : {
595 : : int len;
596 : :
1621 alvherre@alvh.no-ip. 597 : 0 : fprintf(f, "FunctionCallResponse\t");
598 : 0 : len = pqTraceOutputInt32(f, message, cursor, false);
599 [ # # ]: 0 : if (len != -1)
394 600 : 0 : pqTraceOutputNchar(f, len, message, cursor, false);
1621 601 : 0 : }
602 : :
603 : : static void
492 peter@eisentraut.org 604 : 0 : pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
605 : : {
1621 alvherre@alvh.no-ip. 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
492 peter@eisentraut.org 614 :CBC 29 : pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
615 : : {
1621 alvherre@alvh.no-ip. 616 : 29 : fprintf(f, "ReadyForQuery\t");
617 : 29 : pqTraceOutputByte1(f, message, cursor);
618 : 29 : }
619 : :
620 : : /*
621 : : * Print the given message to the trace output stream.
622 : : */
623 : : void
624 : 414 : pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
625 : : {
626 : : char id;
627 : : int length;
628 [ + + ]: 414 : char *prefix = toServer ? "F" : "B";
629 : 414 : int logCursor = 0;
630 : : bool regress;
631 : :
632 [ - + ]: 414 : if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
633 : : {
634 : : char timestr[128];
635 : :
1621 alvherre@alvh.no-ip. 636 :UBC 0 : pqTraceFormatTimestamp(timestr, sizeof(timestr));
637 : 0 : fprintf(conn->Pfdebug, "%s\t", timestr);
638 : : }
1621 alvherre@alvh.no-ip. 639 :CBC 414 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
640 : :
641 : 414 : id = message[logCursor++];
642 : :
643 : 414 : memcpy(&length, message + logCursor, 4);
644 : 414 : length = (int) pg_ntoh32(length);
645 : 414 : 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 : : */
492 peter@eisentraut.org 653 [ + - + + : 414 : if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
+ + + + ]
1611 alvherre@alvh.no-ip. 654 : 10 : fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
655 : : else
656 : 404 : fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
657 : :
1621 658 [ + + + - : 414 : switch (id)
+ - + - +
+ - - - -
+ - - + +
+ + - - +
+ + - - -
+ + - ]
659 : : {
746 nathan@postgresql.or 660 : 31 : case PqMsg_ParseComplete:
1621 alvherre@alvh.no-ip. 661 : 31 : fprintf(conn->Pfdebug, "ParseComplete");
662 : : /* No message content */
663 : 31 : break;
746 nathan@postgresql.or 664 : 29 : case PqMsg_BindComplete:
1621 alvherre@alvh.no-ip. 665 : 29 : fprintf(conn->Pfdebug, "BindComplete");
666 : : /* No message content */
667 : 29 : break;
746 nathan@postgresql.or 668 : 4 : case PqMsg_CloseComplete:
1621 alvherre@alvh.no-ip. 669 : 4 : fprintf(conn->Pfdebug, "CloseComplete");
670 : : /* No message content */
671 : 4 : break;
746 nathan@postgresql.or 672 :UBC 0 : case PqMsg_NotificationResponse:
492 peter@eisentraut.org 673 : 0 : pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 674 : 0 : break;
746 nathan@postgresql.or 675 :CBC 36 : case PqMsg_Bind:
492 peter@eisentraut.org 676 : 36 : pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 677 : 36 : break;
746 nathan@postgresql.or 678 :UBC 0 : case PqMsg_CopyDone:
1621 alvherre@alvh.no-ip. 679 : 0 : fprintf(conn->Pfdebug, "CopyDone");
680 : : /* No message content */
681 : 0 : break;
746 nathan@postgresql.or 682 :CBC 41 : case PqMsg_CommandComplete:
683 : : /* Close(F) and CommandComplete(B) use the same identifier. */
684 : : Assert(PqMsg_Close == PqMsg_CommandComplete);
492 peter@eisentraut.org 685 [ + + ]: 41 : if (toServer)
686 : 4 : pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
687 : : else
688 : 37 : pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 689 : 41 : break;
746 nathan@postgresql.or 690 :UBC 0 : case PqMsg_CopyData:
386 alvherre@alvh.no-ip. 691 : 0 : pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
692 : : length, regress);
1621 693 : 0 : break;
746 nathan@postgresql.or 694 :CBC 82 : case PqMsg_Describe:
695 : : /* Describe(F) and DataRow(B) use the same identifier. */
696 : : Assert(PqMsg_Describe == PqMsg_DataRow);
492 peter@eisentraut.org 697 [ + + ]: 82 : if (toServer)
698 : 40 : pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
699 : : else
700 : 42 : pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 701 : 82 : break;
746 nathan@postgresql.or 702 : 43 : case PqMsg_Execute:
703 : : /* Execute(F) and ErrorResponse(B) use the same identifier. */
704 : : Assert(PqMsg_Execute == PqMsg_ErrorResponse);
492 peter@eisentraut.org 705 [ + + ]: 43 : if (toServer)
706 : 36 : pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
707 : : else
708 : 7 : pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 709 : 43 : break;
746 nathan@postgresql.or 710 :UBC 0 : case PqMsg_CopyFail:
492 peter@eisentraut.org 711 : 0 : pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 712 : 0 : break;
390 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 nathan@postgresql.or 746 : 0 : case PqMsg_FunctionCall:
492 peter@eisentraut.org 747 : 0 : pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 748 : 0 : break;
746 nathan@postgresql.or 749 : 0 : case PqMsg_CopyInResponse:
492 peter@eisentraut.org 750 : 0 : pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 751 : 0 : break;
746 nathan@postgresql.or 752 :CBC 7 : case PqMsg_Flush:
753 : : /* Flush(F) and CopyOutResponse(B) use the same identifier */
754 : : Assert(PqMsg_CopyOutResponse == PqMsg_Flush);
492 peter@eisentraut.org 755 [ + - ]: 7 : if (toServer)
1621 alvherre@alvh.no-ip. 756 : 7 : fprintf(conn->Pfdebug, "Flush"); /* no message content */
757 : : else
492 peter@eisentraut.org 758 :UBC 0 : pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 759 :CBC 7 : break;
746 nathan@postgresql.or 760 :UBC 0 : case PqMsg_EmptyQueryResponse:
1621 alvherre@alvh.no-ip. 761 : 0 : fprintf(conn->Pfdebug, "EmptyQueryResponse");
762 : : /* No message content */
763 : 0 : break;
746 nathan@postgresql.or 764 : 0 : case PqMsg_BackendKeyData:
492 peter@eisentraut.org 765 : 0 : pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 766 : 0 : break;
746 nathan@postgresql.or 767 :CBC 5 : case PqMsg_NoData:
1621 alvherre@alvh.no-ip. 768 : 5 : fprintf(conn->Pfdebug, "NoData");
769 : : /* No message content */
770 : 5 : break;
746 nathan@postgresql.or 771 : 3 : case PqMsg_NoticeResponse:
492 peter@eisentraut.org 772 : 3 : pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 773 : 3 : break;
746 nathan@postgresql.or 774 : 36 : case PqMsg_Parse:
492 peter@eisentraut.org 775 : 36 : pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 776 : 36 : break;
746 nathan@postgresql.or 777 : 8 : case PqMsg_Query:
492 peter@eisentraut.org 778 : 8 : pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 779 : 8 : break;
746 nathan@postgresql.or 780 :UBC 0 : case PqMsg_AuthenticationRequest:
386 alvherre@alvh.no-ip. 781 : 0 : pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
782 : : length, regress);
1621 783 : 0 : break;
746 nathan@postgresql.or 784 : 0 : case PqMsg_PortalSuspended:
1621 alvherre@alvh.no-ip. 785 : 0 : fprintf(conn->Pfdebug, "PortalSuspended");
786 : : /* No message content */
787 : 0 : break;
746 nathan@postgresql.or 788 :CBC 21 : case PqMsg_Sync:
789 : : /* ParameterStatus(B) and Sync(F) use the same identifier */
790 : : Assert(PqMsg_ParameterStatus == PqMsg_Sync);
492 peter@eisentraut.org 791 [ + - ]: 21 : if (toServer)
1578 tgl@sss.pgh.pa.us 792 : 21 : fprintf(conn->Pfdebug, "Sync"); /* no message content */
793 : : else
492 peter@eisentraut.org 794 :UBC 0 : pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 795 :CBC 21 : break;
746 nathan@postgresql.or 796 : 1 : case PqMsg_ParameterDescription:
492 peter@eisentraut.org 797 : 1 : pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 798 : 1 : break;
746 nathan@postgresql.or 799 : 29 : case PqMsg_RowDescription:
492 peter@eisentraut.org 800 : 29 : pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
1621 alvherre@alvh.no-ip. 801 : 29 : break;
746 nathan@postgresql.or 802 :UBC 0 : case PqMsg_NegotiateProtocolVersion:
492 peter@eisentraut.org 803 : 0 : pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 804 : 0 : break;
746 nathan@postgresql.or 805 : 0 : case PqMsg_FunctionCallResponse:
492 peter@eisentraut.org 806 : 0 : pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 807 : 0 : break;
746 nathan@postgresql.or 808 : 0 : case PqMsg_CopyBothResponse:
492 peter@eisentraut.org 809 : 0 : pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
1621 alvherre@alvh.no-ip. 810 : 0 : break;
746 nathan@postgresql.or 811 :CBC 9 : case PqMsg_Terminate:
1621 alvherre@alvh.no-ip. 812 : 9 : fprintf(conn->Pfdebug, "Terminate");
813 : : /* No message content */
814 : 9 : break;
746 nathan@postgresql.or 815 : 29 : case PqMsg_ReadyForQuery:
492 peter@eisentraut.org 816 : 29 : pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
1621 alvherre@alvh.no-ip. 817 : 29 : break;
1621 alvherre@alvh.no-ip. 818 :UBC 0 : default:
819 : 0 : fprintf(conn->Pfdebug, "Unknown message: %02x", id);
820 : 0 : break;
821 : : }
822 : :
1621 alvherre@alvh.no-ip. 823 :CBC 414 : 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 [ - + ]: 414 : if (logCursor - 1 != length)
1621 alvherre@alvh.no-ip. 831 :UBC 0 : fprintf(conn->Pfdebug,
832 : : "mismatched message length: consumed %d, expected %d\n",
833 : : logCursor - 1, length);
1621 alvherre@alvh.no-ip. 834 :CBC 414 : }
835 : :
836 : : /*
837 : : * Print special messages (those containing no type byte) to the trace output
838 : : * stream.
839 : : */
840 : : void
1621 alvherre@alvh.no-ip. 841 :UBC 0 : pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
842 : : {
843 : : int length;
844 : : int version;
845 : : bool regress;
846 : 0 : int logCursor = 0;
847 : :
393 848 : 0 : regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
849 : :
1621 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 : :
393 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 : :
1621 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
388 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 : }
|
