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), 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     for (int i = 0; needed; i++, needed--)
 347       {
 348       debug_pretrigger_buf[pretrigger_writeoff] = debug_buffer[i];
 349       if (++pretrigger_writeoff >= debug_pretrigger_bsize) pretrigger_writeoff = 0;
 350       }
 351     }
 352   else
 353     {
 354     fprintf(debug_file, "%s", CS debug_buffer);
 355     fflush(debug_file);
 356     }
 357   debug_ptr = debug_buffer;
 358   debug_prefix_length = 0;
 359   }
 360 errno = save_errno;
 361 }
 362
 363
 364
 365 /* Output the details of a socket */
 366
 367 void
 368 debug_print_socket(int fd)
 369 {
 370 struct stat s;
 371 if (fstat(fd, &s) == 0 && (s.st_mode & S_IFMT) == S_IFSOCK)
 372   {
 373   gstring * g = NULL;
 374   int val;
 375   socklen_t vlen = sizeof(val);
 376   struct sockaddr_storage a;
 377   socklen_t alen = sizeof(a);
 378   struct sockaddr_in * sinp = (struct sockaddr_in *)&a;
 379   struct sockaddr_in6 * sin6p = (struct sockaddr_in6 *)&a;
 380   struct sockaddr_un * sunp = (struct sockaddr_un *)&a;
 381
 382   if (getsockname(fd, (struct sockaddr*)&a, &alen) == 0)
 383     switch (a.ss_family)
 384       {
 385       case AF_INET:
 386         g = string_cat(g, US"domain AF_INET");
 387         g = string_fmt_append(g, " lcl [%s]:%u",
 388           inet_ntoa(sinp->sin_addr), ntohs(sinp->sin_port));
 389         alen = sizeof(*sinp);
 390         if (getpeername(fd, (struct sockaddr *)sinp, &alen) == 0)
 391           g = string_fmt_append(g, " rmt [%s]:%u",
 392             inet_ntoa(sinp->sin_addr), ntohs(sinp->sin_port));
 393         break;
 394       case AF_INET6:
 395         {
 396         uschar buf[46];
 397         g = string_cat(g, US"domain AF_INET6");
 398         g = string_fmt_append(g, " lcl [%s]:%u",
 399           inet_ntop(AF_INET6, &sin6p->sin6_addr, CS buf, sizeof(buf)),
 400           ntohs(sin6p->sin6_port));
 401         alen = sizeof(*sin6p);
 402         if (getpeername(fd, (struct sockaddr *)sin6p, &alen) == 0)
 403           g = string_fmt_append(g, " rmt [%s]:%u",
 404             inet_ntop(AF_INET6, &sin6p->sin6_addr, CS buf, sizeof(buf)),
 405             ntohs(sin6p->sin6_port));
 406         break;
 407         }
 408       case AF_UNIX:
 409         g = string_cat(g, US"domain AF_UNIX");
 410         if (alen > sizeof(sa_family_t)) /* not unix(7) "unnamed socket" */
 411           g = string_fmt_append(g, " lcl %s%s",
 412             sunp->sun_path[0] ? US"" : US"@",
 413             sunp->sun_path[0] ? sunp->sun_path : sunp->sun_path+1);
 414         alen = sizeof(*sunp);
 415         if (getpeername(fd, (struct sockaddr *)sunp, &alen) == 0)
 416           g = string_fmt_append(g, " rmt %s%s",
 417             sunp->sun_path[0] ? US"" : US"@",
 418             sunp->sun_path[0] ? sunp->sun_path : sunp->sun_path+1);
 419         break;
 420       default:
 421         g = string_fmt_append(g, "domain %u", sinp->sin_family);
 422         break;
 423       }
 424   if (getsockopt(fd, SOL_SOCKET, SO_TYPE, &val, &vlen) == 0)
 425     switch (val)
 426       {
 427       case SOCK_STREAM: g = string_cat(g, US" type SOCK_STREAM"); break;
 428       case SOCK_DGRAM:  g = string_cat(g, US" type SOCK_DGRAM"); break;
 429       default:  g = string_fmt_append(g, " type %d", val); break;
 430       }
 431 #ifdef SO_PROTOCOL
 432   if (getsockopt(fd, SOL_SOCKET, SO_PROTOCOL, &val, &vlen) == 0)
 433     {
 434     struct protoent * p = getprotobynumber(val);
 435     g = p
 436       ? string_fmt_append(g, " proto %s", p->p_name)
 437       : string_fmt_append(g, " proto %d", val);
 438     }
 439 #endif
 440   debug_printf_indent(" socket: %s\n", string_from_gstring(g));
 441   }
 442 else
 443   debug_printf_indent(" fd st_mode 0%o\n", s.st_mode);
 444 }
 445
 446
 447 /**************************************************************/
 448 /* Pretrigger handling for debug.  The debug_printf implementation
 449 diverts output to a circular buffer if the buffer is set up.
 450 The routines here set up the buffer, and unload it to file (and release it).
 451 What ends up in the buffer is subject to the usual debug_selector. */
 452
 453 void
 454 debug_pretrigger_setup(const uschar * size_string)
 455 {
 456 long size = Ustrtol(size_string, NULL, 0);
 457 if (size > 0)
 458   {
 459   unsigned bufsize = MIN(size, 16384);
 460
 461   dtrigger_selector |= BIT(DTi_pretrigger);
 462   if (debug_pretrigger_buf) store_free(debug_pretrigger_buf);
 463   debug_pretrigger_buf = store_malloc((size_t)(debug_pretrigger_bsize = bufsize));
 464   pretrigger_readoff = pretrigger_writeoff = 0;
 465   }
 466 }
 467
 468 void
 469 debug_trigger_fire(void)
 470 {
 471 int nbytes;
 472
 473 if (!debug_pretrigger_buf) return;
 474
 475 if (debug_file && (nbytes = pretrigger_writeoff - pretrigger_readoff) != 0)
 476   if (nbytes > 0)
 477     fwrite(debug_pretrigger_buf + pretrigger_readoff, 1, nbytes, debug_file);
 478   else
 479     {
 480     fwrite(debug_pretrigger_buf + pretrigger_readoff, 1,
 481       debug_pretrigger_bsize - pretrigger_readoff, debug_file);
 482     fwrite(debug_pretrigger_buf, 1, pretrigger_writeoff, debug_file);
 483     }
 484
 485 debug_pretrigger_discard();
 486 }
 487
 488 void
 489 debug_pretrigger_discard(void)
 490 {
 491 if (debug_pretrigger_buf) store_free(debug_pretrigger_buf);
 492 debug_pretrigger_buf = NULL;
 493 dtrigger_selector = 0;
 494 }
 495
 496
 497 /* End of debug.c */