PostgreSQL Source Code  git master
fe-trace.c
Go to the documentation of this file.
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 PQtrace(PGconn *conn, FILE *debug_port)
36 {
37  if (conn == NULL)
38  return;
39  PQuntrace(conn);
40  if (debug_port == NULL)
41  return;
42 
43  conn->Pfdebug = debug_port;
44  conn->traceFlags = 0;
45 }
46 
47 /* Disable tracing */
48 void
50 {
51  if (conn == NULL)
52  return;
53  if (conn->Pfdebug)
54  {
56  conn->Pfdebug = NULL;
57  }
58 
59  conn->traceFlags = 0;
60 }
61 
62 /* Set flags for current tracing session */
63 void
65 {
66  if (conn == NULL)
67  return;
68  /* If PQtrace() failed, do nothing. */
69  if (conn->Pfdebug == NULL)
70  return;
71  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 pqTraceFormatTimestamp(char *timestr, size_t ts_len)
81 {
82  struct timeval tval;
83  time_t now;
84  struct tm tmbuf;
85 
86  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  now = tval.tv_sec;
95  strftime(timestr, ts_len,
96  "%Y-%m-%d %H:%M:%S",
97  localtime_r(&now, &tmbuf));
98  /* append microseconds */
99  snprintf(timestr + strlen(timestr), ts_len - strlen(timestr),
100  ".%06u", (unsigned int) (tval.tv_usec));
101 }
102 
103 /*
104  * pqTraceOutputByte1: output a 1-char message to the log
105  */
106 static void
107 pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor)
108 {
109  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  if (!isprint((unsigned char) *v))
116  fprintf(pfdebug, " \\x%02x", *v);
117  else
118  fprintf(pfdebug, " %c", *v);
119  *cursor += 1;
120 }
121 
122 /*
123  * pqTraceOutputInt16: output a 2-byte integer message to the log
124  */
125 static int
126 pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor)
127 {
128  uint16 tmp;
129  int result;
130 
131  memcpy(&tmp, data + *cursor, 2);
132  *cursor += 2;
133  result = (int) pg_ntoh16(tmp);
134  fprintf(pfdebug, " %d", result);
135 
136  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 pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress)
146 {
147  int result;
148 
149  memcpy(&result, data + *cursor, 4);
150  *cursor += 4;
151  result = (int) pg_ntoh32(result);
152  if (suppress)
153  fprintf(pfdebug, " NNNN");
154  else
155  fprintf(pfdebug, " %d", result);
156 
157  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 pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
167 {
168  int len;
169 
170  if (suppress)
171  {
172  fprintf(pfdebug, " \"SSSS\"");
173  *cursor += strlen(data + *cursor) + 1;
174  }
175  else
176  {
177  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  *cursor += (len - 3 + 1);
184  }
185 }
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 pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
194 {
195  int i,
196  next; /* first char not yet printed */
197  const char *v = data + *cursor;
198 
199  if (suppress)
200  {
201  fprintf(pfdebug, " 'BBBB'");
202  *cursor += len;
203  return;
204  }
205 
206  fprintf(pfdebug, " \'");
207 
208  for (next = i = 0; i < len; ++i)
209  {
210  if (isprint((unsigned char) v[i]))
211  continue;
212  else
213  {
214  fwrite(v + next, 1, i - next, pfdebug);
215  fprintf(pfdebug, "\\x%02x", v[i]);
216  next = i + 1;
217  }
218  }
219  if (next < len)
220  fwrite(v + next, 1, len - next, pfdebug);
221 
222  fprintf(pfdebug, "\'");
223  *cursor += len;
224 }
225 
226 /*
227  * Output functions by protocol message type
228  */
229 
230 static void
231 pqTraceOutput_NotificationResponse(FILE *f, const char *message, int *cursor, bool regress)
232 {
233  fprintf(f, "NotificationResponse\t");
234  pqTraceOutputInt32(f, message, cursor, regress);
235  pqTraceOutputString(f, message, cursor, false);
236  pqTraceOutputString(f, message, cursor, false);
237 }
238 
239 static void
240 pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
241 {
242  int nparams;
243 
244  fprintf(f, "Bind\t");
245  pqTraceOutputString(f, message, cursor, false);
246  pqTraceOutputString(f, message, cursor, false);
247  nparams = pqTraceOutputInt16(f, message, cursor);
248 
249  for (int i = 0; i < nparams; i++)
250  pqTraceOutputInt16(f, message, cursor);
251 
252  nparams = pqTraceOutputInt16(f, message, cursor);
253 
254  for (int i = 0; i < nparams; i++)
255  {
256  int nbytes;
257 
258  nbytes = pqTraceOutputInt32(f, message, cursor, false);
259  if (nbytes == -1)
260  continue;
261  pqTraceOutputNchar(f, nbytes, message, cursor, false);
262  }
263 
264  nparams = pqTraceOutputInt16(f, message, cursor);
265  for (int i = 0; i < nparams; i++)
266  pqTraceOutputInt16(f, message, cursor);
267 }
268 
269 static void
270 pqTraceOutput_Close(FILE *f, const char *message, int *cursor)
271 {
272  fprintf(f, "Close\t");
273  pqTraceOutputByte1(f, message, cursor);
274  pqTraceOutputString(f, message, cursor, false);
275 }
276 
277 static void
278 pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
279 {
280  fprintf(f, "CommandComplete\t");
281  pqTraceOutputString(f, message, cursor, false);
282 }
283 
284 static void
285 pqTraceOutput_CopyData(FILE *f, const char *message, int *cursor, int length,
286  bool suppress)
287 {
288  fprintf(f, "CopyData\t");
289  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, suppress);
290 }
291 
292 static void
293 pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
294 {
295  int nfields;
296  int len;
297  int i;
298 
299  fprintf(f, "DataRow\t");
300  nfields = pqTraceOutputInt16(f, message, cursor);
301  for (i = 0; i < nfields; i++)
302  {
303  len = pqTraceOutputInt32(f, message, cursor, false);
304  if (len == -1)
305  continue;
306  pqTraceOutputNchar(f, len, message, cursor, false);
307  }
308 }
309 
310 static void
311 pqTraceOutput_Describe(FILE *f, const char *message, int *cursor)
312 {
313  fprintf(f, "Describe\t");
314  pqTraceOutputByte1(f, message, cursor);
315  pqTraceOutputString(f, message, cursor, false);
316 }
317 
318 /* shared code NoticeResponse / ErrorResponse */
319 static void
320 pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor,
321  bool regress)
322 {
323  fprintf(f, "%s\t", type);
324  for (;;)
325  {
326  char field;
327  bool suppress;
328 
329  pqTraceOutputByte1(f, message, cursor);
330  field = message[*cursor - 1];
331  if (field == '\0')
332  break;
333 
334  suppress = regress && (field == 'L' || field == 'F' || field == 'R');
335  pqTraceOutputString(f, message, cursor, suppress);
336  }
337 }
338 
339 static void
340 pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress)
341 {
342  pqTraceOutputNR(f, "ErrorResponse", message, cursor, regress);
343 }
344 
345 static void
346 pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress)
347 {
348  pqTraceOutputNR(f, "NoticeResponse", message, cursor, regress);
349 }
350 
351 static void
352 pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress)
353 {
354  fprintf(f, "Execute\t");
355  pqTraceOutputString(f, message, cursor, false);
356  pqTraceOutputInt32(f, message, cursor, false);
357 }
358 
359 static void
360 pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor)
361 {
362  fprintf(f, "CopyFail\t");
363  pqTraceOutputString(f, message, cursor, false);
364 }
365 
366 static void
367 pqTraceOutput_GSSResponse(FILE *f, const char *message, int *cursor,
368  int length, bool regress)
369 {
370  fprintf(f, "GSSResponse\t");
371  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
372 }
373 
374 static void
375 pqTraceOutput_PasswordMessage(FILE *f, const char *message, int *cursor)
376 {
377  fprintf(f, "PasswordMessage\t");
378  pqTraceOutputString(f, message, cursor, false);
379 }
380 
381 static void
382 pqTraceOutput_SASLInitialResponse(FILE *f, const char *message, int *cursor,
383  bool regress)
384 {
385  int initialResponse;
386 
387  fprintf(f, "SASLInitialResponse\t");
388  pqTraceOutputString(f, message, cursor, false);
389  initialResponse = pqTraceOutputInt32(f, message, cursor, false);
390  if (initialResponse != -1)
391  pqTraceOutputNchar(f, initialResponse, message, cursor, regress);
392 }
393 
394 static void
395 pqTraceOutput_SASLResponse(FILE *f, const char *message, int *cursor,
396  int length, bool regress)
397 {
398  fprintf(f, "SASLResponse\t");
399  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor, regress);
400 }
401 
402 static void
403 pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regress)
404 {
405  int nfields;
406  int nbytes;
407 
408  fprintf(f, "FunctionCall\t");
409  pqTraceOutputInt32(f, message, cursor, regress);
410  nfields = pqTraceOutputInt16(f, message, cursor);
411 
412  for (int i = 0; i < nfields; i++)
413  pqTraceOutputInt16(f, message, cursor);
414 
415  nfields = pqTraceOutputInt16(f, message, cursor);
416 
417  for (int i = 0; i < nfields; i++)
418  {
419  nbytes = pqTraceOutputInt32(f, message, cursor, false);
420  if (nbytes == -1)
421  continue;
422  pqTraceOutputNchar(f, nbytes, message, cursor, false);
423  }
424 
425  pqTraceOutputInt16(f, message, cursor);
426 }
427 
428 static void
429 pqTraceOutput_CopyInResponse(FILE *f, const char *message, int *cursor)
430 {
431  int nfields;
432 
433  fprintf(f, "CopyInResponse\t");
434  pqTraceOutputByte1(f, message, cursor);
435  nfields = pqTraceOutputInt16(f, message, cursor);
436 
437  for (int i = 0; i < nfields; i++)
438  pqTraceOutputInt16(f, message, cursor);
439 }
440 
441 static void
442 pqTraceOutput_CopyOutResponse(FILE *f, const char *message, int *cursor)
443 {
444  int nfields;
445 
446  fprintf(f, "CopyOutResponse\t");
447  pqTraceOutputByte1(f, message, cursor);
448  nfields = pqTraceOutputInt16(f, message, cursor);
449 
450  for (int i = 0; i < nfields; i++)
451  pqTraceOutputInt16(f, message, cursor);
452 }
453 
454 static void
455 pqTraceOutput_BackendKeyData(FILE *f, const char *message, int *cursor, bool regress)
456 {
457  fprintf(f, "BackendKeyData\t");
458  pqTraceOutputInt32(f, message, cursor, regress);
459  pqTraceOutputInt32(f, message, cursor, regress);
460 }
461 
462 static void
463 pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
464 {
465  int nparams;
466 
467  fprintf(f, "Parse\t");
468  pqTraceOutputString(f, message, cursor, false);
469  pqTraceOutputString(f, message, cursor, false);
470  nparams = pqTraceOutputInt16(f, message, cursor);
471 
472  for (int i = 0; i < nparams; i++)
473  pqTraceOutputInt32(f, message, cursor, regress);
474 }
475 
476 static void
477 pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
478 {
479  fprintf(f, "Query\t");
480  pqTraceOutputString(f, message, cursor, false);
481 }
482 
483 static void
484 pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor,
485  int length, bool suppress)
486 {
487  int authType = 0;
488 
489  memcpy(&authType, message + *cursor, 4);
490  authType = (int) pg_ntoh32(authType);
491  *cursor += 4;
492  switch (authType)
493  {
494  case AUTH_REQ_OK:
495  fprintf(f, "AuthenticationOk");
496  break;
497  /* AUTH_REQ_KRB4 not supported */
498  /* AUTH_REQ_KRB5 not supported */
499  case AUTH_REQ_PASSWORD:
500  fprintf(f, "AuthenticationCleartextPassword");
501  break;
502  /* AUTH_REQ_CRYPT not supported */
503  case AUTH_REQ_MD5:
504  fprintf(f, "AuthenticationMD5Password");
505  break;
506  case AUTH_REQ_GSS:
507  fprintf(f, "AuthenticationGSS");
508  break;
509  case AUTH_REQ_GSS_CONT:
510  fprintf(f, "AuthenticationGSSContinue\t");
511  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
512  suppress);
513  break;
514  case AUTH_REQ_SSPI:
515  fprintf(f, "AuthenticationSSPI");
516  break;
517  case AUTH_REQ_SASL:
518  fprintf(f, "AuthenticationSASL\t");
519  while (message[*cursor] != '\0')
520  pqTraceOutputString(f, message, cursor, false);
521  pqTraceOutputString(f, message, cursor, false);
522  break;
523  case AUTH_REQ_SASL_CONT:
524  fprintf(f, "AuthenticationSASLContinue\t");
525  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
526  suppress);
527  break;
528  case AUTH_REQ_SASL_FIN:
529  fprintf(f, "AuthenticationSASLFinal\t");
530  pqTraceOutputNchar(f, length - *cursor + 1, message, cursor,
531  suppress);
532  break;
533  default:
534  fprintf(f, "Unknown authentication message %d", authType);
535  }
536 }
537 
538 static void
539 pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor)
540 {
541  fprintf(f, "ParameterStatus\t");
542  pqTraceOutputString(f, message, cursor, false);
543  pqTraceOutputString(f, message, cursor, false);
544 }
545 
546 static void
547 pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
548 {
549  int nfields;
550 
551  fprintf(f, "ParameterDescription\t");
552  nfields = pqTraceOutputInt16(f, message, cursor);
553 
554  for (int i = 0; i < nfields; i++)
555  pqTraceOutputInt32(f, message, cursor, regress);
556 }
557 
558 static void
559 pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
560 {
561  int nfields;
562 
563  fprintf(f, "RowDescription\t");
564  nfields = pqTraceOutputInt16(f, message, cursor);
565 
566  for (int i = 0; i < nfields; i++)
567  {
568  pqTraceOutputString(f, message, cursor, false);
569  pqTraceOutputInt32(f, message, cursor, regress);
570  pqTraceOutputInt16(f, message, cursor);
571  pqTraceOutputInt32(f, message, cursor, regress);
572  pqTraceOutputInt16(f, message, cursor);
573  pqTraceOutputInt32(f, message, cursor, false);
574  pqTraceOutputInt16(f, message, cursor);
575  }
576 }
577 
578 static void
579 pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
580 {
581  fprintf(f, "NegotiateProtocolVersion\t");
582  pqTraceOutputInt32(f, message, cursor, false);
583  pqTraceOutputInt32(f, message, cursor, false);
584 }
585 
586 static void
587 pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
588 {
589  int len;
590 
591  fprintf(f, "FunctionCallResponse\t");
592  len = pqTraceOutputInt32(f, message, cursor, false);
593  if (len != -1)
594  pqTraceOutputNchar(f, len, message, cursor, false);
595 }
596 
597 static void
598 pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
599 {
600  fprintf(f, "CopyBothResponse\t");
601  pqTraceOutputByte1(f, message, cursor);
602 
603  while (length > *cursor)
604  pqTraceOutputInt16(f, message, cursor);
605 }
606 
607 static void
608 pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
609 {
610  fprintf(f, "ReadyForQuery\t");
611  pqTraceOutputByte1(f, message, cursor);
612 }
613 
614 /*
615  * Print the given message to the trace output stream.
616  */
617 void
618 pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
619 {
620  char id;
621  int length;
622  char *prefix = toServer ? "F" : "B";
623  int logCursor = 0;
624  bool regress;
625 
627  {
628  char timestr[128];
629 
630  pqTraceFormatTimestamp(timestr, sizeof(timestr));
631  fprintf(conn->Pfdebug, "%s\t", timestr);
632  }
633  regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
634 
635  id = message[logCursor++];
636 
637  memcpy(&length, message + logCursor, 4);
638  length = (int) pg_ntoh32(length);
639  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  if (regress && !toServer && (id == PqMsg_ErrorResponse || id == PqMsg_NoticeResponse))
648  fprintf(conn->Pfdebug, "%s\tNN\t", prefix);
649  else
650  fprintf(conn->Pfdebug, "%s\t%d\t", prefix, length);
651 
652  switch (id)
653  {
654  case PqMsg_ParseComplete:
655  fprintf(conn->Pfdebug, "ParseComplete");
656  /* No message content */
657  break;
658  case PqMsg_BindComplete:
659  fprintf(conn->Pfdebug, "BindComplete");
660  /* No message content */
661  break;
662  case PqMsg_CloseComplete:
663  fprintf(conn->Pfdebug, "CloseComplete");
664  /* No message content */
665  break;
667  pqTraceOutput_NotificationResponse(conn->Pfdebug, message, &logCursor, regress);
668  break;
669  case PqMsg_Bind:
670  pqTraceOutput_Bind(conn->Pfdebug, message, &logCursor);
671  break;
672  case PqMsg_CopyDone:
673  fprintf(conn->Pfdebug, "CopyDone");
674  /* No message content */
675  break;
677  /* Close(F) and CommandComplete(B) use the same identifier. */
679  if (toServer)
680  pqTraceOutput_Close(conn->Pfdebug, message, &logCursor);
681  else
682  pqTraceOutput_CommandComplete(conn->Pfdebug, message, &logCursor);
683  break;
684  case PqMsg_CopyData:
685  pqTraceOutput_CopyData(conn->Pfdebug, message, &logCursor,
686  length, regress);
687  break;
688  case PqMsg_Describe:
689  /* Describe(F) and DataRow(B) use the same identifier. */
691  if (toServer)
692  pqTraceOutput_Describe(conn->Pfdebug, message, &logCursor);
693  else
694  pqTraceOutput_DataRow(conn->Pfdebug, message, &logCursor);
695  break;
696  case PqMsg_Execute:
697  /* Execute(F) and ErrorResponse(B) use the same identifier. */
699  if (toServer)
700  pqTraceOutput_Execute(conn->Pfdebug, message, &logCursor, regress);
701  else
702  pqTraceOutput_ErrorResponse(conn->Pfdebug, message, &logCursor, regress);
703  break;
704  case PqMsg_CopyFail:
705  pqTraceOutput_CopyFail(conn->Pfdebug, message, &logCursor);
706  break;
707  case PqMsg_GSSResponse:
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  switch (conn->current_auth_response)
717  {
718  case AUTH_RESPONSE_GSS:
720  &logCursor, length, regress);
721  break;
724  &logCursor);
725  break;
728  &logCursor, regress);
729  break;
730  case AUTH_RESPONSE_SASL:
732  &logCursor, length, regress);
733  break;
734  default:
735  fprintf(conn->Pfdebug, "UnknownAuthenticationResponse");
736  break;
737  }
738  conn->current_auth_response = '\0';
739  break;
740  case PqMsg_FunctionCall:
741  pqTraceOutput_FunctionCall(conn->Pfdebug, message, &logCursor, regress);
742  break;
744  pqTraceOutput_CopyInResponse(conn->Pfdebug, message, &logCursor);
745  break;
746  case PqMsg_Flush:
747  /* Flush(F) and CopyOutResponse(B) use the same identifier */
749  if (toServer)
750  fprintf(conn->Pfdebug, "Flush"); /* no message content */
751  else
752  pqTraceOutput_CopyOutResponse(conn->Pfdebug, message, &logCursor);
753  break;
755  fprintf(conn->Pfdebug, "EmptyQueryResponse");
756  /* No message content */
757  break;
759  pqTraceOutput_BackendKeyData(conn->Pfdebug, message, &logCursor, regress);
760  break;
761  case PqMsg_NoData:
762  fprintf(conn->Pfdebug, "NoData");
763  /* No message content */
764  break;
766  pqTraceOutput_NoticeResponse(conn->Pfdebug, message, &logCursor, regress);
767  break;
768  case PqMsg_Parse:
769  pqTraceOutput_Parse(conn->Pfdebug, message, &logCursor, regress);
770  break;
771  case PqMsg_Query:
772  pqTraceOutput_Query(conn->Pfdebug, message, &logCursor);
773  break;
775  pqTraceOutput_Authentication(conn->Pfdebug, message, &logCursor,
776  length, regress);
777  break;
779  fprintf(conn->Pfdebug, "PortalSuspended");
780  /* No message content */
781  break;
782  case PqMsg_Sync:
783  /* ParameterStatus(B) and Sync(F) use the same identifier */
785  if (toServer)
786  fprintf(conn->Pfdebug, "Sync"); /* no message content */
787  else
788  pqTraceOutput_ParameterStatus(conn->Pfdebug, message, &logCursor);
789  break;
791  pqTraceOutput_ParameterDescription(conn->Pfdebug, message, &logCursor, regress);
792  break;
794  pqTraceOutput_RowDescription(conn->Pfdebug, message, &logCursor, regress);
795  break;
797  pqTraceOutput_NegotiateProtocolVersion(conn->Pfdebug, message, &logCursor);
798  break;
800  pqTraceOutput_FunctionCallResponse(conn->Pfdebug, message, &logCursor);
801  break;
803  pqTraceOutput_CopyBothResponse(conn->Pfdebug, message, &logCursor, length);
804  break;
805  case PqMsg_Terminate:
806  fprintf(conn->Pfdebug, "Terminate");
807  /* No message content */
808  break;
809  case PqMsg_ReadyForQuery:
810  pqTraceOutput_ReadyForQuery(conn->Pfdebug, message, &logCursor);
811  break;
812  default:
813  fprintf(conn->Pfdebug, "Unknown message: %02x", id);
814  break;
815  }
816 
817  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  if (logCursor - 1 != length)
826  "mismatched message length: consumed %d, expected %d\n",
827  logCursor - 1, length);
828 }
829 
830 /*
831  * Print special messages (those containing no type byte) to the trace output
832  * stream.
833  */
834 void
836 {
837  int length;
838  int version;
839  bool regress;
840  int logCursor = 0;
841 
842  regress = (conn->traceFlags & PQTRACE_REGRESS_MODE) != 0;
843 
845  {
846  char timestr[128];
847 
848  pqTraceFormatTimestamp(timestr, sizeof(timestr));
849  fprintf(conn->Pfdebug, "%s\t", timestr);
850  }
851 
852  memcpy(&length, message + logCursor, 4);
853  length = (int) pg_ntoh32(length);
854  logCursor += 4;
855 
856  fprintf(conn->Pfdebug, "F\t%d\t", length);
857 
858  if (length < 8)
859  {
860  fprintf(conn->Pfdebug, "Unknown message\n");
861  return;
862  }
863 
864  memcpy(&version, message + logCursor, 4);
865  version = (int) pg_ntoh32(version);
866 
867  if (version == CANCEL_REQUEST_CODE && length >= 16)
868  {
869  fprintf(conn->Pfdebug, "CancelRequest\t");
870  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
871  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
872  pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
873  pqTraceOutputInt32(conn->Pfdebug, message, &logCursor, regress);
874  }
875  else if (version == NEGOTIATE_SSL_CODE)
876  {
877  fprintf(conn->Pfdebug, "SSLRequest\t");
878  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
879  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
880  }
881  else if (version == NEGOTIATE_GSS_CODE)
882  {
883  fprintf(conn->Pfdebug, "GSSENCRequest\t");
884  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
885  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
886  }
887  else
888  {
889  fprintf(conn->Pfdebug, "StartupMessage\t");
890  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
891  pqTraceOutputInt16(conn->Pfdebug, message, &logCursor);
892  while (message[logCursor] != '\0')
893  {
894  /* XXX should we suppress anything in regress mode? */
895  pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
896  pqTraceOutputString(conn->Pfdebug, message, &logCursor, false);
897  }
898  }
899 
900  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 pqTraceOutputCharResponse(PGconn *conn, const char *responseType,
910  char response)
911 {
913  {
914  char timestr[128];
915 
916  pqTraceFormatTimestamp(timestr, sizeof(timestr));
917  fprintf(conn->Pfdebug, "%s\t", timestr);
918  }
919 
920  fprintf(conn->Pfdebug, "B\t1\t%s\t %c\n", responseType, response);
921 }
Datum now(PG_FUNCTION_ARGS)
Definition: timestamp.c:1608
static int32 next
Definition: blutils.c:219
unsigned short uint16
Definition: c.h:491
#define Assert(condition)
Definition: c.h:837
static void pqTraceOutput_RowDescription(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:559
static void pqTraceOutput_GSSResponse(FILE *f, const char *message, int *cursor, int length, bool regress)
Definition: fe-trace.c:367
static void pqTraceOutputString(FILE *pfdebug, const char *data, int *cursor, bool suppress)
Definition: fe-trace.c:166
static void pqTraceOutput_FunctionCall(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:403
static void pqTraceOutput_CopyInResponse(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:429
static void pqTraceOutput_BackendKeyData(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:455
static void pqTraceOutput_Authentication(FILE *f, const char *message, int *cursor, int length, bool suppress)
Definition: fe-trace.c:484
static void pqTraceOutput_Parse(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:463
static void pqTraceOutput_NoticeResponse(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:346
void PQtrace(PGconn *conn, FILE *debug_port)
Definition: fe-trace.c:35
static void pqTraceOutput_ParameterDescription(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:547
static void pqTraceOutputNchar(FILE *pfdebug, int len, const char *data, int *cursor, bool suppress)
Definition: fe-trace.c:193
static void pqTraceOutput_DataRow(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:293
static void pqTraceOutput_SASLResponse(FILE *f, const char *message, int *cursor, int length, bool regress)
Definition: fe-trace.c:395
static void pqTraceOutput_Query(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:477
static void pqTraceOutput_CopyData(FILE *f, const char *message, int *cursor, int length, bool suppress)
Definition: fe-trace.c:285
static int pqTraceOutputInt16(FILE *pfdebug, const char *data, int *cursor)
Definition: fe-trace.c:126
static void pqTraceOutput_SASLInitialResponse(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:382
static void pqTraceOutput_NegotiateProtocolVersion(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:579
static void pqTraceOutput_CopyBothResponse(FILE *f, const char *message, int *cursor, int length)
Definition: fe-trace.c:598
static void pqTraceOutput_Bind(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:240
static void pqTraceOutput_ErrorResponse(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:340
static void pqTraceOutputNR(FILE *f, const char *type, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:320
static void pqTraceOutput_Close(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:270
static void pqTraceOutputByte1(FILE *pfdebug, const char *data, int *cursor)
Definition: fe-trace.c:107
static void pqTraceOutput_Describe(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:311
void pqTraceOutputMessage(PGconn *conn, const char *message, bool toServer)
Definition: fe-trace.c:618
static void pqTraceOutput_NotificationResponse(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:231
static void pqTraceOutput_CommandComplete(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:278
void PQsetTraceFlags(PGconn *conn, int flags)
Definition: fe-trace.c:64
static void pqTraceOutput_ParameterStatus(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:539
static void pqTraceOutput_Execute(FILE *f, const char *message, int *cursor, bool regress)
Definition: fe-trace.c:352
void PQuntrace(PGconn *conn)
Definition: fe-trace.c:49
static void pqTraceOutput_CopyOutResponse(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:442
static void pqTraceOutput_ReadyForQuery(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:608
static int pqTraceOutputInt32(FILE *pfdebug, const char *data, int *cursor, bool suppress)
Definition: fe-trace.c:145
void pqTraceOutputNoTypeByteMessage(PGconn *conn, const char *message)
Definition: fe-trace.c:835
void pqTraceOutputCharResponse(PGconn *conn, const char *responseType, char response)
Definition: fe-trace.c:909
static void pqTraceFormatTimestamp(char *timestr, size_t ts_len)
Definition: fe-trace.c:80
static void pqTraceOutput_CopyFail(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:360
static void pqTraceOutput_PasswordMessage(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:375
static void pqTraceOutput_FunctionCallResponse(FILE *f, const char *message, int *cursor)
Definition: fe-trace.c:587
int i
Definition: isn.c:72
#define PQTRACE_SUPPRESS_TIMESTAMPS
Definition: libpq-fe.h:466
#define PQTRACE_REGRESS_MODE
Definition: libpq-fe.h:468
#define AUTH_RESPONSE_PASSWORD
Definition: libpq-int.h:342
#define AUTH_RESPONSE_SASL
Definition: libpq-int.h:344
#define AUTH_RESPONSE_SASL_INITIAL
Definition: libpq-int.h:343
#define AUTH_RESPONSE_GSS
Definition: libpq-int.h:341
static void const char fflush(stdout)
static struct pg_tm tm
Definition: localtime.c:104
#define pg_ntoh32(x)
Definition: pg_bswap.h:125
#define pg_ntoh16(x)
Definition: pg_bswap.h:124
const void size_t len
const void * data
#define snprintf
Definition: port.h:238
#define fprintf
Definition: port.h:242
#define CANCEL_REQUEST_CODE
Definition: pqcomm.h:133
#define NEGOTIATE_GSS_CODE
Definition: pqcomm.h:168
#define NEGOTIATE_SSL_CODE
Definition: pqcomm.h:167
#define PqMsg_CloseComplete
Definition: protocol.h:40
#define AUTH_REQ_SSPI
Definition: protocol.h:83
#define AUTH_REQ_SASL_CONT
Definition: protocol.h:85
#define PqMsg_CopyDone
Definition: protocol.h:64
#define PqMsg_NotificationResponse
Definition: protocol.h:41
#define PqMsg_BindComplete
Definition: protocol.h:39
#define PqMsg_CopyData
Definition: protocol.h:65
#define PqMsg_ParameterDescription
Definition: protocol.h:58
#define PqMsg_FunctionCall
Definition: protocol.h:23
#define PqMsg_GSSResponse
Definition: protocol.h:30
#define AUTH_REQ_GSS
Definition: protocol.h:81
#define PqMsg_SASLResponse
Definition: protocol.h:33
#define AUTH_REQ_MD5
Definition: protocol.h:79
#define PqMsg_Describe
Definition: protocol.h:21
#define AUTH_REQ_OK
Definition: protocol.h:74
#define PqMsg_FunctionCallResponse
Definition: protocol.h:53
#define PqMsg_SASLInitialResponse
Definition: protocol.h:32
#define PqMsg_ReadyForQuery
Definition: protocol.h:55
#define PqMsg_AuthenticationRequest
Definition: protocol.h:50
#define PqMsg_CopyInResponse
Definition: protocol.h:45
#define PqMsg_EmptyQueryResponse
Definition: protocol.h:47
#define PqMsg_RowDescription
Definition: protocol.h:52
#define PqMsg_CopyBothResponse
Definition: protocol.h:54
#define PqMsg_ParameterStatus
Definition: protocol.h:51
#define PqMsg_NoData
Definition: protocol.h:56
#define PqMsg_NegotiateProtocolVersion
Definition: protocol.h:59
#define PqMsg_PortalSuspended
Definition: protocol.h:57
#define AUTH_REQ_PASSWORD
Definition: protocol.h:77
#define AUTH_REQ_GSS_CONT
Definition: protocol.h:82
#define PqMsg_Parse
Definition: protocol.h:25
#define PqMsg_Bind
Definition: protocol.h:19
#define PqMsg_PasswordMessage
Definition: protocol.h:31
#define PqMsg_Sync
Definition: protocol.h:27
#define PqMsg_CopyFail
Definition: protocol.h:29
#define PqMsg_Flush
Definition: protocol.h:24
#define PqMsg_BackendKeyData
Definition: protocol.h:48
#define PqMsg_CommandComplete
Definition: protocol.h:42
#define PqMsg_Query
Definition: protocol.h:26
#define PqMsg_ErrorResponse
Definition: protocol.h:44
#define PqMsg_DataRow
Definition: protocol.h:43
#define AUTH_REQ_SASL
Definition: protocol.h:84
#define PqMsg_NoticeResponse
Definition: protocol.h:49
#define PqMsg_Terminate
Definition: protocol.h:28
#define PqMsg_Execute
Definition: protocol.h:22
#define PqMsg_Close
Definition: protocol.h:20
#define PqMsg_CopyOutResponse
Definition: protocol.h:46
#define AUTH_REQ_SASL_FIN
Definition: protocol.h:86
#define PqMsg_ParseComplete
Definition: protocol.h:38
PGconn * conn
Definition: streamutil.c:53
Definition: type.h:138
char current_auth_response
Definition: libpq-int.h:505
FILE * Pfdebug
Definition: libpq-int.h:436
int traceFlags
Definition: libpq-int.h:437
const char * type
int gettimeofday(struct timeval *tp, void *tzp)