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