Debug: "kill" option on ACL control=debug. Bug 1831
[exim.git] / src / src / log.c
index 231db6581db9c95bb0e7018b378eec83753bca31..b01a179c0bb37ccb27c1f3f658ca8c16bcea6070 100644 (file)
@@ -1,10 +1,8 @@
-/* $Cambridge: exim/src/src/log.c,v 1.15 2010/06/06 00:27:52 pdp Exp $ */
-
 /*************************************************
 *     Exim - an Internet mail transport agent    *
 *************************************************/
 
-/* Copyright (c) University of Cambridge 1995 - 2009 */
+/* Copyright (c) University of Cambridge 1995 - 2016 */
 /* See the file NOTICE for conditions of use and distribution. */
 
 /* Functions for writing log files. The code for maintaining datestamped
@@ -50,7 +48,77 @@ static int    logging_mode = LOG_MODE_FILE;
 static uschar *file_path = US"";
 
 
-
+/* These should be kept in-step with the private delivery error
+number definitions in macros.h */
+
+static const uschar * exim_errstrings[] = {
+  US"",
+  US"unknown error",
+  US"user slash",
+  US"exist race",
+  US"not regular",
+  US"not directory",
+  US"bad ugid",
+  US"bad mode",
+  US"inode changed",
+  US"lock failed",
+  US"bad address2",
+  US"forbid pipe",
+  US"forbid file",
+  US"forbid reply",
+  US"missing pipe",
+  US"missing file",
+  US"missing reply",
+  US"bad redirect",
+  US"smtp closed",
+  US"smtp format",
+  US"spool format",
+  US"not absolute",
+  US"Exim-imposed quota",
+  US"held",
+  US"Delivery filter process failure",
+  US"Delivery add/remove header failure",
+  US"Delivery write incomplete error",
+  US"Some expansion failed",
+  US"Failed to get gid",
+  US"Failed to get uid",
+  US"Unset or non-existent transport",
+  US"MBX length mismatch",
+  US"Lookup failed routing or in smtp tpt",
+  US"Can't match format in appendfile",
+  US"Creation outside home in appendfile",
+  US"Can't check a list; lookup defer",
+  US"DNS lookup defer",
+  US"Failed to start TLS session",
+  US"Mandatory TLS session not started",
+  US"Failed to chown a file",
+  US"Failed to create a pipe",
+  US"When verifying",
+  US"When required by client",
+  US"Used internally in smtp transport",
+  US"RCPT gave 4xx error",
+  US"MAIL gave 4xx error",
+  US"DATA gave 4xx error",
+  US"Negotiation failed for proxy configured host",
+  US"Authenticator 'other' failure",
+  US"target not supporting SMTPUTF8",
+  US"",
+
+  US"Not time for routing",
+  US"Not time for local delivery",
+  US"Not time for any remote host",
+  US"Local-only delivery",
+  US"Domain in queue_domains",
+  US"Transport concurrency limit",
+};
+
+
+/************************************************/
+const uschar *
+exim_errstr(int err)
+{
+return errno < 0 ? exim_errstrings[-err] : CUS strerror(err);
+}
 
 /*************************************************
 *              Write to syslog                   *
@@ -181,7 +249,7 @@ overwrite it temporarily if it is necessary to create the directory.
 Returns:       a file descriptor, or < 0 on failure (errno set)
 */
 
