032eb876f205099888597450168df2fca5364145
[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 err < 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)
494   if ((panic_save_buffer = US malloc(LOG_BUFFER_SIZE)))
495     memcpy(panic_save_buffer, log_buffer, LOG_BUFFER_SIZE);
496
497 log_write(0, LOG_PANIC_DIE, "Cannot open %s log file \"%s\": %s: "
498   "euid=%d egid=%d", log_names[type], buffer, strerror(errno), euid, getegid());
499 /* Never returns */
500 }
501
502
503 static void
504 unlink_log(int type)
505 {
506 if (type == lt_debug) unlink(CS debuglog_name);
507 }
508
509
510
511 /*************************************************
512 *     Add configuration file info to log line    *
513 *************************************************/
514
515 /* This is put in a function because it's needed twice (once for debugging,
516 once for real).
517
518 Arguments:
519   ptr         pointer to the end of the line we are building
520   flags       log flags
521
522 Returns:      updated pointer
523 */
524
525 static uschar *
526 log_config_info(uschar *ptr, int flags)
527 {
528 Ustrcpy(ptr, "Exim configuration error");
529 ptr += 24;
530
531 if ((flags & (LOG_CONFIG_FOR & ~LOG_CONFIG)) != 0)
532   {
533   Ustrcpy(ptr, " for ");
534   return ptr + 5;
535   }
536
537 if ((flags & (LOG_CONFIG_IN & ~LOG_CONFIG)) != 0)
538   {
539   sprintf(CS ptr, " in line %d of %s", config_lineno, config_filename);
540   while (*ptr) ptr++;
541   }
542
543 Ustrcpy(ptr, ":\n  ");
544 return ptr + 4;
545 }
546
547
548 /*************************************************
549 *           A write() operation failed           *
550 *************************************************/
551
552 /* This function is called when write() fails on anything other than the panic
553 log, which can happen if a disk gets full or a file gets too large or whatever.
554 We try to save the relevant message in the panic_save buffer before crashing
555 out.
556
557 The potential invoker should probably not call us for EINTR -1 writes.  But
558 otherwise, short writes are bad as we don't do non-blocking writes to fds
559 subject to flow control.  (If we do, that's new and the logic of this should
560 be reconsidered).
561
562 Arguments:
563   name      the name of the log being written
564   length    the string length being written
565   rc        the return value from write()
566
567 Returns:    does not return
568 */
569
570 static void
571 log_write_failed(uschar *name, int length, int rc)
572 {
573 int save_errno = errno;
574
575 if (!panic_save_buffer)
576   if ((panic_save_buffer = US malloc(LOG_BUFFER_SIZE)))
577     memcpy(panic_save_buffer, log_buffer, LOG_BUFFER_SIZE);
578
579 log_write(0, LOG_PANIC_DIE, "failed to write to %s: length=%d result=%d "
580   "errno=%d (%s)", name, length, rc, save_errno,
581   (save_errno == 0)? "write incomplete" : strerror(save_errno));
582 /* Never returns */
583 }
584
585
586
587 /*************************************************
588 *     Write to an fd, retrying after signals     *
589 *************************************************/
590
591 /* Basic write to fd for logs, handling EINTR.
592
593 Arguments:
594   fd        the fd to write to
595   buf       the string to write
596   length    the string length being written
597
598 Returns:
599   length actually written, persisting an errno from write()
600 */
601 ssize_t
602 write_to_fd_buf(int fd, const uschar *buf, size_t length)
603 {
604 ssize_t wrote;
605 size_t total_written = 0;
606 const uschar *p = buf;
607 size_t left = length;
608
609 while (1)
610   {
611   wrote = write(fd, p, left);
612   if (wrote == (ssize_t)-1)
613     {
614     if (errno == EINTR) continue;
615     return wrote;
616     }
617   total_written += wrote;
618   if (wrote == left)
619     break;
620   else
621     {
622     p += wrote;
623     left -= wrote;
624     }
625   }
626 return total_written;
627 }
628
629
630
631 static void
632 set_file_path(void)
633 {
634 int sep = ':';              /* Fixed separator - outside use */
635 uschar *t;
636 const uschar *tt = US LOG_FILE_PATH;
637 while ((t = string_nextinlist(&tt, &sep, log_buffer, LOG_BUFFER_SIZE)))
638   {
639   if (Ustrcmp(t, "syslog") == 0 || t[0] == 0) continue;
640   file_path = string_copy(t);
641   break;
642   }
643 }
644
645
646
647 /*************************************************
648 *            Write message to log file           *
649 *************************************************/
650
651 /* Exim can be configured to log to local files, or use syslog, or both. This
652 is controlled by the setting of log_file_path. The following cases are
653 recognized:
654
655   log_file_path = ""               write files in the spool/log directory
656   log_file_path = "xxx"            write files in the xxx directory
657   log_file_path = "syslog"         write to syslog
658   log_file_path = "syslog : xxx"   write to syslog and to files (any order)
659
660 The message always gets '\n' added on the end of it, since more than one
661 process may be writing to the log at once and we don't want intermingling to
662 happen in the middle of lines. To be absolutely sure of this we write the data
663 into a private buffer and then put it out in a single write() call.
664
665 The flags determine which log(s) the message is written to, or for syslogging,
666 which priority to use, and in the case of the panic log, whether the process
667 should die afterwards.
668
669 The variable really_exim is TRUE only when exim is running in privileged state
670 (i.e. not with a changed configuration or with testing options such as -brw).
671 If it is not, don't try to write to the log because permission will probably be
672 denied.
673
674 Avoid actually writing to the logs when exim is called with -bv or -bt to
675 test an address, but take other actions, such as panicing.
676
677 In Exim proper, the buffer for building the message is got at start-up, so that
678 nothing gets done if it can't be got. However, some functions that are also
679 used in utilities occasionally obey log_write calls in error situations, and it
680 is simplest to put a single malloc() here rather than put one in each utility.
681 Malloc is used directly because the store functions may call log_write().
682
683 If a message_id exists, we include it after the timestamp.
684
685 Arguments:
686   selector  write to main log or LOG_INFO only if this value is zero, or if
687               its bit is set in log_selector[0]
688   flags     each bit indicates some independent action:
689               LOG_SENDER      add raw sender to the message
690               LOG_RECIPIENTS  add raw recipients list to message
691               LOG_CONFIG      add "Exim configuration error"
692               LOG_CONFIG_FOR  add " for " instead of ":\n  "
693               LOG_CONFIG_IN   add " in line x[ of file y]"
694               LOG_MAIN        write to main log or syslog LOG_INFO
695               LOG_REJECT      write to reject log or syslog LOG_NOTICE
696               LOG_PANIC       write to panic log or syslog LOG_ALERT
697               LOG_PANIC_DIE   write to panic log or LOG_ALERT and then crash
698   format    a printf() format
699   ...       arguments for format
700
701 Returns:    nothing
702 */
703
704 void
705 log_write(unsigned int selector, int flags, const char *format, ...)
706 {
707 uschar *ptr;
708 int length;
709 int paniclogfd;
710 ssize_t written_len;
711 va_list ap;
712
713 /* If panic_recurseflag is set, we have failed to open the panic log. This is
714 the ultimate disaster. First try to write the message to a debug file and/or
715 stderr and also to syslog. If panic_save_buffer is not NULL, it contains the
716 original log line that caused the problem. Afterwards, expire. */
717
718 if (panic_recurseflag)
719   {
720   uschar *extra = (panic_save_buffer == NULL)? US"" : panic_save_buffer;
721   if (debug_file != NULL) debug_printf("%s%s", extra, log_buffer);
722   if (log_stderr != NULL && log_stderr != debug_file)
723     fprintf(log_stderr, "%s%s", extra, log_buffer);
724   if (*extra != 0) write_syslog(LOG_CRIT, extra);
725   write_syslog(LOG_CRIT, log_buffer);
726   die(US"exim: could not open panic log - aborting: see message(s) above",
727     US"Unexpected log failure, please try later");
728   }
729
730 /* Ensure we have a buffer (see comment above); this should never be obeyed
731 when running Exim proper, only when running utilities. */
732
733 if (!log_buffer)
734   if (!(log_buffer = US malloc(LOG_BUFFER_SIZE)))
735     {
736     fprintf(stderr, "exim: failed to get store for log buffer\n");
737     exim_exit(EXIT_FAILURE);
738     }
739
740 /* If we haven't already done so, inspect the setting of log_file_path to
741 determine whether to log to files and/or to syslog. Bits in logging_mode
742 control this, and for file logging, the path must end up in file_path. This
743 variable must be in permanent store because it may be required again later in
744 the process. */
745
746 if (!path_inspected)
747   {
748   BOOL multiple = FALSE;
749   int old_pool = store_pool;
750
751   store_pool = POOL_PERM;
752
753   /* If nothing has been set, don't waste effort... the default values for the
754   statics are file_path="" and logging_mode = LOG_MODE_FILE. */
755
756   if (*log_file_path)
757     {
758     int sep = ':';              /* Fixed separator - outside use */
759     uschar *s;
760     const uschar *ss = log_file_path;
761     logging_mode = 0;
762     while ((s = string_nextinlist(&ss, &sep, log_buffer, LOG_BUFFER_SIZE)))
763       {
764       if (Ustrcmp(s, "syslog") == 0)
765         logging_mode |= LOG_MODE_SYSLOG;
766       else if ((logging_mode & LOG_MODE_FILE) != 0) multiple = TRUE;
767       else
768         {
769         logging_mode |= LOG_MODE_FILE;
770
771         /* If a non-empty path is given, use it */
772
773         if (*s)
774           file_path = string_copy(s);
775
776         /* If the path is empty, we want to use the first non-empty, non-
777         syslog item in LOG_FILE_PATH, if there is one, since the value of
778         log_file_path may have been set at runtime. If there is no such item,
779         use the ultimate default in the spool directory. */
780
781         else
782           set_file_path();  /* Empty item in log_file_path */
783         }    /* First non-syslog item in log_file_path */
784       }      /* Scan of log_file_path */
785     }
786
787   /* If no modes have been selected, it is a major disaster */
788
789   if (logging_mode == 0)
790     die(US"Neither syslog nor file logging set in log_file_path",
791         US"Unexpected logging failure");
792
793   /* Set up the ultimate default if necessary. Then revert to the old store
794   pool, and record that we've sorted out the path. */
795
796   if ((logging_mode & LOG_MODE_FILE) != 0 && file_path[0] == 0)
797     file_path = string_sprintf("%s/log/%%slog", spool_directory);
798   store_pool = old_pool;
799   path_inspected = TRUE;
800
801   /* If more than one file path was given, log a complaint. This recursive call
802   should work since we have now set up the routing. */
803
804   if (multiple)
805     log_write(0, LOG_MAIN|LOG_PANIC,
806       "More than one path given in log_file_path: using %s", file_path);
807   }
808
809 /* If debugging, show all log entries, but don't show headers. Do it all
810 in one go so that it doesn't get split when multi-processing. */
811
812 DEBUG(D_any|D_v)
813   {
814   int i;
815   ptr = log_buffer;
816
817   Ustrcpy(ptr, "LOG:");
818   ptr += 4;
819
820   /* Show the selector that was passed into the call. */
821
822   for (i = 0; i < log_options_count; i++)
823     {
824     unsigned int bitnum = log_options[i].bit;
825     if (bitnum < BITWORDSIZE && selector == BIT(bitnum))
826       {
827       *ptr++ = ' ';
828       Ustrcpy(ptr, log_options[i].name);
829       while (*ptr) ptr++;
830       }
831     }
832
833   sprintf(CS ptr, "%s%s%s%s\n  ",
834     ((flags & LOG_MAIN) != 0)?    " MAIN"   : "",
835     ((flags & LOG_PANIC) != 0)?   " PANIC"  : "",
836     ((flags & LOG_PANIC_DIE) == LOG_PANIC_DIE)? " DIE" : "",
837     ((flags & LOG_REJECT) != 0)?  " REJECT" : "");
838
839   while(*ptr) ptr++;
840   if ((flags & LOG_CONFIG) != 0) ptr = log_config_info(ptr, flags);
841
842   va_start(ap, format);
843   if (!string_vformat(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer)-1, format, ap))
844     Ustrcpy(ptr, "**** log string overflowed log buffer ****");
845   va_end(ap);
846
847   while(*ptr) ptr++;
848   Ustrcat(ptr, "\n");
849   debug_printf("%s", log_buffer);
850   }
851
852 /* If no log file is specified, we are in a mess. */
853
854 if ((flags & (LOG_MAIN|LOG_PANIC|LOG_REJECT)) == 0)
855   log_write(0, LOG_MAIN|LOG_PANIC_DIE, "log_write called with no log "
856     "flags set");
857
858 /* There are some weird circumstances in which logging is disabled. */
859
860 if (disable_logging)
861   {
862   DEBUG(D_any) debug_printf("log writing disabled\n");
863   return;
864   }
865
866 /* Handle disabled reject log */
867
868 if (!write_rejectlog) flags &= ~LOG_REJECT;
869
870 /* Create the main message in the log buffer. Do not include the message id
871 when called by a utility. */
872
873 ptr = log_buffer;
874 sprintf(CS ptr, "%s ", tod_stamp(tod_log));
875 while(*ptr) ptr++;
876
877 if (LOGGING(pid))
878   {
879   sprintf(CS ptr, "[%d] ", (int)getpid());
880   while (*ptr) ptr++;
881   }
882
883 if (really_exim && message_id[0] != 0)
884   {
885   sprintf(CS ptr, "%s ", message_id);
886   while(*ptr) ptr++;
887   }
888
889 if ((flags & LOG_CONFIG) != 0) ptr = log_config_info(ptr, flags);
890
891 va_start(ap, format);
892 if (!string_vformat(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer)-1, format, ap))
893   Ustrcpy(ptr, "**** log string overflowed log buffer ****\n");
894 while(*ptr) ptr++;
895 va_end(ap);
896
897 /* Add the raw, unrewritten, sender to the message if required. This is done
898 this way because it kind of fits with LOG_RECIPIENTS. */
899
900 if ((flags & LOG_SENDER) != 0 &&
901     ptr < log_buffer + LOG_BUFFER_SIZE - 10 - Ustrlen(raw_sender))
902   {
903   sprintf(CS ptr, " from <%s>", raw_sender);
904   while (*ptr) ptr++;
905   }
906
907 /* Add list of recipients to the message if required; the raw list,
908 before rewriting, was saved in raw_recipients. There may be none, if an ACL
909 discarded them all. */
910
911 if ((flags & LOG_RECIPIENTS) != 0 && ptr < log_buffer + LOG_BUFFER_SIZE - 6 &&
912      raw_recipients_count > 0)
913   {
914   int i;
915   sprintf(CS ptr, " for");
916   while (*ptr) ptr++;
917   for (i = 0; i < raw_recipients_count; i++)
918     {
919     uschar *s = raw_recipients[i];
920     if (log_buffer + LOG_BUFFER_SIZE - ptr < Ustrlen(s) + 3) break;
921     sprintf(CS ptr, " %s", s);
922     while (*ptr) ptr++;
923     }
924   }
925
926 sprintf(CS  ptr, "\n");
927 while(*ptr) ptr++;
928 length = ptr - log_buffer;
929
930 /* Handle loggable errors when running a utility, or when address testing.
931 Write to log_stderr unless debugging (when it will already have been written),
932 or unless there is no log_stderr (expn called from daemon, for example). */
933
934 if (!really_exim || log_testing_mode)
935   {
936   if (debug_selector == 0 && log_stderr != NULL &&
937       (selector == 0 || (selector & log_selector[0]) != 0))
938     {
939     if (host_checking)
940       fprintf(log_stderr, "LOG: %s", CS(log_buffer + 20));  /* no timestamp */
941     else
942       fprintf(log_stderr, "%s", CS log_buffer);
943     }
944   if ((flags & LOG_PANIC_DIE) == LOG_PANIC_DIE) exim_exit(EXIT_FAILURE);
945   return;
946   }
947
948 /* Handle the main log. We know that either syslog or file logging (or both) is
949 set up. A real file gets left open during reception or delivery once it has
950 been opened, but we don't want to keep on writing to it for too long after it
951 has been renamed. Therefore, do a stat() and see if the inode has changed, and
952 if so, re-open. */
953
954 if ((flags & LOG_MAIN) != 0 &&
955     (selector == 0 || (selector & log_selector[0]) != 0))
956   {
957   if ((logging_mode & LOG_MODE_SYSLOG) != 0 &&
958       (syslog_duplication || (flags & (LOG_REJECT|LOG_PANIC)) == 0))
959     write_syslog(LOG_INFO, log_buffer);
960
961   if ((logging_mode & LOG_MODE_FILE) != 0)
962     {
963     struct stat statbuf;
964
965     /* Check for a change to the mainlog file name when datestamping is in
966     operation. This happens at midnight, at which point we want to roll over
967     the file. Closing it has the desired effect. */
968
969     if (mainlog_datestamp != NULL)
970       {
971       uschar *nowstamp = tod_stamp(string_datestamp_type);
972       if (Ustrncmp (mainlog_datestamp, nowstamp, Ustrlen(nowstamp)) != 0)
973         {
974         (void)close(mainlogfd);       /* Close the file */
975         mainlogfd = -1;               /* Clear the file descriptor */
976         mainlog_inode = 0;            /* Unset the inode */
977         mainlog_datestamp = NULL;     /* Clear the datestamp */
978         }
979       }
980
981     /* Otherwise, we want to check whether the file has been renamed by a
982     cycling script. This could be "if else", but for safety's sake, leave it as
983     "if" so that renaming the log starts a new file even when datestamping is
984     happening. */
985
986     if (mainlogfd >= 0)
987       {
988       if (Ustat(mainlog_name, &statbuf) < 0 || statbuf.st_ino != mainlog_inode)
989         {
990         (void)close(mainlogfd);
991         mainlogfd = -1;
992         mainlog_inode = 0;
993         }
994       }
995
996     /* If the log is closed, open it. Then write the line. */
997
998     if (mainlogfd < 0)
999       {
1000       open_log(&mainlogfd, lt_main, NULL);     /* No return on error */
1001       if (fstat(mainlogfd, &statbuf) >= 0) mainlog_inode = statbuf.st_ino;
1002       }
1003
1004     /* Failing to write to the log is disastrous */
1005
1006     written_len = write_to_fd_buf(mainlogfd, log_buffer, length);
1007     if (written_len != length)
1008       {
1009       log_write_failed(US"main log", length, written_len);
1010       /* That function does not return */
1011       }
1012     }
1013   }
1014
1015 /* Handle the log for rejected messages. This can be globally disabled, in
1016 which case the flags are altered above. If there are any header lines (i.e. if
1017 the rejection is happening after the DATA phase), log the recipients and the
1018 headers. */
1019
1020 if ((flags & LOG_REJECT) != 0)
1021   {
1022   header_line *h;
1023
1024   if (header_list != NULL && LOGGING(rejected_header))
1025     {
1026     if (recipients_count > 0)
1027       {
1028       int i;
1029
1030       /* List the sender */
1031
1032       string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1033         "Envelope-from: <%s>\n", sender_address);
1034       while (*ptr) ptr++;
1035
1036       /* List up to 5 recipients */
1037
1038       string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1039         "Envelope-to: <%s>\n", recipients_list[0].address);
1040       while (*ptr) ptr++;
1041
1042       for (i = 1; i < recipients_count && i < 5; i++)
1043         {
1044         string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer), "    <%s>\n",
1045           recipients_list[i].address);
1046         while (*ptr) ptr++;
1047         }
1048
1049       if (i < recipients_count)
1050         {
1051         (void)string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1052           "    ...\n");
1053         while (*ptr) ptr++;
1054         }
1055       }
1056
1057     /* A header with a NULL text is an unfilled in Received: header */
1058
1059     for (h = header_list; h != NULL; h = h->next)
1060       {
1061       BOOL fitted;
1062       if (h->text == NULL) continue;
1063       fitted = string_format(ptr, LOG_BUFFER_SIZE - (ptr-log_buffer),
1064         "%c %s", h->type, h->text);
1065       while(*ptr) ptr++;
1066       if (!fitted)         /* Buffer is full; truncate */
1067         {
1068         ptr -= 100;        /* For message and separator */
1069         if (ptr[-1] == '\n') ptr--;
1070         Ustrcpy(ptr, "\n*** truncated ***\n");
1071         while (*ptr) ptr++;
1072         break;
1073         }
1074       }
1075
1076     length = ptr - log_buffer;
1077     }
1078
1079   /* Write to syslog or to a log file */
1080
1081   if ((logging_mode & LOG_MODE_SYSLOG) != 0 &&
1082       (syslog_duplication || (flags & LOG_PANIC) == 0))
1083     write_syslog(LOG_NOTICE, log_buffer);
1084
1085   /* Check for a change to the rejectlog file name when datestamping is in
1086   operation. This happens at midnight, at which point we want to roll over
1087   the file. Closing it has the desired effect. */
1088
1089   if ((logging_mode & LOG_MODE_FILE) != 0)
1090     {
1091     struct stat statbuf;
1092
1093     if (rejectlog_datestamp != NULL)
1094       {
1095       uschar *nowstamp = tod_stamp(string_datestamp_type);
1096       if (Ustrncmp (rejectlog_datestamp, nowstamp, Ustrlen(nowstamp)) != 0)
1097         {
1098         (void)close(rejectlogfd);       /* Close the file */
1099         rejectlogfd = -1;               /* Clear the file descriptor */
1100         rejectlog_inode = 0;            /* Unset the inode */
1101         rejectlog_datestamp = NULL;     /* Clear the datestamp */
1102         }
1103       }
1104
1105     /* Otherwise, we want to check whether the file has been renamed by a
1106     cycling script. This could be "if else", but for safety's sake, leave it as
1107     "if" so that renaming the log starts a new file even when datestamping is
1108     happening. */
1109
1110     if (rejectlogfd >= 0)
1111       {
1112       if (Ustat(rejectlog_name, &statbuf) < 0 ||
1113            statbuf.st_ino != rejectlog_inode)
1114         {
1115         (void)close(rejectlogfd);
1116         rejectlogfd = -1;
1117         rejectlog_inode = 0;
1118         }
1119       }
1120
1121     /* Open the file if necessary, and write the data */
1122
1123     if (rejectlogfd < 0)
1124       {
1125       open_log(&rejectlogfd, lt_reject, NULL); /* No return on error */
1126       if (fstat(rejectlogfd, &statbuf) >= 0) rejectlog_inode = statbuf.st_ino;
1127       }
1128
1129     written_len = write_to_fd_buf(rejectlogfd, log_buffer, length);
1130     if (written_len != length)
1131       {
1132       log_write_failed(US"reject log", length, written_len);
1133       /* That function does not return */
1134       }
1135     }
1136   }
1137
1138
1139 /* Handle the panic log, which is not kept open like the others. If it fails to
1140 open, there will be a recursive call to log_write(). We detect this above and
1141 attempt to write to the system log as a last-ditch try at telling somebody. In
1142 all cases except mua_wrapper, try to write to log_stderr. */
1143
1144 if ((flags & LOG_PANIC) != 0)
1145   {
1146   if (log_stderr != NULL && log_stderr != debug_file && !mua_wrapper)
1147     fprintf(log_stderr, "%s", CS log_buffer);
1148
1149   if ((logging_mode & LOG_MODE_SYSLOG) != 0)
1150     {
1151     write_syslog(LOG_ALERT, log_buffer);
1152     }
1153
1154   /* If this panic logging was caused by a failure to open the main log,
1155   the original log line is in panic_save_buffer. Make an attempt to write it. */
1156
1157   if ((logging_mode & LOG_MODE_FILE) != 0)
1158     {
1159     panic_recurseflag = TRUE;
1160     open_log(&paniclogfd, lt_panic, NULL);  /* Won't return on failure */
1161     panic_recurseflag = FALSE;
1162
1163     if (panic_save_buffer != NULL)
1164       {
1165       int i = write(paniclogfd, panic_save_buffer, Ustrlen(panic_save_buffer));
1166       i = i;    /* compiler quietening */
1167       }
1168
1169     written_len = write_to_fd_buf(paniclogfd, log_buffer, length);
1170     if (written_len != length)
1171       {
1172       int save_errno = errno;
1173       write_syslog(LOG_CRIT, log_buffer);
1174       sprintf(CS log_buffer, "write failed on panic log: length=%d result=%d "
1175         "errno=%d (%s)", length, (int)written_len, save_errno, strerror(save_errno));
1176       write_syslog(LOG_CRIT, log_buffer);
1177       flags |= LOG_PANIC_DIE;
1178       }
1179
1180     (void)close(paniclogfd);
1181     }
1182
1183   /* Give up if the DIE flag is set */
1184
1185   if ((flags & LOG_PANIC_DIE) != LOG_PANIC)
1186     die(NULL, US"Unexpected failure, please try later");
1187   }
1188 }
1189
1190
1191
1192 /*************************************************
1193 *            Close any open log files            *
1194 *************************************************/
1195
1196 void
1197 log_close_all(void)
1198 {
1199 if (mainlogfd >= 0)
1200   { (void)close(mainlogfd); mainlogfd = -1; }
1201 if (rejectlogfd >= 0)
1202   { (void)close(rejectlogfd); rejectlogfd = -1; }
1203 closelog();
1204 syslog_open = FALSE;
1205 }
1206
1207
1208
1209 /*************************************************
1210 *             Multi-bit set or clear             *
1211 *************************************************/
1212
1213 /* These functions take a list of bit indexes (terminated by -1) and
1214 clear or set the corresponding bits in the selector.
1215
1216 Arguments:
1217   selector       address of the bit string
1218   selsize        number of words in the bit string
1219   bits           list of bits to set
1220 */
1221
1222 void
1223 bits_clear(unsigned int *selector, size_t selsize, int *bits)
1224 {
1225 for(; *bits != -1; ++bits)
1226   BIT_CLEAR(selector, selsize, *bits);
1227 }
1228
1229 void
1230 bits_set(unsigned int *selector, size_t selsize, int *bits)
1231 {
1232 for(; *bits != -1; ++bits)
1233   BIT_SET(selector, selsize, *bits);
1234 }
1235
1236
1237
1238 /*************************************************
1239 *         Decode bit settings for log/debug      *
1240 *************************************************/
1241
1242 /* This function decodes a string containing bit settings in the form of +name
1243 and/or -name sequences, and sets/unsets bits in a bit string accordingly. It
1244 also recognizes a numeric setting of the form =<number>, but this is not
1245 intended for user use. It's an easy way for Exim to pass the debug settings
1246 when it is re-exec'ed.
1247
1248 The option table is a list of names and bit indexes. The index -1
1249 means "set all bits, except for those listed in notall". The notall
1250 list is terminated by -1.
1251
1252 The action taken for bad values varies depending upon why we're here.
1253 For log messages, or if the debugging is triggered from config, then we write
1254 to the log on the way out.  For debug setting triggered from the command-line,
1255 we treat it as an unknown option: error message to stderr and die.
1256
1257 Arguments:
1258   selector       address of the bit string
1259   selsize        number of words in the bit string
1260   notall         list of bits to exclude from "all"
1261   string         the configured string
1262   options        the table of option names
1263   count          size of table
1264   which          "log" or "debug"
1265   flags          DEBUG_FROM_CONFIG
1266
1267 Returns:         nothing on success - bomb out on failure
1268 */
1269
1270 void
1271 decode_bits(unsigned int *selector, size_t selsize, int *notall,
1272   uschar *string, bit_table *options, int count, uschar *which, int flags)
1273 {
1274 uschar *errmsg;
1275 if (string == NULL) return;
1276
1277 if (*string == '=')
1278   {
1279   char *end;    /* Not uschar */
1280   memset(selector, 0, sizeof(*selector)*selsize);
1281   *selector = strtoul(CS string+1, &end, 0);
1282   if (*end == 0) return;
1283   errmsg = string_sprintf("malformed numeric %s_selector setting: %s", which,
1284     string);
1285   goto ERROR_RETURN;
1286   }
1287
1288 /* Handle symbolic setting */
1289
1290 else for(;;)
1291   {
1292   BOOL adding;
1293   uschar *s;
1294   int len;
1295   bit_table *start, *end;
1296
1297   while (isspace(*string)) string++;
1298   if (*string == 0) return;
1299
1300   if (*string != '+' && *string != '-')
1301     {
1302     errmsg = string_sprintf("malformed %s_selector setting: "
1303       "+ or - expected but found \"%s\"", which, string);
1304     goto ERROR_RETURN;
1305     }
1306
1307   adding = *string++ == '+';
1308   s = string;
1309   while (isalnum(*string) || *string == '_') string++;
1310   len = string - s;
1311
1312   start = options;
1313   end = options + count;
1314
1315   while (start < end)
1316     {
1317     bit_table *middle = start + (end - start)/2;
1318     int c = Ustrncmp(s, middle->name, len);
1319     if (c == 0)
1320       {
1321       if (middle->name[len] != 0) c = -1; else
1322         {
1323         unsigned int bit = middle->bit;
1324
1325         if (bit == -1)
1326           {
1327           if (adding)
1328             {
1329             memset(selector, -1, sizeof(*selector)*selsize);
1330             bits_clear(selector, selsize, notall);
1331             }
1332           else
1333             memset(selector, 0, sizeof(*selector)*selsize);
1334           }
1335         else if (adding)
1336           BIT_SET(selector, selsize, bit);
1337         else
1338           BIT_CLEAR(selector, selsize, bit);
1339
1340         break;  /* Out of loop to match selector name */
1341         }
1342       }
1343     if (c < 0) end = middle; else start = middle + 1;
1344     }  /* Loop to match selector name */
1345
1346   if (start >= end)
1347     {
1348     errmsg = string_sprintf("unknown %s_selector setting: %c%.*s", which,
1349       adding? '+' : '-', len, s);
1350     goto ERROR_RETURN;
1351     }
1352   }    /* Loop for selector names */
1353
1354 /* Handle disasters */
1355
1356 ERROR_RETURN:
1357 if (Ustrcmp(which, "debug") == 0)
1358   {
1359   if (flags & DEBUG_FROM_CONFIG)
1360     {
1361     log_write(0, LOG_CONFIG|LOG_PANIC, "%s", errmsg);
1362     return;
1363     }
1364   fprintf(stderr, "exim: %s\n", errmsg);
1365   exit(EXIT_FAILURE);
1366   }
1367 else log_write(0, LOG_CONFIG|LOG_PANIC_DIE, "%s", errmsg);
1368 }
1369
1370
1371
1372 /*************************************************
1373 *        Activate a debug logfile (late)         *
1374 *************************************************/
1375
1376 /* Normally, debugging is activated from the command-line; it may be useful
1377 within the configuration to activate debugging later, based on certain
1378 conditions.  If debugging is already in progress, we return early, no action
1379 taken (besides debug-logging that we wanted debug-logging).
1380
1381 Failures in options are not fatal but will result in paniclog entries for the
1382 misconfiguration.
1383
1384 The first use of this is in ACL logic, "control = debug/tag=foo/opts=+expand"
1385 which can be combined with conditions, etc, to activate extra logging only
1386 for certain sources. The second use is inetd wait mode debug preservation. */
1387
1388 void
1389 debug_logging_activate(uschar *tag_name, uschar *opts)
1390 {
1391 int fd = -1;
1392
1393 if (debug_file)
1394   {
1395   debug_printf("DEBUGGING ACTIVATED FROM WITHIN CONFIG.\n"
1396       "DEBUG: Tag=\"%s\" opts=\"%s\"\n", tag_name, opts ? opts : US"");
1397   return;
1398   }
1399
1400 if (tag_name != NULL && (Ustrchr(tag_name, '/') != NULL))
1401   {
1402   log_write(0, LOG_MAIN|LOG_PANIC, "debug tag may not contain a '/' in: %s",
1403       tag_name);
1404   return;
1405   }
1406
1407 debug_selector = D_default;
1408 if (opts)
1409   decode_bits(&debug_selector, 1, debug_notall, opts,
1410       debug_options, debug_options_count, US"debug", DEBUG_FROM_CONFIG);
1411
1412 /* When activating from a transport process we may never have logged at all
1413 resulting in certain setup not having been done.  Hack this for now so we
1414 do not segfault; note that nondefault log locations will not work */
1415
1416 if (!*file_path) set_file_path();
1417
1418 open_log(&fd, lt_debug, tag_name);
1419
1420 if (fd != -1)
1421   debug_file = fdopen(fd, "w");
1422 else
1423   log_write(0, LOG_MAIN|LOG_PANIC, "unable to open debug log");
1424 }
1425
1426
1427 void
1428 debug_logging_stop(void)
1429 {
1430 if (!debug_file || !debuglog_name[0]) return;
1431
1432 debug_selector = 0;
1433 fclose(debug_file);
1434 debug_file = NULL;
1435 unlink_log(lt_debug);
1436 }
1437
1438
1439 /* End of log.c */