postfix-2.12-20140801

diff --git a/postfix/HISTORY b/postfix/HISTORY
index bbd440f0ad15ce773f38c29f089505e7673f2701..9b28f52bb5f1cb4ffede5bae2dfad31d8f2c9545 100644 (file)
--- a/postfix/HISTORY
+++ b/postfix/HISTORY
@@ -20315,3 +20315,10 @@ Apologies for any names omitted.
        that was originally part of the RELEASE_NOTES file. Files:
        proto/SMTPUTF8_README.html, proto/Makefile.in, html/index.html.
 
+20140731
+
+       Feature: the Postfix SMTP server now logs at the end of
+       a session how many times each SMTP command was successfully
+       invoked, followed by the total number of invocations if it
+       is different.  File: smtpd/smtpd.c.
+       

diff --git a/postfix/RELEASE_NOTES b/postfix/RELEASE_NOTES
index e8adebce96b94b0ba5345ba91d4e47f02c18d804..c49daae86a2bee7132f9e82b5d825c4bed8e6818 100644 (file)
--- a/postfix/RELEASE_NOTES
+++ b/postfix/RELEASE_NOTES
@@ -41,6 +41,37 @@ Maintainers may also benefit from the makedefs documentation
 (mantools/srctoman - makedefs | nroff -man | less) with information
 about build options that are not described in the INSTALL instructions.
 
+Major changes with snapshot 20140801
+====================================
+
+The Postfix SMTP server now logs at the end of a session how many
+times an SMTP command was successfully invoked, followed by the
+total number of invocations if it is different.
+
+This logging will often be enough to diagnose a problem without
+verbose logging or network sniffer.
+
+    Normal session, no TLS:
+       disconnect from name[addr] ehlo=1 mail=1 rcpt=1 data=1 quit=1
+
+    Normal session. with TLS:
+       disconnect from name[addr] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1
+
+    All recipients rejected, no ESMTP command pipelining:
+       disconnect from name[addr] ehlo=1 mail=1 rcpt=0/1 quit=1
+
+    All recipients rejected, with ESMTP command pipelining:
+       disconnect from name[addr] ehlo=1 mail=1 rcpt=0/1 data=0/1 rset=1 quit=1
+
+    Password guessing bot, hangs up without QUIT:
+       disconnect from name[addr] ehlo=1 auth=0/1
+
+    Mis-configured client trying to use TLS wrappermode on port 587:
+       disconnect from name[addr] unknown=0/1
+
+Logfile analyzers can trigger on the presence of "/". It indicates
+that Postfix rejected at least one command.
+
 Incompatible changes with snapshot 20140714
 ===========================================
 

diff --git a/postfix/src/global/mail_version.h b/postfix/src/global/mail_version.h
index 596b58ee1e925eb6c55e445dd398c032e4a438e0..c2a8dc3602aeb16ffe6a4f268784a3e5844ab5ae 100644 (file)
--- a/postfix/src/global/mail_version.h
+++ b/postfix/src/global/mail_version.h
@@ -20,7 +20,7 @@
   * Patches change both the patchlevel and the release date. Snapshots have no
   * patchlevel; they change the release date only.
   */
-#define MAIL_RELEASE_DATE      "20140731"
+#define MAIL_RELEASE_DATE      "20140801"
 #define MAIL_VERSION_NUMBER    "2.12"
 
 #ifdef SNAPSHOT

diff --git a/postfix/src/smtpd/smtpd.c b/postfix/src/smtpd/smtpd.c
index 8e24768d35958136a3934e20e62ff5c2b084c58a..ba9e7768208bbb73d99b5f1e869520e0accb8781 100644 (file)
--- a/postfix/src/smtpd/smtpd.c
+++ b/postfix/src/smtpd/smtpd.c
@@ -4597,6 +4597,8 @@ typedef struct SMTPD_CMD {
     char   *name;
     int     (*action) (SMTPD_STATE *, int, SMTPD_TOKEN *);
     int     flags;
+    int     success_count;
+    int     total_count;
 } SMTPD_CMD;
 
 #define SMTPD_CMD_FLAG_LIMIT   (1<<0)  /* limit usage */
