src/src/debug.c

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