src/src/debug.c

   1 /*************************************************
   2 *     Exim - an Internet mail transport agent    *
   3 *************************************************/
   4
   5 /* Copyright (c) The Exim Maintainers 2015 - 2022 */
   6 /* Copyright (c) University of Cambridge 1995 - 2018 */
   7 /* See the file NOTICE for conditions of use and distribution. */
   8 /* SPDX-License-Identifier: GPL-2.0-or-later */
   9
  10
  11 #include "exim.h"
  12
  13 static uschar  debug_buffer[2048];
  14 static uschar *debug_ptr = debug_buffer;
  15 static int     debug_prefix_length = 0;
  16
  17 static unsigned pretrigger_writeoff;
  18 static unsigned pretrigger_readoff;
  19
  20
  21 const uschar * rc_names[] = {           /* Mostly for debug output */
  22   [OK] =                US"OK",
  23   [DEFER] =             US"DEFER",
  24   [FAIL] =              US"FAIL",
  25   [ERROR] =             US"ERROR",
  26   [FAIL_FORCED] =       US"FAIL_FORCED",
  27   [DECLINE] =           US"DECLINE",
  28   [PASS] =              US"PASS",
  29   [DISCARD] =           US"DISCARD",
  30   [SKIP] =              US"SKIP",
  31   [REROUTED] =          US"REROUTED",
  32   [PANIC] =             US"PANIC",
  33   [BAD64] =             US"BAD64",
  34   [UNEXPECTED] =        US"UNEXPECTED",
  35   [CANCELLED] =         US"CANCELLED",
  36   [FAIL_SEND] =         US"FAIL_SEND",
  37   [FAIL_DROP] =         US"FAIL_DROP",
  38   [DANE] =              US"DANE",
  39 };
  40
  41 const uschar * dns_rc_names[] = {
  42   [DNS_SUCCEED] =       US"DNS_SUCCEED",
  43   [DNS_NOMATCH] =       US"DNS_NOMATCH",
  44   [DNS_NODATA] =        US"DNS_NODATA",
  45   [DNS_AGAIN] =         US"DNS_AGAIN",
  46   [DNS_FAIL] =          US"DNS_FAIL",
  47 };
  48
  49
  50 /*************************************************
  51 *               Print tree                       *
  52 *************************************************/
  53
  54 /* Recursive tree-printing subroutine. It uses a static vector of uschar to
  55 hold the line-drawing characters that need to be printed on every line as it
  56 moves down the page. This function is used only in debugging circumstances. The
  57 output is done via debug_printf(). */
  58
  59 #define TREE_PRINTLINESIZE 132   /* line size for printing */
  60 static uschar tree_printline[TREE_PRINTLINESIZE];
  61
  62 /* Internal recursive subroutine.
  63
  64 Arguments:
  65   p          tree node
  66   pos        amount of indenting & vertical bars to print
  67   barswitch  if TRUE print | at the pos value
  68
  69 Returns:     nothing
  70 */
  71
  72 static void
  73 tree_printsub(tree_node * p, int pos, int barswitch)
  74 {
  75 if (p->right) tree_printsub(p->right, pos+2, 1);
  76 for (int i = 0; i <= pos-1; i++) debug_printf_indent(" %c", tree_printline[i]);
  77 debug_printf_indent(" -->%s [%d]\n", p->name, p->balance);
  78 tree_printline[pos] = barswitch ? '|' : ' ';
  79 if (p->left)
  80   {
  81   tree_printline[pos+2] = '|';
  82   tree_printsub(p->left, pos+2, 0);
  83   }
  84 }
  85
  86 /* The external function, with just a tree node argument. */
  87
  88 void
  89 debug_print_tree(const char * title, tree_node * p)
  90 {
  91 debug_printf_indent("%s:\n", title);
  92 for (int i = 0; i < TREE_PRINTLINESIZE; i++) tree_printline[i] = ' ';
  93 if (!p) debug_printf_indent(" Empty Tree\n"); else tree_printsub(p, 0, 0);
  94 debug_printf_indent("---- End of tree ----\n");
  95 }
  96
  97
  98
  99 /*************************************************
 100 *          Print an argv vector                  *
 101 *************************************************/
 102
 103 /* Called when about to obey execv().
 104
 105 Argument:    the argv vector
 106 Returns:     nothing
 107 */
 108
 109 void
 110 debug_print_argv(const uschar ** argv)
 111 {
 112 debug_printf("exec");
 113 while (*argv) debug_printf(" %.256s", *argv++);
 114 debug_printf("\n");
 115 }
 116
 117
 118
 119 /*************************************************
 120 *      Expand and print debugging string         *
 121 *************************************************/
 122
 123 /* The string is expanded and written as debugging output. If
 124 expansion fails, a message is written instead.
 125
 126 Argument:    the string
 127 Returns:     nothing
 128 */
 129
 130 void
 131 debug_print_string(uschar *debug_string)
 132 {
 133 if (!debug_string) return;
 134 HDEBUG(D_any|D_v)
 135   {
 136   uschar *s = expand_string(debug_string);
 137   if (!s)
 138     debug_printf("failed to expand debug_output \"%s\": %s\n", debug_string,
 139       expand_string_message);
 140   else if (s[0] != 0)
 141     debug_printf("%s%s", s, (s[Ustrlen(s)-1] == '\n')? "" : "\n");
 142   }
 143 }
 144
 145
 146
 147 /*************************************************
 148 *      Print current uids and gids               *
 149 *************************************************/
 150
 151 /*
 152 Argument:   an introductory string
 153 Returns:    nothing
 154 */
 155
 156 void
 157 debug_print_ids(uschar *s)
 158 {
 159 debug_printf("%s uid=%ld gid=%ld euid=%ld egid=%ld\n", s,
 160   (long int)getuid(), (long int)getgid(), (long int)geteuid(),
 161   (long int)getegid());
 162 }
 163
 164 /************************************************/
 165
 166 /* Give a string for a return-code */
 167
 168 const uschar *
 169 rc_to_string(int rc)
 170 {
 171 return rc < 0 || rc >= nelem(rc_names) ? US"?" : rc_names[rc];
 172 }
 173
 174
 175
 176
 177
 178 /*************************************************
 179 *           Print debugging message              *
 180 *************************************************/
 181
 182 /* There are two entries, one for use when being called directly from a
 183 function with a variable argument list, one for prepending an indent.
 184
 185 If debug_pid is nonzero, print the pid at the start of each line. This is for
 186 tidier output when running parallel remote deliveries with debugging turned on.
 187 Must do the whole thing with a single printf and flush, as otherwise output may
 188 get interleaved. Since some calls to debug_printf() don't end with newline,
 189 we save up the text until we do get the newline.
 190 Take care to not disturb errno. */
 191
 192
 193 /* Debug printf indented by ACL nest depth */
 194 void
 195 debug_printf_indent(const char * format, ...)
 196 {
 197 va_list ap;
 198 va_start(ap, format);
 199 debug_vprintf(acl_level + expand_level, format, ap);
 200 va_end(ap);
 201 }
 202
 203 void
 204 debug_printf(const char *format, ...)
 205 {
 206 va_list ap;
 207 va_start(ap, format);
 208 debug_vprintf(0, format, ap);
 209 va_end(ap);
 210 }
 211
 212 void
 213 debug_vprintf(int indent, const char *format, va_list ap)
 214 {
 215 int save_errno = errno;
 216
 217 if (!debug_file) return;
 218
 219 /* Various things can be inserted at the start of a line. Don't use the
 220 tod_stamp() function for the timestamp, because that will overwrite the
 221 timestamp buffer, which may contain something useful. (This was a bug fix: the
 222 +memory debugging with +timestamp did cause a problem.) */
 223
 224 if (debug_ptr == debug_buffer)
 225   {
 226   DEBUG(D_timestamp)
 227     {
 228     struct timeval now;
 229     time_t tmp;
 230     struct tm * t;
 231
 232     gettimeofday(&now, NULL);
 233     tmp = now.tv_sec;
 234     t = f.timestamps_utc ? gmtime(&tmp) : localtime(&tmp);
 235     debug_ptr += sprintf(CS debug_ptr,
 236       LOGGING(millisec) ? "%02d:%02d:%02d.%03d " : "%02d:%02d:%02d ",
 237       t->tm_hour, t->tm_min, t->tm_sec, (int)(now.tv_usec/1000));
 238     }
 239
 240   DEBUG(D_pid)
 241     debug_ptr += sprintf(CS debug_ptr, "%5d ", (int)getpid());
 242
 243   /* Set up prefix if outputting for host checking and not debugging */
 244
 245   if (host_checking && debug_selector == 0)
 246     {
 247     Ustrcpy(debug_ptr, US">>> ");
 248     debug_ptr += 4;
 249     }
 250
 251   debug_prefix_length = debug_ptr - debug_buffer;
 252   }
 253
 254 if (indent > 0)
 255   {
 256   for (int i = indent >> 2; i > 0; i--)
 257     DEBUG(D_noutf8)
 258       {
 259       Ustrcpy(debug_ptr, US"   !");
 260       debug_ptr += 4;   /* 3 spaces + shriek */
 261       debug_prefix_length += 4;
 262       }
 263     else
 264       {
 265       Ustrcpy(debug_ptr, US"   " UTF8_VERT_2DASH);
 266       debug_ptr += 6;   /* 3 spaces + 3 UTF-8 octets */
 267       debug_prefix_length += 6;
 268       }
 269
 270   Ustrncpy(debug_ptr, US"   ", indent &= 3);
 271   debug_ptr += indent;
 272   debug_prefix_length += indent;
 273   }
 274
 275 /* Use the lengthchecked formatting routine to ensure that the buffer
 276 does not overflow. Ensure there's space for a newline at the end.
 277 However, use taint-unchecked routines for writing into the buffer
 278 so that we can write tainted info into the static debug_buffer -
 279 we trust that we will never expand the results. */
 280
 281   {
 282   gstring gs = { .size = (int)sizeof(debug_buffer) - 1,
 283                 .ptr = debug_ptr - debug_buffer,
 284                 .s = debug_buffer };
 285   if (!string_vformat(&gs, SVFMT_TAINT_NOCHK, format, ap))
 286     {
 287     uschar * s = US"**** debug string too long - truncated ****\n";
 288     uschar * p = gs.s + gs.ptr;
 289     int maxlen = gs.size - Ustrlen(s) - 2;
 290     if (p > gs.s + maxlen) p = gs.s + maxlen;
 291     if (p > gs.s && p[-1] != '\n') *p++ = '\n';
 292     Ustrcpy(p, s);
 293     while(*debug_ptr) debug_ptr++;
 294     }
 295   else
 296     {
 297     string_from_gstring(&gs);
 298     debug_ptr = gs.s + gs.ptr;
 299     }
 300   }
 301
 302 /* Output the line if it is complete. If we added any prefix data and there
 303 are internal newlines, make sure the prefix is on the continuation lines,
 304 as long as there is room in the buffer. We want to do just a single fprintf()
 305 so as to avoid interleaving. */
 306
 307 if (debug_ptr[-1] == '\n')
 308   {
 309   if (debug_prefix_length > 0)
 310     {
 311     uschar *p = debug_buffer;
 312     int left = sizeof(debug_buffer) - (debug_ptr - debug_buffer) - 1;
 313     while ((p = Ustrchr(p, '\n') + 1) != debug_ptr &&
 314            left >= debug_prefix_length)
 315       {
 316       int len = debug_ptr - p;
 317       memmove(p + debug_prefix_length, p, len + 1);
 318       memmove(p, debug_buffer, debug_prefix_length);
 319       debug_ptr += debug_prefix_length;
 320       left -= debug_prefix_length;
 321       }
 322     }
 323
 324   if (debug_pretrigger_buf)
 325     {
 326     int needed = Ustrlen(debug_buffer)+1, avail;
 327     char c;
 328
 329     if (needed > debug_pretrigger_bsize)
 330       needed = debug_pretrigger_bsize;
 331     if ((avail = pretrigger_readoff - pretrigger_writeoff) <= 0)
 332       avail += debug_pretrigger_bsize;
 333
 334     /* We have a pretrigger set up, trigger not yet hit. Copy the line(s) to the
 335     pretrig buffer, dropping earlier lines if needed but truncating this line if
 336     the pbuf is maxed out.  In the PTB the lines are NOT nul-terminated. */
 337
 338     while (avail < needed)
 339       do
 340         {
 341         avail++;
 342         c = debug_pretrigger_buf[pretrigger_readoff];
 343         if (++pretrigger_readoff >= debug_pretrigger_bsize) pretrigger_readoff = 0;
 344         }
 345       while (c && c != '\n' && pretrigger_readoff != pretrigger_writeoff);
 346
 347     needed--;
 348     for (int i = 0; needed; i++, needed--)
 349       {
 350       debug_pretrigger_buf[pretrigger_writeoff] = debug_buffer[i];
 351       if (++pretrigger_writeoff >= debug_pretrigger_bsize) pretrigger_writeoff = 0;
 352       }
 353     }
 354   else
 355     {
 356     fprintf(debug_file, "%s", CS debug_buffer);
 357     fflush(debug_file);
 358     }
 359   debug_ptr = debug_buffer;
 360   debug_prefix_length = 0;
 361   }
 362 errno = save_errno;
 363 }
 364
 365
 366
 367 /* Output the details of a socket */
 368
 369 void
 370 debug_print_socket(int fd)
 371 {
 372 struct stat s;
 373 if (fstat(fd, &s) == 0 && (s.st_mode & S_IFMT) == S_IFSOCK)
 374   {
 375   gstring * g = NULL;
 376   int val;
 377   socklen_t vlen = sizeof(val);
 378   struct sockaddr_storage a;
 379   socklen_t alen = sizeof(a);
 380   struct sockaddr_in * sinp = (struct sockaddr_in *)&a;
 381   struct sockaddr_in6 * sin6p = (struct sockaddr_in6 *)&a;
 382   struct sockaddr_un * sunp = (struct sockaddr_un *)&a;
 383
 384   if (getsockname(fd, (struct sockaddr*)&a, &alen) == 0)
 385     switch (a.ss_family)
 386       {
 387       case AF_INET:
 388         g = string_cat(g, US"domain AF_INET");
 389         g = string_fmt_append(g, " lcl [%s]:%u",
 390           inet_ntoa(sinp->sin_addr), ntohs(sinp->sin_port));
 391         alen = sizeof(*sinp);
 392         if (getpeername(fd, (struct sockaddr *)sinp, &alen) == 0)
 393           g = string_fmt_append(g, " rmt [%s]:%u",
 394             inet_ntoa(sinp->sin_addr), ntohs(sinp->sin_port));
 395         break;
 396       case AF_INET6:
 397         {
 398         uschar buf[46];
 399         g = string_cat(g, US"domain AF_INET6");
 400         g = string_fmt_append(g, " lcl [%s]:%u",
 401           inet_ntop(AF_INET6, &sin6p->sin6_addr, CS buf, sizeof(buf)),
 402           ntohs(sin6p->sin6_port));
 403         alen = sizeof(*sin6p);
 404         if (getpeername(fd, (struct sockaddr *)sin6p, &alen) == 0)
 405           g = string_fmt_append(g, " rmt [%s]:%u",
 406             inet_ntop(AF_INET6, &sin6p->sin6_addr, CS buf, sizeof(buf)),
 407             ntohs(sin6p->sin6_port));
 408         break;
 409         }
 410       case AF_UNIX:
 411         g = string_cat(g, US"domain AF_UNIX");
 412         if (alen > sizeof(sa_family_t)) /* not unix(7) "unnamed socket" */
 413           g = string_fmt_append(g, " lcl %s%s",
 414             sunp->sun_path[0] ? US"" : US"@",
 415             sunp->sun_path[0] ? sunp->sun_path : sunp->sun_path+1);
 416         alen = sizeof(*sunp);
 417         if (getpeername(fd, (struct sockaddr *)sunp, &alen) == 0)
 418           g = string_fmt_append(g, " rmt %s%s",
 419             sunp->sun_path[0] ? US"" : US"@",
 420             sunp->sun_path[0] ? sunp->sun_path : sunp->sun_path+1);
 421         break;
 422       default:
 423         g = string_fmt_append(g, "domain %u", sinp->sin_family);
 424         break;
 425       }
 426   if (getsockopt(fd, SOL_SOCKET, SO_TYPE, &val, &vlen) == 0)
 427     switch (val)
 428       {
 429       case SOCK_STREAM: g = string_cat(g, US" type SOCK_STREAM"); break;
 430       case SOCK_DGRAM:  g = string_cat(g, US" type SOCK_DGRAM"); break;
 431       default:  g = string_fmt_append(g, " type %d", val); break;
 432       }
 433 #ifdef SO_PROTOCOL
 434   if (getsockopt(fd, SOL_SOCKET, SO_PROTOCOL, &val, &vlen) == 0)
 435     {
 436     struct protoent * p = getprotobynumber(val);
 437     g = p
 438       ? string_fmt_append(g, " proto %s", p->p_name)
 439       : string_fmt_append(g, " proto %d", val);
 440     }
 441 #endif
 442   debug_printf_indent(" socket: %Y\n", g);
 443   }
 444 else
 445   debug_printf_indent(" fd st_mode 0%o\n", s.st_mode);
 446 }
 447
 448
 449 /**************************************************************/
 450 /* Pretrigger handling for debug.  The debug_printf implementation
 451 diverts output to a circular buffer if the buffer is set up.
 452 The routines here set up the buffer, and unload it to file (and release it).
 453 What ends up in the buffer is subject to the usual debug_selector. */
 454
 455 void
 456 debug_pretrigger_setup(const uschar * size_string)
 457 {
 458 long size = Ustrtol(size_string, NULL, 0);
 459 if (size > 0)
 460   {
 461   unsigned bufsize = MIN(size, 16384);
 462
 463   dtrigger_selector |= BIT(DTi_pretrigger);
 464   if (debug_pretrigger_buf) store_free(debug_pretrigger_buf);
 465   debug_pretrigger_buf = store_malloc((size_t)(debug_pretrigger_bsize = bufsize));
 466   pretrigger_readoff = pretrigger_writeoff = 0;
 467   }
 468 }
 469
 470 void
 471 debug_trigger_fire(void)
 472 {
 473 int nbytes;
 474
 475 if (!debug_pretrigger_buf) return;
 476
 477 if (debug_file && (nbytes = pretrigger_writeoff - pretrigger_readoff) != 0)
 478   if (nbytes > 0)
 479     fwrite(debug_pretrigger_buf + pretrigger_readoff, 1, nbytes, debug_file);
 480   else
 481     {
 482     fwrite(debug_pretrigger_buf + pretrigger_readoff, 1,
 483       debug_pretrigger_bsize - pretrigger_readoff, debug_file);
 484     fwrite(debug_pretrigger_buf, 1, pretrigger_writeoff, debug_file);
 485     }
 486
 487 debug_pretrigger_discard();
 488 }
 489
 490 void
 491 debug_pretrigger_discard(void)
 492 {
 493 if (debug_pretrigger_buf) store_free(debug_pretrigger_buf);
 494 debug_pretrigger_buf = NULL;
 495 dtrigger_selector = 0;
 496 }
 497
 498
 499 /* End of debug.c */