@@ -4604,25 +4606,25 @@ typedef struct SMTPD_CMD {
 #define SMTPD_CMD_FLAG_LAST    (1<<2)  /* last in PIPELINING command group */
 
 static SMTPD_CMD smtpd_cmd_table[] = {
-    SMTPD_CMD_HELO, helo_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,
-    SMTPD_CMD_EHLO, ehlo_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,
+    {SMTPD_CMD_HELO, helo_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,},
+    {SMTPD_CMD_EHLO, ehlo_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,},
+    {SMTPD_CMD_XCLIENT, xclient_cmd,},
+    {SMTPD_CMD_XFORWARD, xforward_cmd,},
 #ifdef USE_TLS
-    SMTPD_CMD_STARTTLS, starttls_cmd, SMTPD_CMD_FLAG_PRE_TLS,
+    {SMTPD_CMD_STARTTLS, starttls_cmd, SMTPD_CMD_FLAG_PRE_TLS,},
 #endif
 #ifdef USE_SASL_AUTH
-    SMTPD_CMD_AUTH, smtpd_sasl_auth_cmd, 0,
+    {SMTPD_CMD_AUTH, smtpd_sasl_auth_cmd,},
 #endif
-    SMTPD_CMD_MAIL, mail_cmd, 0,
-    SMTPD_CMD_RCPT, rcpt_cmd, 0,
-    SMTPD_CMD_DATA, data_cmd, SMTPD_CMD_FLAG_LAST,
-    SMTPD_CMD_RSET, rset_cmd, SMTPD_CMD_FLAG_LIMIT,
-    SMTPD_CMD_NOOP, noop_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,
-    SMTPD_CMD_VRFY, vrfy_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_LAST,
-    SMTPD_CMD_ETRN, etrn_cmd, SMTPD_CMD_FLAG_LIMIT,
-    SMTPD_CMD_QUIT, quit_cmd, SMTPD_CMD_FLAG_PRE_TLS,
-    SMTPD_CMD_XCLIENT, xclient_cmd, 0,
-    SMTPD_CMD_XFORWARD, xforward_cmd, 0,
-    0,
+    {SMTPD_CMD_MAIL, mail_cmd,},
+    {SMTPD_CMD_RCPT, rcpt_cmd,},
+    {SMTPD_CMD_DATA, data_cmd, SMTPD_CMD_FLAG_LAST,},
+    {SMTPD_CMD_RSET, rset_cmd, SMTPD_CMD_FLAG_LIMIT,},
+    {SMTPD_CMD_NOOP, noop_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_PRE_TLS | SMTPD_CMD_FLAG_LAST,},
+    {SMTPD_CMD_VRFY, vrfy_cmd, SMTPD_CMD_FLAG_LIMIT | SMTPD_CMD_FLAG_LAST,},
+    {SMTPD_CMD_ETRN, etrn_cmd, SMTPD_CMD_FLAG_LIMIT,},
+    {SMTPD_CMD_QUIT, quit_cmd, SMTPD_CMD_FLAG_PRE_TLS,},
+    {0,},
 };
 
 static STRING_LIST *smtpd_noop_cmds;
@@ -4868,6 +4870,18 @@ static void smtpd_proto(SMTPD_STATE *state)
                                var_smtpd_sasl_opts);
 #endif
 
+       /*
+        * Reset the per-command counters.
+        */
+       for (cmdp = smtpd_cmd_table; /* see below */ ; cmdp++) {
+           cmdp->success_count = cmdp->total_count = 0;
+           if (cmdp->name == 0)
+               break;
+       }
+
+       /*
+        * The command read/execute loop.
+        */
        for (;;) {
            if (state->flags & SMTPD_FLAG_HANGUP)
                break;
@@ -4912,6 +4926,7 @@ static void smtpd_proto(SMTPD_STATE *state)
            for (cmdp = smtpd_cmd_table; cmdp->name != 0; cmdp++)
                if (strcasecmp(argv[0].strval, cmdp->name) == 0)
                    break;
+           cmdp->total_count += 1;
            /* Ignore smtpd_forbid_cmds lookup errors. Non-critical feature. */
            if (cmdp->name == 0) {
                state->where = SMTPD_CMD_UNKNOWN;
@@ -4978,6 +4993,8 @@ static void smtpd_proto(SMTPD_STATE *state)
            }
            if (cmdp->action(state, argc, argv) != 0)
                state->error_count++;
+           else
+               cmdp->success_count += 1;
            if ((cmdp->flags & SMTPD_CMD_FLAG_LIMIT)
                && state->junk_cmds++ > var_smtpd_junk_cmd_limit)
                state->error_count++;
@@ -5047,6 +5064,28 @@ static void smtpd_proto(SMTPD_STATE *state)
        milter_disc_event(smtpd_milters);
 }
 
+/* smtpd_format_cmd_stats - format per-command statistics */
+
+static char *smtpd_format_cmd_stats(VSTRING *buf)
+{
+    SMTPD_CMD *cmdp;
+
+    VSTRING_RESET(buf);
+    for (cmdp = smtpd_cmd_table; /* see below */ ; cmdp++) {
+       if (cmdp->total_count > 0) {
+           vstring_sprintf_append(buf, " %s=%d",
+                                  cmdp->name ? cmdp->name : "unknown",
+                                  cmdp->success_count);
+           if (cmdp->success_count != cmdp->total_count)
+               vstring_sprintf_append(buf, "/%d", cmdp->total_count);
+       }
+       if (cmdp->name == 0)
+           break;
+    }
+    return (lowercase(STR(buf)));
+}
+
+
 /* smtpd_service - service one client */
 
 static void smtpd_service(VSTREAM *stream, char *service, char **argv)
@@ -5117,7 +5156,8 @@ static void smtpd_service(VSTREAM *stream, char *service, char **argv)
      * After the client has gone away, clean up whatever we have set up at
      * connection time.
      */
-    msg_info("disconnect from %s", state.namaddr);
+    msg_info("disconnect from %s%s", state.namaddr,
+            smtpd_format_cmd_stats(state.buffer));
     smtpd_state_reset(&state);
     debug_peer_restore();
 }