7b9be057bb08145e703f722990791fe70d5558cd
[exim.git] / 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 */