Debug: "kill" option on ACL control=debug. Bug 1831
[exim.git] / src / src / log.c
1 /*************************************************
2 * Exim - an Internet mail transport agent *
3 *************************************************/
4
5 /* Copyright (c) University of Cambridge 1995 - 2016 */
6 /* See the file NOTICE for conditions of use and distribution. */
7
8 /* Functions for writing log files. The code for maintaining datestamped
9 log files was originally contributed by Tony Sheen. */
10
11
12 #include "exim.h"
13
14 #define LOG_NAME_SIZE 256
15 #define MAX_SYSLOG_LEN 870
16
17 #define LOG_MODE_FILE 1
18 #define LOG_MODE_SYSLOG 2
19
20 enum { lt_main, lt_reject, lt_panic, lt_debug };
21
22 static uschar *log_names[] = { US"main", US"reject", US"panic", US"debug" };
23
24
25
26 /*************************************************
27 * Local static variables *
28 *************************************************/
29
30 static uschar mainlog_name[LOG_NAME_SIZE];
31 static uschar rejectlog_name[LOG_NAME_SIZE];
32 static uschar debuglog_name[LOG_NAME_SIZE];
33
34 static uschar *mainlog_datestamp = NULL;
35 static uschar *rejectlog_datestamp = NULL;
36
37 static int mainlogfd = -1;
38 static int rejectlogfd = -1;
39 static ino_t mainlog_inode = 0;
40 static ino_t rejectlog_inode = 0;
41
42 static uschar *panic_save_buffer = NULL;
43 static BOOL panic_recurseflag = FALSE;
44
45 static BOOL syslog_open = FALSE;
46 static BOOL path_inspected = FALSE;
47 static int logging_mode = LOG_MODE_FILE;
48 static uschar *file_path = US"";
49
50
51 /* These should be kept in-step with the private delivery error
52 number definitions in macros.h */
53
54 static const uschar * exim_errstrings[] = {
55 US"",
56 US"unknown error",
57 US"user slash",
58 US"exist race",
59 US"not regular",
60 US"not directory",
61 US"bad ugid",
62 US"bad mode",
63 US"inode changed",
64 US"lock failed",
65 US"bad address2",
66 US"forbid pipe",
67 US"forbid file",
68 US"forbid reply",
69 US"missing pipe",
70 US"missing file",
71 US"missing reply",
72 US"bad redirect",
73 US"smtp closed",
74 US"smtp format",
75 US"spool format",
76 US"not absolute",
77 US"Exim-imposed quota",
78 US"held",
79 US"Delivery filter process failure",
80 US"Delivery add/remove header failure",
81 US"Delivery write incomplete error",
82 US"Some expansion failed",
83 US"Failed to get gid",
84 US"Failed to get uid",
85 US"Unset or non-existent transport",
86 US"MBX length mismatch",
87 US"Lookup failed routing or in smtp tpt",
88 US"Can't match format in appendfile",
89 US"Creation outside home in appendfile",
90 US"Can't check a list; lookup defer",
91 US"DNS lookup defer",
92 US"Failed to start TLS session",
93 US"Mandatory TLS session not started",
94 US"Failed to chown a file",
95 US"Failed to create a pipe",
96 US"When verifying",
97 US"When required by client",
98 US"Used internally in smtp transport",
99 US"RCPT gave 4xx error",
100 US"MAIL gave 4xx error",
101 US"DATA gave 4xx error",
102 US"Negotiation failed for proxy configured host",
103 US"Authenticator 'other' failure",
104 US"target not supporting SMTPUTF8",
105 US"",
106
107 US"Not time for routing",
108 US"Not time for local delivery",
109 US"Not time for any remote host",
110 US"Local-only delivery",
111 US"Domain in queue_domains",
112 US"Transport concurrency limit",
113 };
114
115
116 /************************************************/
117 const uschar *
118 exim_errstr(int err)
119 {
120 return errno < 0 ? exim_errstrings[-err] : CUS strerror(err);
121 }
122
123 /*************************************************
124 * Write to syslog *
125 *************************************************/
126
127 /* The given string is split into sections according to length, or at embedded
128 newlines, and syslogged as a numbered sequence if it is overlong or if there is
129 more than one line. However, if we are running in the test harness, do not do
130 anything. (The test harness doesn't use syslog - for obvious reasons - but we
131 can get here if there is a failure to open the panic log.)
132
133 Arguments:
134 priority syslog priority
135 s the string to be written
136
137 Returns: nothing
138 */
139
140 static void
141 write_syslog(int priority, uschar *s)
142 {
143 int len, pass;
144 int linecount = 0;
145
146 if (running_in_test_harness) return;
147
148 if (!syslog_timestamp) s += log_timezone? 26 : 20;
149
150 len = Ustrlen(s);
151
152 #ifndef NO_OPENLOG
153 if (!syslog_open)
154 {
155 #ifdef SYSLOG_LOG_PID
156 openlog(CS syslog_processname, LOG_PID|LOG_CONS, syslog_facility);
157 #else
158 openlog(CS syslog_processname, LOG_CONS, syslog_facility);
159 #endif
160 syslog_open = TRUE;
161 }
162 #endif
163
164 /* First do a scan through the message in order to determine how many lines
165 it is going to end up as. Then rescan to output it. */
166
167 for (pass = 0; pass < 2; pass++)
168 {
169 int i;
170 int tlen;
171 uschar *ss = s;
172 for (i = 1, tlen = len; tlen > 0; i++)
173 {
174 int plen = tlen;
175 uschar *nlptr = Ustrchr(ss, '\n');
176 if (nlptr != NULL) plen = nlptr - ss;
177 #ifndef SYSLOG_LONG_LINES
178 if (plen > MAX_SYSLOG_LEN) plen = MAX_SYSLOG_LEN;
179 #endif
180 tlen -= plen;
181 if (ss[plen] == '\n') tlen--; /* chars left */
182
183 if (pass == 0) linecount++; else
184 {
185 if (linecount == 1)
186 syslog(priority, "%.*s", plen, ss);
187 else
188 syslog(priority, "[%d%c%d] %.*s", i,
189 (ss[plen] == '\n' && tlen != 0)? '\\' : '/',
190 linecount, plen, ss);
191 }
192 ss += plen;
193 if (*ss == '\n') ss++;
194 }
195 }
196 }
197
198
199
200 /*************************************************
201 * Die tidily *
202 *************************************************/
203
204 /* This is called when Exim is dying as a result of something going wrong in
205 the logging, or after a log call with LOG_PANIC_DIE set. Optionally write a
206 message to debug_file or a stderr file, if they exist. Then, if in the middle
207 of accepting a message, throw it away tidily by calling receive_bomb_out();
208 this will attempt to send an SMTP response if appropriate. Passing NULL as the
209 first argument stops it trying to run the NOTQUIT ACL (which might try further
210 logging and thus cause problems). Otherwise, try to close down an outstanding
211 SMTP call tidily.
212
213 Arguments:
214 s1 Error message to write to debug_file and/or stderr and syslog
215 s2 Error message for any SMTP call that is in progress
216 Returns: The function does not return
217 */
218
219 static void
220 die(uschar *s1, uschar *s2)
221 {
222 if (s1 != NULL)
223 {
224 write_syslog(LOG_CRIT, s1);
225 if (debug_file != NULL) debug_printf("%s\n", s1);
226 if (log_stderr != NULL && log_stderr != debug_file)
227 fprintf(log_stderr, "%s\n", s1);
228 }
229 if (receive_call_bombout) receive_bomb_out(NULL, s2); /* does not return */
230 if (smtp_input) smtp_closedown(s2);
231 exim_exit(EXIT_FAILURE);
232 }
233
234
235
236 /*************************************************
237 * Create a log file *
238 *************************************************/
239
240 /* This function is called to create and open a log file. It may be called in a
241 subprocess when the original process is root.
242
243 Arguments:
244 name the file name
245
246 The file name has been build in a working buffer, so it is permissible to
247 overwrite it temporarily if it is necessary to create the directory.
248
249 Returns: a file descriptor, or < 0 on failure (errno set)
250 */
251
252 int
253 log_create(uschar *name)
254 {
255 int fd = Uopen(name, O_CREAT|O_APPEND|O_WRONLY, LOG_MODE);
256
257 /* If creation failed, attempt to build a log directory in case that is the
258 problem. */
259
260 if (fd < 0 && errno == ENOENT)
261 {
262 BOOL created;
263 uschar *lastslash = Ustrrchr(name, '/');
264 *lastslash = 0;
265 created = directory_make(NULL, name, LOG_DIRECTORY_MODE, FALSE);
266 DEBUG(D_any) debug_printf("%s log directory %s\n",
267 created? "created" : "failed to create", name);
268 *lastslash = '/';
269 if (created) fd = Uopen(name, O_CREAT|O_APPEND|O_WRONLY, LOG_MODE);
270 }
271
272 return fd;
273 }
274
275
276
277 /*************************************************
278 * Create a log file as the exim user *
279 *************************************************/
280
281 /* This function is called when we are root to spawn an exim:exim subprocess
282 in which we can create a log file. It must be signal-safe since it is called
283 by the usr1_handler().
284
285 Arguments:
286 name the file name
287
288 Returns: a file descriptor, or < 0 on failure (errno set)
289 */
290
291 int
292 log_create_as_exim(uschar *name)
293 {
294 pid_t pid = fork();
295 int status = 1;
296 int fd = -1;
297
298 /* In the subprocess, change uid/gid and do the creation. Return 0 from the
299 subprocess on success. If we don't check for setuid failures, then the file
300 can be created as root, so vulnerabilities which cause setuid to fail mean
301 that the Exim user can use symlinks to cause a file to be opened/created as
302 root. We always open for append, so can't nuke existing content but it would
303 still be Rather Bad. */
304
305 if (pid == 0)
306 {
307 if (setgid(exim_gid) < 0)
308 die(US"exim: setgid for log-file creation failed, aborting",
309 US"Unexpected log failure, please try later");
310 if (setuid(exim_uid) < 0)
311 die(US"exim: setuid for log-file creation failed, aborting",
312 US"Unexpected log failure, please try later");
313 _exit((log_create(name) < 0)? 1 : 0);
314 }
315
316 /* If we created a subprocess, wait for it. If it succeeded, try the open. */
317
318 while (pid > 0 && waitpid(pid, &status, 0) != pid);
319 if (status == 0) fd = Uopen(name, O_APPEND|O_WRONLY, LOG_MODE);
320
321 /* If we failed to create a subprocess, we are in a bad way. We return
322 with fd still < 0, and errno set, letting the caller handle the error. */
323
324 return fd;
325 }
326
327
328
329
330 /*************************************************
331 * Open a log file *
332 *************************************************/
333
334 /* This function opens one of a number of logs, creating the log directory if
335 it does not exist. This may be called recursively on failure, in order to open
336 the panic log.
337
338 The directory is in the static variable file_path. This is static so that it
339 the work of sorting out the path is done just once per Exim process.
340
341 Exim is normally configured to avoid running as root wherever possible, the log
342 files must be owned by the non-privileged exim user. To ensure this, first try
343 an open without O_CREAT - most of the time this will succeed. If it fails, try
344 to create the file; if running as root, this must be done in a subprocess to
345 avoid races.
346
347 Arguments:
348 fd where to return the resulting file descriptor
349 type lt_main, lt_reject, lt_panic, or lt_debug
350 tag optional tag to include in the name (only hooked up for debug)
351
352 Returns: nothing
353 */
354
355 static void
356 open_log(int *fd, int type, uschar *tag)
357 {
358 uid_t euid;
359 BOOL ok, ok2;
360 uschar buffer[LOG_NAME_SIZE];
361
362 /* The names of the log files are controlled by file_path. The panic log is
363 written to the same directory as the main and reject logs, but its name does
364 not have a datestamp. The use of datestamps is indicated by %D/%M in file_path.
365 When opening the panic log, if %D or %M is present, we remove the datestamp
366 from the generated name; if it is at the start, remove a following
367 non-alphanumeric character as well; otherwise, remove a preceding
368 non-alphanumeric character. This is definitely kludgy, but it sort of does what
369 people want, I hope. */
370
371 ok = string_format(buffer, sizeof(buffer), CS file_path, log_names[type]);
372
373 /* Save the name of the mainlog for rollover processing. Without a datestamp,
374 it gets statted to see if it has been cycled. With a datestamp, the datestamp
375 will be compared. The static slot for saving it is the same size as buffer,
376 and the text has been checked above to fit, so this use of strcpy() is OK. */
377
378 if (type == lt_main)
379 {
380 Ustrcpy(mainlog_name, buffer);
381 mainlog_datestamp = mainlog_name + string_datestamp_offset;
382 }
383
384 /* Ditto for the reject log */
385
386 else if (type == lt_reject)
387 {
388 Ustrcpy(rejectlog_name, buffer);
389 rejectlog_datestamp = rejectlog_name + string_datestamp_offset;
390 }
391
392 /* and deal with the debug log (which keeps the datestamp, but does not
393 update it) */
394
395 else if (type == lt_debug)
396 {
397 Ustrcpy(debuglog_name, buffer);
398 if (tag)
399 {
400 /* this won't change the offset of the datestamp */
401 ok2 = string_format(buffer, sizeof(buffer), "%s%s",
402 debuglog_name, tag);
403 if (ok2)
404 Ustrcpy(debuglog_name, buffer);
405 }
406 }
407
408 /* Remove any datestamp if this is the panic log. This is rare, so there's no
409 need to optimize getting the datestamp length. We remove one non-alphanumeric
410 char afterwards if at the start, otherwise one before. */
411
412 else if (string_datestamp_offset >= 0)
413 {
414 uschar *from = buffer + string_datestamp_offset;
415 uschar *to = from + string_datestamp_length;
416 if (from == buffer || from[-1] == '/')
417 {
418 if (!isalnum(*to)) to++;
419 }
420 else
421 {
422 if (!isalnum(from[-1])) from--;
423 }
424
425 /* This strcpy is ok, because we know that to is a substring of from. */
426
427 Ustrcpy(from, to);
428 }
429
430 /* If the file name is too long, it is an unrecoverable disaster */
431
432 if (!ok)
433 {
434 die(US"exim: log file path too long: aborting",
435 US"Logging failure; please try later");
436 }
437
438 /* We now have the file name. Try to open an existing file. After a successful
439 open, arrange for automatic closure on exec(), and then return. */
440
441 *fd = Uopen(buffer, O_APPEND|O_WRONLY, LOG_MODE);
442
443 if (*fd >= 0)
444 {
445 (void)fcntl(*fd, F_SETFD, fcntl(*fd, F_GETFD) | FD_CLOEXEC);
446 return;
447 }
448
449 /* Open was not successful: try creating the file. If this is a root process,
450 we must do the creating in a subprocess set to exim:exim in order to ensure
451 that the file is created with the right ownership. Otherwise, there can be a
452 race if another Exim process is trying to write to the log at the same time.
453 The use of SIGUSR1 by the exiwhat utility can provoke a lot of simultaneous
454 writing. */
455
456 euid = geteuid();
457
458 /* If we are already running as the Exim user (even if that user is root),
459 we can go ahead and create in the current process. */
460
461 if (euid == exim_uid) *fd = log_create(buffer);
462
463 /* Otherwise, if we are root, do the creation in an exim:exim subprocess. If we
464 are neither exim nor root, creation is not attempted. */
465
466 else if (euid == root_uid) *fd = log_create_as_exim(buffer);
467
468 /* If we now have an open file, set the close-on-exec flag and return. */
469
470 if (*fd >= 0)
471 {
472 (void)fcntl(*fd, F_SETFD, fcntl(*fd, F_GETFD) | FD_CLOEXEC);
473 return;
474 }
475
476 /* Creation failed. There are some circumstances in which we get here when
477 the effective uid is not root or exim, which is the problem. (For example, a
478 non-setuid binary with log_arguments set, called in certain ways.) Rather than
479 just bombing out, force the log to stderr and carry on if stderr is available.
480 */
481
482 if (euid != root_uid && euid != exim_uid && log_stderr != NULL)
483 {
484 *fd = fileno(log_stderr);
485 return;
486 }
487
488 /* Otherwise this is a disaster. This call is deliberately ONLY to the panic
489 log. If possible, save a copy of the original line that was being logged. If we
490 are recursing (can't open the panic log either), the pointer will already be
491 set. */
492
493 if (panic_save_buffer == NULL)
494 {
495 panic_save_buffer = (uschar *)malloc(LOG_BUFFER_SIZE);
496 if (panic_save_buffer != NULL)
497 memcpy(panic_save_buffer, log_buffer, LOG_BUFFER_SIZE);
498 }
499
500 log_write(0, LOG_PANIC_DIE, "Cannot open %s log file \"%s\": %s: "
501 "euid=%d egid=%d", log_names[type], buffer, strerror(errno), euid, getegid());
502 /* Never returns */
503 }
504
505
506 static void
507 unlink_log(int type)
508 {
509 if (type == lt_debug) unlink(CS debuglog_name);
510 }
511
512
513
514 /*************************************************
515 * Add configuration file info to log line *
516 *************************************************/
517
518 /* This is put in a function because it's needed twice (once for debugging,
519 once for real).
520
521 Arguments:
522 ptr pointer to the end of the line we are building
523 flags log flags
524
525 Returns: updated pointer
526 */
527
528 static uschar *
529 log_config_info(uschar *ptr, int flags)
530 {
531 Ustrcpy(ptr, "Exim configuration error");
532 ptr += 24;
533
534 if ((flags & (LOG_CONFIG_FOR & ~LOG_CONFIG)) != 0)
535 {
536 Ustrcpy(ptr, " for ");
537 return ptr + 5;
538 }
539
540 if ((flags & (LOG_CONFIG_IN & ~LOG_CONFIG)) != 0)
541 {
542 sprintf(CS ptr, " in line %d of %s", config_lineno, config_filename);
543 while (*ptr) ptr++;
544 }
545
546 Ustrcpy(ptr, ":\n ");
547 return ptr + 4;
548 }
549
550
551 /*************************************************
552 * A write() operation failed *
553 *************************************************/
554
555 /* This function is called when write() fails on anything other than the panic
556 log, which can happen if a disk gets full or a file gets too large or whatever.
557 We try to save the relevant message in the panic_save buffer before crashing
558 out.
559
560 The potential invoker should probably not call us for EINTR -1 writes. But
561 otherwise, short writes are bad as we don't do non-blocking writes to fds
562 subject to flow control. (If we do, that's new and the logic of this should
563 be reconsidered).
564
565 Arguments:
566 name the name of the log being written
567 length the string length being written
568 rc the return value from write()
569
570 Returns: does not return
571 */
572
573 static void
574 log_write_failed(uschar *name, int length, int rc)
575 {
576 int save_errno = errno;
577
578 if (panic_save_buffer == NULL)
579 {
580 panic_save_buffer = (uschar *)malloc(LOG_BUFFER_SIZE);
581 if (panic_save_buffer != NULL)
582 memcpy(panic_save_buffer, log_buffer, LOG_BUFFER_SIZE);
583 }
584
585 log_write(0, LOG_PANIC_DIE, "failed to write to %s: length=%d result=%d "
586 "errno=%d (%s)", name, length, rc, save_errno,
587 (save_errno == 0)? "write incomplete" : strerror(save_errno));
588 /* Never returns */
589 }
590
591
592
593 /*************************************************
594 * Write to an fd, retrying after signals *
595 *************************************************/
596
597 /* Basic write to fd for logs, handling EINTR.
598
599 Arguments:
600 fd the fd to write to
601 buf the string to write
602 length the string length being written
603
604 Returns:
605 length actually written, persisting an errno from write()
606 */
607 ssize_t
608 write_to_fd_buf(int fd, const uschar *buf, size_t length)
609 {
610 ssize_t wrote;
611 size_t total_written = 0;
612 const uschar *p = buf;
613 size_t left = length;
614
615 while (1)
616 {
617 wrote = write(fd, p, left);
618 if (wrote == (ssize_t)-1)
619 {
620 if (errno == EINTR) continue;
621 return wrote;
622 }
623 total_written += wrote;
624 if (wrote == left)
625 break;
626 else
627 {
628 p += wrote;
629 left -= wrote;
630 }
631 }
632 return total_written;
633 }
634
635
636
637 static void
638 set_file_path(void)
639 {
640 int sep = ':'; /* Fixed separator - outside use */
641 uschar *t;
642 const uschar *tt = US LOG_FILE_PATH;
643 while ((t = string_nextinlist(&tt, &sep, log_buffer, LOG_BUFFER_SIZE)))
644 {
645 if (Ustrcmp(t, "syslog") == 0 || t[0] == 0) continue;
646 file_path = string_copy(t);
647 break;
648 }
649 }
650
651
652
653 /*************************************************
654 * Write message to log file *
655 *************************************************/
656
657 /* Exim can be configured to log to local files, or use syslog, or both. This
658 is controlled by the setting of log_file_path. The following cases are
659 recognized:
660
661 log_file_path = "" write files in the spool/log directory
662 log_file_path = "xxx" write files in the xxx directory
663 log_file_path = "syslog" write to syslog
664 log_file_path = "syslog : xxx" write to syslog and to files (any order)
665
666 The message always gets '\n' added on the end of it, since more than one
667 process may be writing to the log at once and we don't want intermingling to
668 happen in the middle of lines. To be absolutely sure of this we write the data
669 into a private buffer and then put it out in a single write() call.
670
671 The flags determine which log(s) the message is written to, or for syslogging,
672 which priority to use, and in the case of the panic log, whether the process
673 should die afterwards.
674
675 The variable really_exim is TRUE only when exim is running in privileged state
676 (i.e. not with a changed configuration or with testing options such as -brw).
677 If it is not, don't try to write to the log because permission will probably be
678 denied.
679
680 Avoid actually writing to the logs when exim is called with -bv or -bt to
681 test an address, but take other actions, such as panicing.
682
683 In Exim proper, the buffer for building the message is got at start-up, so that
684 nothing gets done if it can't be got. However, some functions that are also
685 used in utilities occasionally obey log_write calls in error situations, and it
686 is simplest to put a single malloc() here rather than put one in each utility.
687 Malloc is used directly because the store functions may call log_write().
688
689 If a message_id exists, we include it after the timestamp.
690
691 Arguments:
692 selector write to main log or LOG_INFO only if this value is zero, or if
693 its bit is set in log_selector[0]
694 flags each bit indicates some independent action:
695 LOG_SENDER add raw sender to the message
696 LOG_RECIPIENTS add raw recipients list to message
697 LOG_CONFIG add "Exim configuration error"
698 LOG_CONFIG_FOR add " for " instead of ":\n "
699 LOG_CONFIG_IN add " in line x[ of file y]"
700 LOG_MAIN write to main log or syslog LOG_INFO
701 LOG_REJECT write to reject log or syslog LOG_NOTICE
702 LOG_PANIC write to panic log or syslog LOG_ALERT
703 LOG_PANIC_DIE write to panic log or LOG_ALERT and then crash
704 format a printf() format
705 ... arguments for format
706
707 Returns: nothing
708 */
709
710 void
711 log_write(unsigned int selector, int flags, const char *format, ...)
712 {
713 uschar *ptr;
714 int length;
715 int paniclogfd;
716 ssize_t written_len;
717 va_list ap;
718
719 /* If panic_recurseflag is set, we have failed to open the panic log. This is
720 the ultimate disaster. First try to write the message to a debug file and/or
721 stderr and also to syslog. If panic_save_buffer is not NULL, it contains the
722 original log line that caused the problem. Afterwards, expire. */
723
724 if (panic_recurseflag)
725 {
726 uschar *extra = (panic_save_buffer == NULL)? US"" : panic_save_buffer;
727 if (debug_file != NULL) debug_printf("%s%s", extra, log_buffer);
728 if (log_stderr != NULL && log_stderr != debug_file)
729 fprintf(log_stderr, "%s%s", extra, log_buffer);
730 if (*extra != 0) write_syslog(LOG_CRIT, extra);
731 write_syslog(LOG_CRIT, log_buffer);
732 die(US"exim: could not open panic log - aborting: see message(s) above",
733 US"Unexpected log failure, please try later");
734 }
735
736 /* Ensure we have a buffer (see comment above); this should never be obeyed
737 when running Exim proper, only when running utilities. */
738
739 if (log_buffer == NULL)
740 {
741 log_buffer = (uschar *)malloc(LOG_BUFFER_SIZE);
742 if (log_buffer == NULL)
743 {
744 fprintf(stderr, "exim: failed to get store for log buffer\n");
745 exim_exit(EXIT_FAILURE);
746 }
747 }
748
749 /* If we haven't already done so, inspect the setting of log_file_path to
750 determine whether to log to files and/or to syslog. Bits in logging_mode
751 control this, and for file logging, the path must end up in file_path. This
752 variable must be in permanent store because it may be required again later in
753 the process. */
754
755 if (!path_inspected)
756 {
757 BOOL multiple = FALSE;
758 int old_pool = store_pool;
759
760 store_pool = POOL_PERM;
761
762 /* If nothing has been set, don't waste effort... the default values for the
763 statics are file_path="" and logging_mode = LOG_MODE_FILE. */
764
765 if (*log_file_path)
766 {
767 int sep = ':'; /* Fixed separator - outside use */
768 uschar *s;
769 const uschar *ss = log_file_path;
770 logging_mode = 0;
771 while ((s = string_nextinlist(&ss, &sep, log_buffer, LOG_BUFFER_SIZE)))
772 {
773 if (Ustrcmp(s, "syslog") == 0)
774 logging_mode |= LOG_MODE_SYSLOG;
775 else if ((logging_mode & LOG_MODE_FILE) != 0) multiple = TRUE;
776 else
777 {
778 logging_mode |= LOG_MODE_FILE;
779
780 /* If a non-empty path is given, use it */
781
782 if (*s)
783 file_path = string_copy(s);
784
785 /* If the path is empty, we want to use the first non-empty, non-
786 syslog item in LOG_FILE_PATH, if there is one, since the value of
787 log_file_path may have been set at runtime. If there is no such item,
788 use the ultimate default in the spool directory. */
789
790 else
791 set_file_path(); /* Empty item in log_file_path */
792 } /* First non-syslog item in log_file_path */
793 } /* Scan of log_file_path */
794 }
795
796 /* If no modes have been selected, it is a major disaster */
797
798 if (logging_mode == 0)
799 die(US"Neither syslog nor file logging set in log_file_path",
800 US"Unexpected logging failure");
801
802 /* Set up the ultimate default if necessary. Then revert to the old store
803 pool, and record that we've sorted out the path. */
804
805 if ((logging_mode & LOG_MODE_FILE) != 0 && file_path[0] == 0)
806 file_path = string_sprintf("%s/log/%%slog", spool_directory);
807 store_pool = old_pool;
808 path_inspected = TRUE;
809
810 /* If more than one file path was given, log a complaint. This recursive call
811 should work since we have now set up the routing. */
812
813 if (multiple)
814 log_write(0, LOG_MAIN|LOG_PANIC,
815 "More than one path given in log_file_path: using %s", file_path);
816 }
817
818 /* If debugging, show all log entries, but don't show headers. Do it all
819 in one go so that it doesn't get split when multi-processing. */
820
821 DEBUG(D_any|D_v)
822 {
823 int i;
824 ptr = log_buffer;
825
826 Ustrcpy(ptr, "LOG:");
827 ptr += 4;
828
829 /* Show the selector that was passed into the call. */
830
831 for (i = 0; i < log_options_count; i++)
832 {
833 unsigned int bitnum = log_options[i].bit;
834 if (bitnum < BITWORDSIZE && selector == BIT(bitnum))
835 {
836 *ptr++ = ' ';
837 Ustrcpy(ptr, log_options[i].name);
838 while (*ptr) ptr++;
839 }
840 }
841
842 sprintf(CS ptr, "%s%s%s%s\n ",
843 ((flags & LOG_MAIN) != 0)? " MAIN" : "",
844 ((flags & LOG_PANIC) != 0)? " PANIC" : "",
845 ((flags & LOG_PANIC_DIE) == LOG_PANIC_DIE)? " DIE" : "",
846 ((flags & LOG_REJECT) != 0)? " REJECT" : "");
847
848 while(*ptr) ptr++;
849 if ((flags & LOG_CONFIG) != 0) ptr = log_config_info(ptr, flags);
850
851 va_start(ap, format);
852 if (!string_vformat(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer)-1, format, ap))
853 Ustrcpy(ptr, "**** log string overflowed log buffer ****");
854 va_end(ap);
855
856 while(*ptr) ptr++;
857 Ustrcat(ptr, "\n");
858 debug_printf("%s", log_buffer);
859 }
860
861 /* If no log file is specified, we are in a mess. */
862
863 if ((flags & (LOG_MAIN|LOG_PANIC|LOG_REJECT)) == 0)
864 log_write(0, LOG_MAIN|LOG_PANIC_DIE, "log_write called with no log "
865 "flags set");
866
867 /* There are some weird circumstances in which logging is disabled. */
868
869 if (disable_logging)
870 {
871 DEBUG(D_any) debug_printf("log writing disabled\n");
872 return;
873 }
874
875 /* Handle disabled reject log */
876
877 if (!write_rejectlog) flags &= ~LOG_REJECT;
878
879 /* Create the main message in the log buffer. Do not include the message id
880 when called by a utility. */
881
882 ptr = log_buffer;
883 sprintf(CS ptr, "%s ", tod_stamp(tod_log));
884 while(*ptr) ptr++;
885
886 if (LOGGING(pid))
887 {
888 sprintf(CS ptr, "[%d] ", (int)getpid());
889 while (*ptr) ptr++;
890 }
891
892 if (really_exim && message_id[0] != 0)
893 {
894 sprintf(CS ptr, "%s ", message_id);
895 while(*ptr) ptr++;
896 }
897
898 if ((flags & LOG_CONFIG) != 0) ptr = log_config_info(ptr, flags);
899
900 va_start(ap, format);
901 if (!string_vformat(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer)-1, format, ap))
902 Ustrcpy(ptr, "**** log string overflowed log buffer ****\n");
903 while(*ptr) ptr++;
904 va_end(ap);
905
906 /* Add the raw, unrewritten, sender to the message if required. This is done
907 this way because it kind of fits with LOG_RECIPIENTS. */
908
909 if ((flags & LOG_SENDER) != 0 &&
910 ptr < log_buffer + LOG_BUFFER_SIZE - 10 - Ustrlen(raw_sender))
911 {
912 sprintf(CS ptr, " from <%s>", raw_sender);
913 while (*ptr) ptr++;
914 }
915
916 /* Add list of recipients to the message if required; the raw list,
917 before rewriting, was saved in raw_recipients. There may be none, if an ACL
918 discarded them all. */
919
920 if ((flags & LOG_RECIPIENTS) != 0 && ptr < log_buffer + LOG_BUFFER_SIZE - 6 &&
921 raw_recipients_count > 0)
922 {
923 int i;
924 sprintf(CS ptr, " for");
925 while (*ptr) ptr++;
926 for (i = 0; i < raw_recipients_count; i++)
927 {
928 uschar *s = raw_recipients[i];
929 if (log_buffer + LOG_BUFFER_SIZE - ptr < Ustrlen(s) + 3) break;
930 sprintf(CS ptr, " %s", s);
931 while (*ptr) ptr++;
932 }
933 }
934
935 sprintf(CS ptr, "\n");
936 while(*ptr) ptr++;
937 length = ptr - log_buffer;
938
939 /* Handle loggable errors when running a utility, or when address testing.
940 Write to log_stderr unless debugging (when it will already have been written),
941 or unless there is no log_stderr (expn called from daemon, for example). */
942
943 if (!really_exim || log_testing_mode)
944 {
945 if (debug_selector == 0 && log_stderr != NULL &&
946 (selector == 0 || (selector & log_selector[0]) != 0))
947 {
948 if (host_checking)
949 fprintf(log_stderr, "LOG: %s", CS(log_buffer + 20)); /* no timestamp */
950 else
951 fprintf(log_stderr, "%s", CS log_buffer);
952 }
953 if ((flags & LOG_PANIC_DIE) == LOG_PANIC_DIE) exim_exit(EXIT_FAILURE);
954 return;
955 }
956
957 /* Handle the main log. We know that either syslog or file logging (or both) is
958 set up. A real file gets left open during reception or delivery once it has
959 been opened, but we don't want to keep on writing to it for too long after it
960 has been renamed. Therefore, do a stat() and see if the inode has changed, and
961 if so, re-open. */
962
963 if ((flags & LOG_MAIN) != 0 &&
964 (selector == 0 || (selector & log_selector[0]) != 0))
965 {
966 if ((logging_mode & LOG_MODE_SYSLOG) != 0 &&
967 (syslog_duplication || (flags & (LOG_REJECT|LOG_PANIC)) == 0))
968 write_syslog(LOG_INFO, log_buffer);
969
970 if ((logging_mode & LOG_MODE_FILE) != 0)
971 {
972 struct stat statbuf;
973
974 /* Check for a change to the mainlog file name when datestamping is in
975 operation. This happens at midnight, at which point we want to roll over
976 the file. Closing it has the desired effect. */
977
978 if (mainlog_datestamp != NULL)
979 {
980 uschar *nowstamp = tod_stamp(string_datestamp_type);
981 if (Ustrncmp (mainlog_datestamp, nowstamp, Ustrlen(nowstamp)) != 0)
982 {
983 (void)close(mainlogfd); /* Close the file */
984 mainlogfd = -1; /* Clear the file descriptor */
985 mainlog_inode = 0; /* Unset the inode */
986 mainlog_datestamp = NULL; /* Clear the datestamp */
987 }
988 }
989
990 /* Otherwise, we want to check whether the file has been renamed by a
991 cycling script. This could be "if else", but for safety's sake, leave it as
992 "if" so that renaming the log starts a new file even when datestamping is
993 happening. */
994
995 if (mainlogfd >= 0)
996 {
997 if (Ustat(mainlog_name, &statbuf) < 0 || statbuf.st_ino != mainlog_inode)
998 {
999 (void)close(mainlogfd);
1000 mainlogfd = -1;
1001 mainlog_inode = 0;
1002 }
1003 }
1004
1005 /* If the log is closed, open it. Then write the line. */
1006
1007 if (mainlogfd < 0)
1008 {
1009 open_log(&mainlogfd, lt_main, NULL); /* No return on error */
1010 if (fstat(mainlogfd, &statbuf) >= 0) mainlog_inode = statbuf.st_ino;
1011 }
1012
1013 /* Failing to write to the log is disastrous */
1014
1015 written_len = write_to_fd_buf(mainlogfd, log_buffer, length);
1016 if (written_len != length)
1017 {
1018 log_write_failed(US"main log", length, written_len);
1019 /* That function does not return */
1020 }
1021 }
1022 }
1023
1024 /* Handle the log for rejected messages. This can be globally disabled, in
1025 which case the flags are altered above. If there are any header lines (i.e. if
1026 the rejection is happening after the DATA phase), log the recipients and the
1027 headers. */
1028
1029 if ((flags & LOG_REJECT) != 0)
1030 {
1031 header_line *h;
1032
1033 if (header_list != NULL && LOGGING(rejected_header))
1034 {
1035 if (recipients_count > 0)
1036 {
1037 int i;
1038
1039 /* List the sender */
1040
1041 string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1042 "Envelope-from: <%s>\n", sender_address);
1043 while (*ptr) ptr++;
1044
1045 /* List up to 5 recipients */
1046
1047 string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1048 "Envelope-to: <%s>\n", recipients_list[0].address);
1049 while (*ptr) ptr++;
1050
1051 for (i = 1; i < recipients_count && i < 5; i++)
1052 {
1053 string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer), " <%s>\n",
1054 recipients_list[i].address);
1055 while (*ptr) ptr++;
1056 }
1057
1058 if (i < recipients_count)
1059 {
1060 (void)string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1061 " ...\n");
1062 while (*ptr) ptr++;
1063 }
1064 }
1065
1066 /* A header with a NULL text is an unfilled in Received: header */
1067
1068 for (h = header_list; h != NULL; h = h->next)
1069 {
1070 BOOL fitted;
1071 if (h->text == NULL) continue;
1072 fitted = string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1073 "%c %s", h->type, h->text);
1074 while(*ptr) ptr++;
1075 if (!fitted) /* Buffer is full; truncate */
1076 {
1077 ptr -= 100; /* For message and separator */
1078 if (ptr[-1] == '\n') ptr--;
1079 Ustrcpy(ptr, "\n*** truncated ***\n");
1080 while (*ptr) ptr++;
1081 break;
1082 }
1083 }
1084
1085 length = ptr - log_buffer;
1086 }
1087
1088 /* Write to syslog or to a log file */
1089
1090 if ((logging_mode & LOG_MODE_SYSLOG) != 0 &&
1091 (syslog_duplication || (flags & LOG_PANIC) == 0))
1092 write_syslog(LOG_NOTICE, log_buffer);
1093
1094 /* Check for a change to the rejectlog file name when datestamping is in
1095 operation. This happens at midnight, at which point we want to roll over
1096 the file. Closing it has the desired effect. */
1097
1098 if ((logging_mode & LOG_MODE_FILE) != 0)
1099 {
1100 struct stat statbuf;
1101
1102 if (rejectlog_datestamp != NULL)
1103 {
1104 uschar *nowstamp = tod_stamp(string_datestamp_type);
1105 if (Ustrncmp (rejectlog_datestamp, nowstamp, Ustrlen(nowstamp)) != 0)
1106 {
1107 (void)close(rejectlogfd); /* Close the file */
1108 rejectlogfd = -1; /* Clear the file descriptor */
1109 rejectlog_inode = 0; /* Unset the inode */
1110 rejectlog_datestamp = NULL; /* Clear the datestamp */
1111 }
1112 }
1113
1114 /* Otherwise, we want to check whether the file has been renamed by a
1115 cycling script. This could be "if else", but for safety's sake, leave it as
1116 "if" so that renaming the log starts a new file even when datestamping is
1117 happening. */
1118
1119 if (rejectlogfd >= 0)
1120 {
1121 if (Ustat(rejectlog_name, &statbuf) < 0 ||
1122 statbuf.st_ino != rejectlog_inode)
1123 {
1124 (void)close(rejectlogfd);
1125 rejectlogfd = -1;
1126 rejectlog_inode = 0;
1127 }
1128 }
1129
1130 /* Open the file if necessary, and write the data */
1131
1132 if (rejectlogfd < 0)
1133 {
1134 open_log(&rejectlogfd, lt_reject, NULL); /* No return on error */
1135 if (fstat(rejectlogfd, &statbuf) >= 0) rejectlog_inode = statbuf.st_ino;
1136 }
1137
1138 written_len = write_to_fd_buf(rejectlogfd, log_buffer, length);
1139 if (written_len != length)
1140 {
1141 log_write_failed(US"reject log", length, written_len);
1142 /* That function does not return */
1143 }
1144 }
1145 }
1146
1147
1148 /* Handle the panic log, which is not kept open like the others. If it fails to
1149 open, there will be a recursive call to log_write(). We detect this above and
1150 attempt to write to the system log as a last-ditch try at telling somebody. In
1151 all cases except mua_wrapper, try to write to log_stderr. */
1152
1153 if ((flags & LOG_PANIC) != 0)
1154 {
1155 if (log_stderr != NULL && log_stderr != debug_file && !mua_wrapper)
1156 fprintf(log_stderr, "%s", CS log_buffer);
1157
1158 if ((logging_mode & LOG_MODE_SYSLOG) != 0)
1159 {
1160 write_syslog(LOG_ALERT, log_buffer);
1161 }
1162
1163 /* If this panic logging was caused by a failure to open the main log,
1164 the original log line is in panic_save_buffer. Make an attempt to write it. */
1165
1166 if ((logging_mode & LOG_MODE_FILE) != 0)
1167 {
1168 panic_recurseflag = TRUE;
1169 open_log(&paniclogfd, lt_panic, NULL); /* Won't return on failure */
1170 panic_recurseflag = FALSE;
1171
1172 if (panic_save_buffer != NULL)
1173 {
1174 int i = write(paniclogfd, panic_save_buffer, Ustrlen(panic_save_buffer));
1175 i = i; /* compiler quietening */
1176 }
1177
1178 written_len = write_to_fd_buf(paniclogfd, log_buffer, length);
1179 if (written_len != length)
1180 {
1181 int save_errno = errno;
1182 write_syslog(LOG_CRIT, log_buffer);
1183 sprintf(CS log_buffer, "write failed on panic log: length=%d result=%d "
1184 "errno=%d (%s)", length, (int)written_len, save_errno, strerror(save_errno));
1185 write_syslog(LOG_CRIT, log_buffer);
1186 flags |= LOG_PANIC_DIE;
1187 }
1188
1189 (void)close(paniclogfd);
1190 }
1191
1192 /* Give up if the DIE flag is set */
1193
1194 if ((flags & LOG_PANIC_DIE) != LOG_PANIC)
1195 die(NULL, US"Unexpected failure, please try later");
1196 }
1197 }
1198
1199
1200
1201 /*************************************************
1202 * Close any open log files *
1203 *************************************************/
1204
1205 void
1206 log_close_all(void)
1207 {
1208 if (mainlogfd >= 0)
1209 { (void)close(mainlogfd); mainlogfd = -1; }
1210 if (rejectlogfd >= 0)
1211 { (void)close(rejectlogfd); rejectlogfd = -1; }
1212 closelog();
1213 syslog_open = FALSE;
1214 }
1215
1216
1217
1218 /*************************************************
1219 * Multi-bit set or clear *
1220 *************************************************/
1221
1222 /* These functions take a list of bit indexes (terminated by -1) and
1223 clear or set the corresponding bits in the selector.
1224
1225 Arguments:
1226 selector address of the bit string
1227 selsize number of words in the bit string
1228 bits list of bits to set
1229 */
1230
1231 void
1232 bits_clear(unsigned int *selector, size_t selsize, int *bits)
1233 {
1234 for(; *bits != -1; ++bits)
1235 BIT_CLEAR(selector, selsize, *bits);
1236 }
1237
1238 void
1239 bits_set(unsigned int *selector, size_t selsize, int *bits)
1240 {
1241 for(; *bits != -1; ++bits)
1242 BIT_SET(selector, selsize, *bits);
1243 }
1244
1245
1246
1247 /*************************************************
1248 * Decode bit settings for log/debug *
1249 *************************************************/
1250
1251 /* This function decodes a string containing bit settings in the form of +name
1252 and/or -name sequences, and sets/unsets bits in a bit string accordingly. It
1253 also recognizes a numeric setting of the form =<number>, but this is not
1254 intended for user use. It's an easy way for Exim to pass the debug settings
1255 when it is re-exec'ed.
1256
1257 The option table is a list of names and bit indexes. The index -1
1258 means "set all bits, except for those listed in notall". The notall
1259 list is terminated by -1.
1260
1261 The action taken for bad values varies depending upon why we're here.
1262 For log messages, or if the debugging is triggered from config, then we write
1263 to the log on the way out. For debug setting triggered from the command-line,
1264 we treat it as an unknown option: error message to stderr and die.
1265
1266 Arguments:
1267 selector address of the bit string
1268 selsize number of words in the bit string
1269 notall list of bits to exclude from "all"
1270 string the configured string
1271 options the table of option names
1272 count size of table
1273 which "log" or "debug"
1274 flags DEBUG_FROM_CONFIG
1275
1276 Returns: nothing on success - bomb out on failure
1277 */
1278
1279 void
1280 decode_bits(unsigned int *selector, size_t selsize, int *notall,
1281 uschar *string, bit_table *options, int count, uschar *which, int flags)
1282 {
1283 uschar *errmsg;
1284 if (string == NULL) return;
1285
1286 if (*string == '=')
1287 {
1288 char *end; /* Not uschar */
1289 memset(selector, 0, sizeof(*selector)*selsize);
1290 *selector = strtoul(CS string+1, &end, 0);
1291 if (*end == 0) return;
1292 errmsg = string_sprintf("malformed numeric %s_selector setting: %s", which,
1293 string);
1294 goto ERROR_RETURN;
1295 }
1296
1297 /* Handle symbolic setting */
1298
1299 else for(;;)
1300 {
1301 BOOL adding;
1302 uschar *s;
1303 int len;
1304 bit_table *start, *end;
1305
1306 while (isspace(*string)) string++;
1307 if (*string == 0) return;
1308
1309 if (*string != '+' && *string != '-')
1310 {
1311 errmsg = string_sprintf("malformed %s_selector setting: "
1312 "+ or - expected but found \"%s\"", which, string);
1313 goto ERROR_RETURN;
1314 }
1315
1316 adding = *string++ == '+';
1317 s = string;
1318 while (isalnum(*string) || *string == '_') string++;
1319 len = string - s;
1320
1321 start = options;
1322 end = options + count;
1323
1324 while (start < end)
1325 {
1326 bit_table *middle = start + (end - start)/2;
1327 int c = Ustrncmp(s, middle->name, len);
1328 if (c == 0)
1329 {
1330 if (middle->name[len] != 0) c = -1; else
1331 {
1332 unsigned int bit = middle->bit;
1333
1334 if (bit == -1)
1335 {
1336 if (adding)
1337 {
1338 memset(selector, -1, sizeof(*selector)*selsize);
1339 bits_clear(selector, selsize, notall);
1340 }
1341 else
1342 memset(selector, 0, sizeof(*selector)*selsize);
1343 }
1344 else if (adding)
1345 BIT_SET(selector, selsize, bit);
1346 else
1347 BIT_CLEAR(selector, selsize, bit);
1348
1349 break; /* Out of loop to match selector name */
1350 }
1351 }
1352 if (c < 0) end = middle; else start = middle + 1;
1353 } /* Loop to match selector name */
1354
1355 if (start >= end)
1356 {
1357 errmsg = string_sprintf("unknown %s_selector setting: %c%.*s", which,
1358 adding? '+' : '-', len, s);
1359 goto ERROR_RETURN;
1360 }
1361 } /* Loop for selector names */
1362
1363 /* Handle disasters */
1364
1365 ERROR_RETURN:
1366 if (Ustrcmp(which, "debug") == 0)
1367 {
1368 if (flags & DEBUG_FROM_CONFIG)
1369 {
1370 log_write(0, LOG_CONFIG|LOG_PANIC, "%s", errmsg);
1371 return;
1372 }
1373 fprintf(stderr, "exim: %s\n", errmsg);
1374 exit(EXIT_FAILURE);
1375 }
1376 else log_write(0, LOG_CONFIG|LOG_PANIC_DIE, "%s", errmsg);
1377 }
1378
1379
1380
1381 /*************************************************
1382 * Activate a debug logfile (late) *
1383 *************************************************/
1384
1385 /* Normally, debugging is activated from the command-line; it may be useful
1386 within the configuration to activate debugging later, based on certain
1387 conditions. If debugging is already in progress, we return early, no action
1388 taken (besides debug-logging that we wanted debug-logging).
1389
1390 Failures in options are not fatal but will result in paniclog entries for the
1391 misconfiguration.
1392
1393 The first use of this is in ACL logic, "control = debug/tag=foo/opts=+expand"
1394 which can be combined with conditions, etc, to activate extra logging only
1395 for certain sources. The second use is inetd wait mode debug preservation. */
1396
1397 void
1398 debug_logging_activate(uschar *tag_name, uschar *opts)
1399 {
1400 int fd = -1;
1401
1402 if (debug_file)
1403 {
1404 debug_printf("DEBUGGING ACTIVATED FROM WITHIN CONFIG.\n"
1405 "DEBUG: Tag=\"%s\" opts=\"%s\"\n", tag_name, opts ? opts : US"");
1406 return;
1407 }
1408
1409 if (tag_name != NULL && (Ustrchr(tag_name, '/') != NULL))
1410 {
1411 log_write(0, LOG_MAIN|LOG_PANIC, "debug tag may not contain a '/' in: %s",
1412 tag_name);
1413 return;
1414 }
1415
1416 debug_selector = D_default;
1417 if (opts)
1418 decode_bits(&debug_selector, 1, debug_notall, opts,
1419 debug_options, debug_options_count, US"debug", DEBUG_FROM_CONFIG);
1420
1421 /* When activating from a transport process we may never have logged at all
1422 resulting in certain setup not having been done. Hack this for now so we
1423 do not segfault; note that nondefault log locations will not work */
1424
1425 if (!*file_path) set_file_path();
1426
1427 open_log(&fd, lt_debug, tag_name);
1428
1429 if (fd != -1)
1430 debug_file = fdopen(fd, "w");
1431 else
1432 log_write(0, LOG_MAIN|LOG_PANIC, "unable to open debug log");
1433 }
1434
1435
1436 void
1437 debug_logging_stop(void)
1438 {
1439 if (!debug_file || !debuglog_name[0]) return;
1440
1441 debug_selector = 0;
1442 fclose(debug_file);
1443 debug_file = NULL;
1444 unlink_log(lt_debug);
1445 }
1446
1447
1448 /* End of log.c */