qmail-checkspam.c: Add copious logging, particularly of envelopes.

This is a fair-sized rewrite of the existing code.  The main point is to
log the envelope sender and recipients in order to make tracking down
incorrect rejections easier.  Logging errors information about errors is
just good practice.

diff --git a/qmail-checkspam.c b/qmail-checkspam.c
index 7847769fd54c5a70b39da7fabb741d6612999e5d..b6595fa44f7243eb724ac803decd961fb40f7b37 100644 (file)
--- a/qmail-checkspam.c
+++ b/qmail-checkspam.c
@@ -36,6 +36,8 @@
 #include <sys/types.h>
 #include <sys/unistd.h>
 
+#include <syslog.h>
+
 #include <libspamc.h>
 
 /*----- Main code ---------------------------------------------------------*/
@@ -56,7 +58,10 @@ static double dblenv(const char *e, double d)
   if (!p) return (d);
   errno = 0;
   f = strtod(p, &q);
-  if (errno) return (d);
+  if (errno) {
+    syslog(LOG_ERR, "bad floating value `%s' for %s'; ignoring", p, e);
+    return (d);
+  }
   errno = err;
   return (f);
 }
@@ -72,89 +77,251 @@ static int intenv(const char *e, int d)
   l = strtol(p, &q, 0);
   if (errno) return (d);
   errno = err;
-  if (l < 0 || l > INT_MAX) return (d);
+  if (l < 0 || l > INT_MAX) {
+    syslog(LOG_ERR, "bad integer value `%s' for `%s'; ignoring", p, e);
+    return (d);
+  }
   return ((int)l);
 }
 