-static int
+int
 log_create(uschar *name)
 {
 int fd = Uopen(name, O_CREAT|O_APPEND|O_WRONLY, LOG_MODE);
@@ -435,6 +503,13 @@ log_write(0, LOG_PANIC_DIE, "Cannot open %s log file \"%s\": %s: "
 }
 
 
+static void
+unlink_log(int type)
+{
+if (type == lt_debug) unlink(CS debuglog_name);
+}
+
+
 
 /*************************************************
 *     Add configuration file info to log line    *
@@ -482,6 +557,11 @@ log, which can happen if a disk gets full or a file gets too large or whatever.
 We try to save the relevant message in the panic_save buffer before crashing
 out.
 
+The potential invoker should probably not call us for EINTR -1 writes.  But
+otherwise, short writes are bad as we don't do non-blocking writes to fds
+subject to flow control.  (If we do, that's new and the logic of this should
+be reconsidered).
+
 Arguments:
   name      the name of the log being written
   length    the string length being written
@@ -510,6 +590,66 @@ log_write(0, LOG_PANIC_DIE, "failed to write to %s: length=%d result=%d "
 
 
 
+/*************************************************
+*     Write to an fd, retrying after signals     *
+*************************************************/
+
+/* Basic write to fd for logs, handling EINTR.
+
+Arguments:
+  fd        the fd to write to
+  buf       the string to write
+  length    the string length being written
+
+Returns:
+  length actually written, persisting an errno from write()
+*/
+ssize_t
+write_to_fd_buf(int fd, const uschar *buf, size_t length)
+{
+ssize_t wrote;
+size_t total_written = 0;
+const uschar *p = buf;
+size_t left = length;
+
+while (1)
+  {
+  wrote = write(fd, p, left);
+  if (wrote == (ssize_t)-1)
+    {
+    if (errno == EINTR) continue;
+    return wrote;
+    }
+  total_written += wrote;
+  if (wrote == left)
+    break;
+  else
+    {
+    p += wrote;
+    left -= wrote;
+    }
+  }
+return total_written;
+}
+
+
+
+static void
+set_file_path(void)
+{
+int sep = ':';              /* Fixed separator - outside use */
+uschar *t;
+const uschar *tt = US LOG_FILE_PATH;
+while ((t = string_nextinlist(&tt, &sep, log_buffer, LOG_BUFFER_SIZE)))
+  {
+  if (Ustrcmp(t, "syslog") == 0 || t[0] == 0) continue;
+  file_path = string_copy(t);
+  break;
+  }
+}
+
+
+
 /*************************************************
 *            Write message to log file           *
 *************************************************/
@@ -550,7 +690,7 @@ If a message_id exists, we include it after the timestamp.
 
 Arguments:
   selector  write to main log or LOG_INFO only if this value is zero, or if
-              its bit is set in log_write_selector
+              its bit is set in log_selector[0]
   flags     each bit indicates some independent action:
               LOG_SENDER      add raw sender to the message
               LOG_RECIPIENTS  add raw recipients list to message
@@ -571,8 +711,9 @@ void
 log_write(unsigned int selector, int flags, const char *format, ...)
 {
 uschar *ptr;
-int length, rc;
+int length;
 int paniclogfd;
+ssize_t written_len;
 va_list ap;
 
 /* If panic_recurseflag is set, we have failed to open the panic log. This is
@@ -621,13 +762,13 @@ if (!path_inspected)
   /* If nothing has been set, don't waste effort... the default values for the
   statics are file_path="" and logging_mode = LOG_MODE_FILE. */
 
-  if (log_file_path[0] != 0)
+  if (*log_file_path)
     {
     int sep = ':';              /* Fixed separator - outside use */
     uschar *s;
-    uschar *ss = log_file_path;
+    const uschar *ss = log_file_path;
     logging_mode = 0;
-    while ((s = string_nextinlist(&ss,&sep,log_buffer,LOG_BUFFER_SIZE)) != NULL)
+    while ((s = string_nextinlist(&ss, &sep, log_buffer, LOG_BUFFER_SIZE)))
       {
       if (Ustrcmp(s, "syslog") == 0)
         logging_mode |= LOG_MODE_SYSLOG;
@@ -638,10 +779,8 @@ if (!path_inspected)
 
         /* If a non-empty path is given, use it */
 
-        if (s[0] != 0)
-          {
+        if (*s)
           file_path = string_copy(s);
-          }
 
         /* If the path is empty, we want to use the first non-empty, non-
         syslog item in LOG_FILE_PATH, if there is one, since the value of
@@ -649,17 +788,7 @@ if (!path_inspected)
         use the ultimate default in the spool directory. */
 
         else
-          {
-          uschar *t;
-          uschar *tt = US LOG_FILE_PATH;
-          while ((t = string_nextinlist(&tt,&sep,log_buffer,LOG_BUFFER_SIZE))
-                != NULL)
-            {
-            if (Ustrcmp(t, "syslog") == 0 || t[0] == 0) continue;
-            file_path = string_copy(t);
-            break;
-            }
-          }  /* Empty item in log_file_path */
+         set_file_path();  /* Empty item in log_file_path */
         }    /* First non-syslog item in log_file_path */
       }      /* Scan of log_file_path */
     }
@@ -682,10 +811,8 @@ if (!path_inspected)
   should work since we have now set up the routing. */
 
   if (multiple)
-    {
     log_write(0, LOG_MAIN|LOG_PANIC,
       "More than one path given in log_file_path: using %s", file_path);
-    }
   }
 
 /* If debugging, show all log entries, but don't show headers. Do it all
@@ -699,15 +826,12 @@ DEBUG(D_any|D_v)
   Ustrcpy(ptr, "LOG:");
   ptr += 4;
 
-  /* Show the options that were passed into the call. These are those whose
-  flag values do not have the 0x80000000 bit in them. Note that this
-  automatically exclude the "all" setting. */
+  /* Show the selector that was passed into the call. */
 
   for (i = 0; i < log_options_count; i++)
     {
-    unsigned int bit = log_options[i].bit;
-    if ((bit & 0x80000000) != 0) continue;
-    if ((selector & bit) != 0)
+    unsigned int bitnum = log_options[i].bit;
+    if (bitnum < BITWORDSIZE && selector == BIT(bitnum))
       {
       *ptr++ = ' ';
       Ustrcpy(ptr, log_options[i].name);
@@ -715,7 +839,7 @@ DEBUG(D_any|D_v)
       }
     }
 
