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