-int shovel(int from, int to)
+static int safewrite(int fd, const void *p, size_t sz)
+{
+  const char *pp = p;
+  ssize_t n;
+
+  while (sz > 0) {
+    n = write(fd, pp, sz);
+    if (sz <= 0 && errno != EINTR && errno != EAGAIN)
+      return (-1);
+    sz -= n;
+    pp += n;
+  }
+  return (0);
+}
+
+static int shovel(int from, int to, const char *what)
 {
   char buf[4096];
   ssize_t n;
-  char *p;
-  size_t r;
 
   for (;;) {
     n = read(from, buf, sizeof(buf));
-    if (n < 0 && errno != EINTR && errno != EAGAIN)
+    if (n < 0 && errno != EINTR && errno != EAGAIN) {
+      syslog(LOG_ERR, "failed to read %s: %m", what);
       return (-1);
+    }
     else if (!n)
       return (0);
-    p = buf;
-    r = n;
-    while (r) {
-      n = write(to, p, n);
-      if (n <= 0 && errno != EINTR && errno != EAGAIN)
-       return (-1);
-      r -= n;
-      p += n;
+    if (safewrite(to, buf, n) < 0) {
+      syslog(LOG_ERR, "failed to write %s: %m", what);
+      return (-1);
+    }
+  }
+}
+
+#define ENVBUF 4096
+#define NRCPT 16
+struct envelope {
+  unsigned f;
+#define EF_TRUNC 1u
+  char buf[ENVBUF + 1];
+  size_t n;
+  const char *send;
+  const char *rcpt[NRCPT];
+  size_t nrcpt;
+};
+
+static int readenv(struct envelope *e)
+{
+  ssize_t n;
+  const char *p, *l;
+
+  /* Read the raw envelope data. */
+  e->n = 0;
+  e->f = 0;
+  while (e->n < ENVBUF) {
+    n = read(1, e->buf + e->n, ENVBUF - e->n);
+    if (n < 0 && errno != EINTR && errno != EAGAIN) {
+      syslog(LOG_ERR, "failed to read envelope: %m");
+      return (-1);
     }
+    if (!n) break;
+    e->n += n;
+  }
+  e->buf[e->n] = 0;
+
+  /* Parse up the envelope data. */
+  p = e->buf; l = p + e->n;
+  e->nrcpt = 0;
+  if (*p++ != 'F') {
+    e->send = "<invalid>";
+    syslog(LOG_ERR, "corrupt envelope (no sender marker)");
+    return (-1);
+  }
+  e->send = p;
+  for (;;) {
+    if (p >= l) goto trunc;
+    else if (!*p++) break;
   }
+
+  for (;;) {
+    if (p >= l) goto trunc;
+    if (!*p) break;
+    else if (*p++ != 'T') {
+      syslog(LOG_ERR, "corrupt envelope (no recipient marker)");
+      return (-1);
+    }
+    if (p >= l) goto trunc;
+    if (e->nrcpt < NRCPT) e->rcpt[e->nrcpt++] = p;
+    for (;;) {
+      if (p >= l) goto trunc;
+      else if (!*p++) break;
+    }
+  }
+  return (0);
+
+  /* Failed to reach the final terminator; maybe there's more.  This isn't a
+   * very bad situation.
+   */
+trunc:
+  e->f |= EF_TRUNC;
+  return (0);
+}
+
+static void real(void)
+{
+  const char *qmq =
+    strenv("QMAIL_CHECKSPAM_QUEUE", "/var/qmail/bin/qmail-queue");
+  execlp(qmq, qmq, (char *)0);
+  syslog(LOG_ERR, "failed to exec %s: %m", qmq);
+  exit(56);
+}
+
+static int split(int *fd_m, int *fd_e)
+{
+  pid_t kid;
+  int pm[2], pe[2];
+
+  if (pipe(pm) || pipe(pe)) return (-1);
+  if ((kid = fork()) < 0) return (-1);
+  if (kid) {
+    dup2(pm[0], 0); close(pm[0]); close(pm[1]);
+    dup2(pe[0], 1); close(pe[0]); close(pe[1]);
+    real();
+  } else {
+    close(pm[0]); *fd_m = pm[1];
+    close(pe[0]); *fd_e = pe[1];
+  }
+  return (0);
+}
+
+static int writemsg(struct message *m, int fd_m, int shovelp)
+{
+  if (message_write(fd_m, m) < 0) {
+    syslog(LOG_ERR, "failed to write message body: %m");
+    return (-1);
+  }
+  if (shovelp && shovel(0, fd_m, "message body"))
+    return (-1);
+  close(fd_m);
+  return (0);
+}
+
+static int writeenv(struct envelope *e, int fd_e)
+{
+  if (safewrite(fd_e, e->buf, e->n) < 0) {
+    syslog(LOG_ERR, "failed to write envelope: %m");
+    return (-1);
+  }
+  if ((e->f & EF_TRUNC) && shovel(1, fd_e, "envelope"))
+    return (-1);
+  close(fd_e);
+  return (0);
+}
+
+static void logenv(struct envelope *e)
+{
+  size_t i;
+
+  syslog(LOG_NOTICE, "sender = %s", e->send);
+  for (i = 0; i < e->nrcpt; i++)
+    syslog(LOG_NOTICE, "recipient %lu = %s", (unsigned long)i, e->rcpt[i]);
 }
 
 int main(int argc, char *argv[])
 {
   struct sockaddr sa;
   struct message m;
-  int fd_m[2], fd_e[2];
-  pid_t kid;
-  const char *qmq;
-  int rc;
+  struct envelope e;
+  int fd_m, fd_e;
+  const char *p;
+  double thresh;
+  int rc, port;
+
+  /* Set up logging output. */
+  if ((p = strrchr(argv[0], '/')) == 0) p = argv[0]; else p++;
+  openlog(p, LOG_PID, LOG_MAIL);
 
-  if (getenv("RELAYCLIENT")) goto exec;
+  /* Read configuration from the environment. */
+  if (getenv("RELAYCLIENT")) real();
   m.max_len = intenv("QMAIL_CHECKSPAM_MAXLEN", 2 * 1024 * 1024);
   m.timeout = intenv("QMAIL_CHECKSPAM_TIMEOUT", 300);
+
+  /* Slurp an initial chunk of the message. */
   rc = message_read(0, 0, &m);
-  if (rc != 0 && rc != EX_TOOBIG)
-    return (54);
-  if (!rc) {
-    if (lookup_host(strenv("QMAIL_CHECKSPAM_SPAMDHOST", "localhost"),
-                   intenv("QMAIL_CHECKSPAM_SPAMDPORT", 783),
-                   &sa))
-      return (56);
-    if (message_filter(&sa, "spamd", 0, &m))
-      return (74);
-    if (m.score >= dblenv("QMAIL_CHECKSPAM_THRESH", m.threshold))
-      return (31);
-  }
-  if (pipe(fd_m) || pipe(fd_e))
-    return (56);
-  if ((kid = fork()) < 0)
-    return (56);
-  if (!kid) {
-    close(fd_m[0]);
-    close(fd_e[0]);
-    if (message_write(fd_m[1], &m) < 0)
-      _exit(127);
-    if (rc == EX_TOOBIG && shovel(0, fd_m[1]))
-      _exit(127);
-    close(fd_m[1]);
-    if (shovel(1, fd_e[1]))
-      _exit(127);
-    close(fd_e[1]);
-    _exit(0);
+
+  switch (rc) {
+
+    case 0:
+      /* We read the message body OK.  Now try to slurp in the envelope and
+       * write a useful message.
+       */
+      if (readenv(&e)) return (54);
+      syslog(LOG_NOTICE, "scanning message");
+      logenv(&e);
+
+      /* Filter the message and see what happens. */
+      p = strenv("QMAIL_CHECKSPAM_SPAMDHOST", "localhost");
+      port = intenv("QMAIL_CHECKSPAM_SPAMDPORT", 783);
+      if (lookup_host(p, port, &sa)) {
+       syslog(LOG_ERR, "lookup failed for host `%s', port %d", p, port);
+       return (56);
+      }
+      if (message_filter(&sa, "spamd", 0, &m)) {
+       syslog(LOG_ERR, "filter failed unexpectedly");
+       return (74);
+      }
+
+      /* Check the resulting score. */
+      thresh = dblenv("QMAIL_CHECKSPAM_THRESH", m.threshold);
+      if (m.score >= thresh) {
+       syslog(LOG_NOTICE, "rejecting: score %g >= %g", m.score, thresh);
+       return (31);
+      }
+      syslog(LOG_NOTICE, "accepting: score %g < %g", m.score, thresh);
+
+      /* Send the remaining stuff on to the real server. */
+      if (split(&fd_m, &fd_e)) return (56);
+      if (writemsg(&m, fd_m, 0) || writeenv(&e, fd_e)) _exit(127);
+      break;
+
+    case EX_TOOBIG:
+      /* Message was too big.  We must pass it all on to the real server
+       * before picking up the envelope.
+       */
+      syslog(LOG_NOTICE, "message too large for filtering");
+      if (split(&fd_m, &fd_e)) return (56);
+      if (writemsg(&m, fd_m, 1) || readenv(&e)) _exit(127);
+      logenv(&e);
+      if (writeenv(&e, fd_e)) _exit(127);
+      break;
+
+    default:
+      syslog(LOG_ERR, "failed to read message (rc = %d): %m", rc);
+      return (54);
   }
 
-  dup2(fd_m[0], 0);
-  dup2(fd_e[0], 1);
-  close(fd_m[0]);
-  close(fd_e[0]);
-  close(fd_m[1]);
-  close(fd_e[1]);
-exec:
-  qmq = strenv("QMAIL_CHECKSPAM_QUEUE", "/var/qmail/bin/qmail-queue");
-  execlp(qmq, qmq, (char *)0);
-  fprintf(stderr, "failed to exec: %s\n", strerror(errno));
-  return (56);
+  return (0);
 }
 
 /*----- That's all, folks -------------------------------------------------*/