-  sprintf(CS ptr, "%s%s%s%s%s\n  ",
+  sprintf(CS ptr, "%s%s%s%s\n  ",
     ((flags & LOG_MAIN) != 0)?    " MAIN"   : "",
     ((flags & LOG_PANIC) != 0)?   " PANIC"  : "",
     ((flags & LOG_PANIC_DIE) == LOG_PANIC_DIE)? " DIE" : "",
@@ -759,7 +883,7 @@ ptr = log_buffer;
 sprintf(CS ptr, "%s ", tod_stamp(tod_log));
 while(*ptr) ptr++;
 
-if ((log_extra_selector & LX_pid) != 0)
+if (LOGGING(pid))
   {
   sprintf(CS ptr, "[%d] ", (int)getpid());
   while (*ptr) ptr++;
@@ -819,7 +943,7 @@ or unless there is no log_stderr (expn called from daemon, for example). */
 if (!really_exim || log_testing_mode)
   {
   if (debug_selector == 0 && log_stderr != NULL &&
-      (selector == 0 || (selector & log_write_selector) != 0))
+      (selector == 0 || (selector & log_selector[0]) != 0))
     {
     if (host_checking)
       fprintf(log_stderr, "LOG: %s", CS(log_buffer + 20));  /* no timestamp */
@@ -837,7 +961,7 @@ has been renamed. Therefore, do a stat() and see if the inode has changed, and
 if so, re-open. */
 
 if ((flags & LOG_MAIN) != 0 &&
-    (selector == 0 || (selector & log_write_selector) != 0))
+    (selector == 0 || (selector & log_selector[0]) != 0))
   {
   if ((logging_mode & LOG_MODE_SYSLOG) != 0 &&
       (syslog_duplication || (flags & (LOG_REJECT|LOG_PANIC)) == 0))
@@ -888,9 +1012,10 @@ if ((flags & LOG_MAIN) != 0 &&
 
     /* Failing to write to the log is disastrous */
 
-    if ((rc = write(mainlogfd, log_buffer, length)) != length)
+    written_len = write_to_fd_buf(mainlogfd, log_buffer, length);
+    if (written_len != length)
       {
-      log_write_failed(US"main log", length, rc);
+      log_write_failed(US"main log", length, written_len);
       /* That function does not return */
       }
     }
@@ -905,7 +1030,7 @@ if ((flags & LOG_REJECT) != 0)
   {
   header_line *h;
 
-  if (header_list != NULL && (log_extra_selector & LX_rejected_header) != 0)
+  if (header_list != NULL && LOGGING(rejected_header))
     {
     if (recipients_count > 0)
       {
@@ -1010,9 +1135,10 @@ if ((flags & LOG_REJECT) != 0)
       if (fstat(rejectlogfd, &statbuf) >= 0) rejectlog_inode = statbuf.st_ino;
       }
 
-    if ((rc = write(rejectlogfd, log_buffer, length)) != length)
+    written_len = write_to_fd_buf(rejectlogfd, log_buffer, length);
+    if (written_len != length)
       {
-      log_write_failed(US"reject log", length, rc);
+      log_write_failed(US"reject log", length, written_len);
       /* That function does not return */
       }
     }
@@ -1044,14 +1170,18 @@ if ((flags & LOG_PANIC) != 0)
     panic_recurseflag = FALSE;
 
     if (panic_save_buffer != NULL)
-      (void) write(paniclogfd, panic_save_buffer, Ustrlen(panic_save_buffer));
+      {
+      int i = write(paniclogfd, panic_save_buffer, Ustrlen(panic_save_buffer));
+      i = i;   /* compiler quietening */
+      }
 
-    if ((rc = write(paniclogfd, log_buffer, length)) != length)
+    written_len = write_to_fd_buf(paniclogfd, log_buffer, length);
+    if (written_len != length)
       {
       int save_errno = errno;
       write_syslog(LOG_CRIT, log_buffer);
       sprintf(CS log_buffer, "write failed on panic log: length=%d result=%d "
-        "errno=%d (%s)", length, rc, save_errno, strerror(save_errno));
+        "errno=%d (%s)", length, (int)written_len, save_errno, strerror(save_errno));
       write_syslog(LOG_CRIT, log_buffer);
       flags |= LOG_PANIC_DIE;
       }
@@ -1085,6 +1215,35 @@ syslog_open = FALSE;
 
 
 
+/*************************************************
+*             Multi-bit set or clear             *
+*************************************************/
+
+/* These functions take a list of bit indexes (terminated by -1) and
+clear or set the corresponding bits in the selector.
+
+Arguments:
+  selector       address of the bit string
+  selsize        number of words in the bit string
+  bits           list of bits to set
+*/
+
+void
+bits_clear(unsigned int *selector, size_t selsize, int *bits)
+{
+for(; *bits != -1; ++bits)
+  BIT_CLEAR(selector, selsize, *bits);
+}
+
+void
+bits_set(unsigned int *selector, size_t selsize, int *bits)
+{
+for(; *bits != -1; ++bits)
+  BIT_SET(selector, selsize, *bits);
+}
+
+
+
 /*************************************************
 *         Decode bit settings for log/debug      *
 *************************************************/
@@ -1095,13 +1254,9 @@ also recognizes a numeric setting of the form =<number>, but this is not
 intended for user use. It's an easy way for Exim to pass the debug settings
 when it is re-exec'ed.
 
-The log options are held in two unsigned ints (because there became too many
-for one). The top bit in the table means "put in 2nd selector". This does not
-yet apply to debug options, so the "=" facility sets only the first selector.
-
-The "all" selector, which must be equal to 0xffffffff, is recognized specially.
-It sets all the bits in both selectors. However, there is a facility for then
-unsetting certain bits, because we want to turn off "memory" in the debug case.
+The option table is a list of names and bit indexes. The index -1
+means "set all bits, except for those listed in notall". The notall
+list is terminated by -1.
 
 The action taken for bad values varies depending upon why we're here.
 For log messages, or if the debugging is triggered from config, then we write
@@ -1109,10 +1264,9 @@ to the log on the way out.  For debug setting triggered from the command-line,
 we treat it as an unknown option: error message to stderr and die.
 
 Arguments:
-  selector1      address of the first bit string
-  selector2      address of the second bit string, or NULL
-  notall1        bits to exclude from "all" for selector1
-  notall2        bits to exclude from "all" for selector2
+  selector       address of the bit string
+  selsize        number of words in the bit string
+  notall         list of bits to exclude from "all"
   string         the configured string
   options        the table of option names
   count          size of table
@@ -1123,9 +1277,8 @@ Returns:         nothing on success - bomb out on failure
 */
 
 void
-decode_bits(unsigned int *selector1, unsigned int *selector2, int notall1,
-  int notall2, uschar *string, bit_table *options, int count, uschar *which,
-  int flags)
+decode_bits(unsigned int *selector, size_t selsize, int *notall,
+  uschar *string, bit_table *options, int count, uschar *which, int flags)
 {
 uschar *errmsg;
 if (string == NULL) return;
@@ -1133,7 +1286,8 @@ if (string == NULL) return;
 if (*string == '=')
   {
   char *end;    /* Not uschar */
-  *selector1 = strtoul(CS string+1, &end, 0);
+  memset(selector, 0, sizeof(*selector)*selsize);
+  *selector = strtoul(CS string+1, &end, 0);
   if (*end == 0) return;
   errmsg = string_sprintf("malformed numeric %s_selector setting: %s", which,
     string);
@@ -1176,40 +1330,22 @@ else for(;;)
       if (middle->name[len] != 0) c = -1; else
         {
         unsigned int bit = middle->bit;
-        unsigned int *selector;
-
-        /* The value with all bits set means "force all bits in both selectors"
-        in the case where two are being handled. However, the top bit in the
-        second selector is never set. When setting, some bits can be excluded.
-        */
-
-        if (bit == 0xffffffff)
-          {
-          if (adding)
-            {
-            *selector1 = 0xffffffff ^ notall1;
-            if (selector2 != NULL) *selector2 = 0x7fffffff ^ notall2;
-            }
-          else
-            {
-            *selector1 = 0;
-            if (selector2 != NULL) *selector2 = 0;
-            }
-          }
-
-        /* Otherwise, the 0x80000000 bit means "this value, without the top
-        bit, belongs in the second selector". */
 
-        else
-          {
-          if ((bit & 0x80000000) != 0)
-            {
-            selector = selector2;
-            bit &= 0x7fffffff;
-            }
-          else selector = selector1;
-          if (adding) *selector |= bit; else *selector &= ~bit;
-          }
+       if (bit == -1)
+         {
+         if (adding)
+           {
+           memset(selector, -1, sizeof(*selector)*selsize);
+           bits_clear(selector, selsize, notall);
+           }
+         else
+           memset(selector, 0, sizeof(*selector)*selsize);
+         }
+       else if (adding)
+         BIT_SET(selector, selsize, bit);
+       else
+         BIT_CLEAR(selector, selsize, bit);
+
         break;  /* Out of loop to match selector name */
         }
       }
@@ -1256,7 +1392,7 @@ misconfiguration.
 
 The first use of this is in ACL logic, "control = debug/tag=foo/opts=+expand"
 which can be combined with conditions, etc, to activate extra logging only
-for certain sources. */
+for certain sources. The second use is inetd wait mode debug preservation. */
 
 void
 debug_logging_activate(uschar *tag_name, uschar *opts)
@@ -1266,7 +1402,7 @@ int fd = -1;
 if (debug_file)
   {
   debug_printf("DEBUGGING ACTIVATED FROM WITHIN CONFIG.\n"
-      "DEBUG: Tag=\"%s\" Opts=\"%s\"\n", tag_name, opts);
+      "DEBUG: Tag=\"%s\" opts=\"%s\"\n", tag_name, opts ? opts : US"");
   return;
   }
 
@@ -1279,10 +1415,14 @@ if (tag_name != NULL && (Ustrchr(tag_name, '/') != NULL))
 
 debug_selector = D_default;
 if (opts)
-  {
-  decode_bits(&debug_selector, NULL, D_memory, 0, opts,
+  decode_bits(&debug_selector, 1, debug_notall, opts,
       debug_options, debug_options_count, US"debug", DEBUG_FROM_CONFIG);
-  }
+
+/* When activating from a transport process we may never have logged at all
+resulting in certain setup not having been done.  Hack this for now so we
+do not segfault; note that nondefault log locations will not work */
+
+if (!*file_path) set_file_path();
 
 open_log(&fd, lt_debug, tag_name);
 
@@ -1293,4 +1433,16 @@ else
 }
 
 
+void
+debug_logging_stop(void)
+{
+if (!debug_file || !debuglog_name[0]) return;
+
+debug_selector = 0;
+fclose(debug_file);
+debug_file = NULL;
+unlink_log(lt_debug);
+}
+
+
 /* End of log.c */