Loading ...
Sorry, an error occurred while loading the content.
 

Re: PATCH: Option to log clients that execute invalid commands or disconnect with no email delivery

Expand Messages
  • John Fawcett
    ... Thanks Wietse That looks like it will do it.
    Message 1 of 12 , Jun 28, 2013
      On 28/06/13 22:30, Wietse Venema wrote:
      > Wietse Venema:
      >> John Fawcett:
      >>> I use fail2ban in order to block some types of apparently malicious
      >>> connections to postfix when the clients keep retrying. For example the
      >> As you agree logging every failed command would not be safe by
      >> default.
      >>
      >> On the other hand, logging the command name (even without) parameters
      >> for every [45]XX response could be tricky. Adding IF statements all
      >> over the code is undesirable, so this would require a structural
      >> change to the command reader and responder.
      >>
      >> What about a one-line change, such that the SMTP server logs the
      >> existing per-session error counter when the connection is closed?
      >>
      >> This counter is reset upon successful completion of a (MAIL, RCPT,
      >> DATA, end-of-data) sequence. This should be sufficient to expose
      >> clients that hammer your server with unimplemented AUTH commands.
      > Example:
      >
      > Jun 28 16:27:25 spike postfix/smtpd[65532]: disconnect from camomile.cloud9.net[2604:8d00:0:1::3] error_count 0
      >
      > As per the patch below for any Postfix version ever released.
      >
      > Wietse
      >
      > *** ./src/smtpd/smtpd.c- Sun Jun 23 11:10:02 2013
      > --- ./src/smtpd/smtpd.c Fri Jun 28 16:26:41 2013
      > ***************
      > *** 4989,4995 ****
      > * After the client has gone away, clean up whatever we have set up at
      > * connection time.
      > */
      > ! msg_info("disconnect from %s", state.namaddr);
      > smtpd_state_reset(&state);
      > debug_peer_restore();
      > }
      > --- 4989,4996 ----
      > * After the client has gone away, clean up whatever we have set up at
      > * connection time.
      > */
      > ! msg_info("disconnect from %s error_count %d",
      > ! state.namaddr, state.error_count);
      > smtpd_state_reset(&state);
      > debug_peer_restore();
      > }
      Thanks Wietse
      That looks like it will do it.
    • John Fawcett
      ... I did some testing on this. For the record I added the following regex in fail2ban: disconnect from (.*) [ ] error_count [^0] Postfix is logging the
      Message 2 of 12 , Jun 28, 2013
        On 28/06/13 23:33, John Fawcett wrote:
        > On 28/06/13 22:30, Wietse Venema wrote:
        >> Wietse Venema:
        >>> John Fawcett:
        >>>> I use fail2ban in order to block some types of apparently malicious
        >>>> connections to postfix when the clients keep retrying. For example the
        >>> As you agree logging every failed command would not be safe by
        >>> default.
        >>>
        >>> On the other hand, logging the command name (even without) parameters
        >>> for every [45]XX response could be tricky. Adding IF statements all
        >>> over the code is undesirable, so this would require a structural
        >>> change to the command reader and responder.
        >>>
        >>> What about a one-line change, such that the SMTP server logs the
        >>> existing per-session error counter when the connection is closed?
        >>>
        >>> This counter is reset upon successful completion of a (MAIL, RCPT,
        >>> DATA, end-of-data) sequence. This should be sufficient to expose
        >>> clients that hammer your server with unimplemented AUTH commands.
        >> Example:
        >>
        >> Jun 28 16:27:25 spike postfix/smtpd[65532]: disconnect from camomile.cloud9.net[2604:8d00:0:1::3] error_count 0
        >>
        >> As per the patch below for any Postfix version ever released.
        >>
        >> Wietse
        >>
        >> *** ./src/smtpd/smtpd.c- Sun Jun 23 11:10:02 2013
        >> --- ./src/smtpd/smtpd.c Fri Jun 28 16:26:41 2013
        >> ***************
        >> *** 4989,4995 ****
        >> * After the client has gone away, clean up whatever we have set up at
        >> * connection time.
        >> */
        >> ! msg_info("disconnect from %s", state.namaddr);
        >> smtpd_state_reset(&state);
        >> debug_peer_restore();
        >> }
        >> --- 4989,4996 ----
        >> * After the client has gone away, clean up whatever we have set up at
        >> * connection time.
        >> */
        >> ! msg_info("disconnect from %s error_count %d",
        >> ! state.namaddr, state.error_count);
        >> smtpd_state_reset(&state);
        >> debug_peer_restore();
        >> }
        > Thanks Wietse
        > That looks like it will do it.
        I did some testing on this. For the record I added the following regex
        in fail2ban:

        disconnect from (.*)\[<HOST>\] error_count [^0]

        Postfix is logging the errors and fail2ban is firing.

        I have to admit my own error though. While I was checking this I found
        some log lines further down which I had overlooked before.

        Jun 28 09:04:52 rosalia postfix/smtpd[10175]: lost connection after AUTH
        from 202-136-109-205.static.adam.com.au[202.136.109.205]

        So seems the "attack" came in two different stages, one where there were
        just connects and disconnects and then another where there were connects
        AUTH and disconencts. I mismatched the evidence from the two stages. Sorry.

        The "lost connection after AUTH" would have been more than adequate to
        do the blocking in the case of disallowed AUTH commands. Actually now I
        have to find why fail2ban didn't pick them up, but that's OT.

        Thanks
        John
      • John Fawcett
        ... I would like to propose the following addition. As well as logging error_count as per the original patch, it also logs the number of messages accepted
        Message 3 of 12 , Jun 30, 2013
          On 28/06/13 22:30, Wietse Venema wrote:
          > Wietse Venema:
          >> John Fawcett:
          >>> I use fail2ban in order to block some types of apparently malicious
          >>> connections to postfix when the clients keep retrying. For example the
          >> As you agree logging every failed command would not be safe by
          >> default.
          >>
          >> On the other hand, logging the command name (even without) parameters
          >> for every [45]XX response could be tricky. Adding IF statements all
          >> over the code is undesirable, so this would require a structural
          >> change to the command reader and responder.
          >>
          >> What about a one-line change, such that the SMTP server logs the
          >> existing per-session error counter when the connection is closed?
          >>
          >> This counter is reset upon successful completion of a (MAIL, RCPT,
          >> DATA, end-of-data) sequence. This should be sufficient to expose
          >> clients that hammer your server with unimplemented AUTH commands.
          > Example:
          >
          > Jun 28 16:27:25 spike postfix/smtpd[65532]: disconnect from camomile.cloud9.net[2604:8d00:0:1::3] error_count 0
          >
          > As per the patch below for any Postfix version ever released.
          >
          > Wietse
          >
          > *** ./src/smtpd/smtpd.c- Sun Jun 23 11:10:02 2013
          > --- ./src/smtpd/smtpd.c Fri Jun 28 16:26:41 2013
          > ***************
          > *** 4989,4995 ****
          > * After the client has gone away, clean up whatever we have set up at
          > * connection time.
          > */
          > ! msg_info("disconnect from %s", state.namaddr);
          > smtpd_state_reset(&state);
          > debug_peer_restore();
          > }
          > --- 4989,4996 ----
          > * After the client has gone away, clean up whatever we have set up at
          > * connection time.
          > */
          > ! msg_info("disconnect from %s error_count %d",
          > ! state.namaddr, state.error_count);
          > smtpd_state_reset(&state);
          > debug_peer_restore();
          > }
          I would like to propose the following addition. As well as logging
          error_count as per the original patch, it also logs the number of
          messages accepted during the smtp session. The aim of that would be to
          identify clients that repeatedly connect and never attempt delivery.

          diff -ur postfix-2.11-20130623/src/smtpd/smtpd.c
          postfix-2.11-20130623-patch/src/smtpd/smtpd.c
          --- postfix-2.11-20130623/src/smtpd/smtpd.c 2013-06-23
          17:10:02.000000000 +0200
          +++ postfix-2.11-20130623-patch/src/smtpd/smtpd.c 2013-07-01
          01:36:19.000000000 +0200
          @@ -3239,9 +3239,11 @@
          state->junk_cmds = 0;
          if (proxy)
          smtpd_chat_reply(state, "%s", STR(proxy->buffer));
          - else
          + else {
          smtpd_chat_reply(state,
          "250 2.0.0 Ok: queued as %s", state->queue_id);
          + state->msg_count++;
          + }
          } else if (why && IS_SMTP_REJECT(STR(why))) {
          state->error_mask |= MAIL_ERROR_POLICY;
          smtpd_chat_reply(state, "%s", STR(why));
          @@ -4989,7 +4991,8 @@
          * 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 error_count %d msg_count %d",
          + state.namaddr, state.error_count,state.msg_count);
          smtpd_state_reset(&state);
          debug_peer_restore();
          }
          diff -ur postfix-2.11-20130623/src/smtpd/smtpd.h
          postfix-2.11-20130623-patch/src/smtpd/smtpd.h
          --- postfix-2.11-20130623/src/smtpd/smtpd.h 2012-07-30
          17:53:16.000000000 +0200
          +++ postfix-2.11-20130623-patch/src/smtpd/smtpd.h 2013-07-01
          01:35:40.000000000 +0200
          @@ -87,6 +87,7 @@
          int conn_count; /* connections from this
          client */
          int conn_rate; /* connection rate for this
          client */
          int error_count; /* reset after DOT */
          + int msg_count; /* message count */
          int error_mask; /* client errors */
          int notify_mask; /* what to report to postmaster */
          char *helo_name; /* client HELO/EHLO argument */
          diff -ur postfix-2.11-20130623/src/smtpd/smtpd_state.c
          postfix-2.11-20130623-patch/src/smtpd/smtpd_state.c
          --- postfix-2.11-20130623/src/smtpd/smtpd_state.c 2012-01-15
          00:13:42.000000000 +0100
          +++ postfix-2.11-20130623-patch/src/smtpd/smtpd_state.c 2013-07-01
          01:35:59.000000000 +0200
          @@ -86,6 +86,7 @@
          state->addr_buf = vstring_alloc(100);
          state->conn_count = state->conn_rate = 0;
          state->error_count = 0;
          + state->msg_count = 0;
          state->error_mask = 0;
          state->notify_mask = name_mask(VAR_NOTIFY_CLASSES, mail_error_masks,
          var_notify_classes);
        • Wietse Venema
          ... Why do you even care? Remember, when the client sends no mail, then the error count reflects all rejected commands in the entire session. I don t think it
          Message 4 of 12 , Jun 30, 2013
            John Fawcett:
            > I would like to propose the following addition. As well as logging
            > error_count as per the original patch, it also logs the number of
            > messages accepted during the smtp session. The aim of that would be to
            > identify clients that repeatedly connect and never attempt delivery.

            Why do you even care? Remember, when the client sends no mail, then
            the error count reflects all rejected commands in the entire session.

            I don't think it is a good idea to expose random pieces of SMTP
            engine internals.

            Wietse
          • Wietse Venema
            ... On the subject of sending commands without sending mail, a related counter is the junk command counter that is incremented with each HELO, EHLO, RSET,
            Message 5 of 12 , Jun 30, 2013
              Wietse Venema:
              > John Fawcett:
              > > I would like to propose the following addition. As well as logging
              > > error_count as per the original patch, it also logs the number of
              > > messages accepted during the smtp session. The aim of that would be to
              > > identify clients that repeatedly connect and never attempt delivery.
              >
              > Why do you even care? Remember, when the client sends no mail, then
              > the error count reflects all rejected commands in the entire session.
              >
              > I don't think it is a good idea to expose random pieces of SMTP
              > engine internals.

              On the subject of sending commands without sending mail, a related
              counter is the "junk" command counter that is incremented with each
              HELO, EHLO, RSET, NOOP, VRFY, ETRN command (any command that can
              be repeated indefinitely without triggering an error response).

              Like the error counter, this counter has a limit, and it
              is reset after a successful mail delivery transaction.

              Wietse
            • John Fawcett
              ... Due to another failure of fail2ban (hopefully now solved) I had the chance to analyze another spambot attempt like the one that prompted my original post,
              Message 6 of 12 , Jun 30, 2013
                On 01/07/13 02:18, Wietse Venema wrote:
                > John Fawcett:
                >> I would like to propose the following addition. As well as logging
                >> error_count as per the original patch, it also logs the number of
                >> messages accepted during the smtp session. The aim of that would be to
                >> identify clients that repeatedly connect and never attempt delivery.
                > Why do you even care? Remember, when the client sends no mail, then
                > the error count reflects all rejected commands in the entire session.
                >
                > I don't think it is a good idea to expose random pieces of SMTP
                > engine internals.
                >
                > Wietse
                Due to another failure of fail2ban (hopefully now solved) I had
                the chance to analyze another spambot attempt like the one that
                prompted my original post, this time 580 connections in 5 minutes.

                Although inexplicable to me, seems like the attack started off
                by connecting and disconnecting without sending any commands,
                so with an error_count of 0. This continued even when the
                concurrency limit was reached.

                Then from the 16th attempt the bot actually started sending
                AUTH commands.

                My idea was to detect the first attempts and block earlier, though
                there is not much difference in it.

                Another idea is to parse the log for repeated concurrency
                limit (smtpd_client_connection_count_limit) being reached in a small
                timeframe. That is already available in the log, though was
                probably triggered in this case because I have changed it from
                the default.

                John
              • John Fawcett
                ... I ll investigate using that since it would be non zero if mail was not delivered and zero if it was.
                Message 7 of 12 , Jun 30, 2013
                  On 01/07/13 02:59, Wietse Venema wrote:
                  > Wietse Venema:
                  >> John Fawcett:
                  >>> I would like to propose the following addition. As well as logging
                  >>> error_count as per the original patch, it also logs the number of
                  >>> messages accepted during the smtp session. The aim of that would be to
                  >>> identify clients that repeatedly connect and never attempt delivery.
                  >> Why do you even care? Remember, when the client sends no mail, then
                  >> the error count reflects all rejected commands in the entire session.
                  >>
                  >> I don't think it is a good idea to expose random pieces of SMTP
                  >> engine internals.
                  > On the subject of sending commands without sending mail, a related
                  > counter is the "junk" command counter that is incremented with each
                  > HELO, EHLO, RSET, NOOP, VRFY, ETRN command (any command that can
                  > be repeated indefinitely without triggering an error response).
                  >
                  > Like the error counter, this counter has a limit, and it
                  > is reset after a successful mail delivery transaction.
                  >
                  > Wietse
                  I'll investigate using that since it would be non zero if mail was
                  not delivered and zero if it was.
                • Stan Hoeppner
                  ... In a span of 26 minutes on June 9th I got hit with parallel connections of this AUTH bot junk, totaling over 5,100, from a hacked Argentinian MX server.
                  Message 8 of 12 , Jun 30, 2013
                    On 6/28/2013 12:31 PM, John Fawcett wrote:

                    > One type of connection which I cannot block in fail2ban are clients that
                    > try the AUTH command on port 25, where I have disabled it. I got 245
                    > connections this morning in the space of 5 minutes and those are the
                    > ones that got through despite the connection concurrency limit being hit
                    > 277 times.

                    In a span of 26 minutes on June 9th I got hit with parallel connections
                    of this "AUTH bot" junk, totaling over 5,100, from a hacked Argentinian
                    MX server. This with a concurrency limit of 4. That's just over 3
                    connections/second. Above you show less than 1 connect per second.

                    ~$ zgrep " connect " /var/log/mail.log.3|grep -c 190.210.114.210
                    5116

                    ~$ zgrep "concurrency limit" /var/log/mail.log.3|grep -c 190.210.114.210
                    3755

                    Jun 9 11:01:17 greer postfix/smtpd[30422]: warning: Connection
                    concurrency limit exceeded: 5 from mail.cqr.com.ar[190.210.114.210] for
                    service smtp
                    .....
                    Jun 9 11:27:43 greer postfix/smtpd[30525]: warning: Connection
                    concurrency limit exceeded: 5 from mail.cqr.com.ar[190.210.114.210] for
                    service smtp

                    None were rejected. The client disconnected each time.

                    ~$ zgrep reject /var/log/mail.log.3|grep -c 190.210.114.210
                    0

                    ~$ zgrep AUTH /var/log/mail.log.3|grep -c 190.210.114.210
                    1360

                    Looks like Anvil was responsible for the bulk of the disconnects.

                    Anvil did its job preventing a DOS condition on smtpd. Even if these
                    had progressed far enough to be rejected they'd still have not put
                    significant load on the server.

                    Thus the sum total negative impact of this attack on my MX is a bloated
                    log. For me, personally, it's not worth the hassle to implement
                    fail2ban simply to keep the log tidy.

                    In your case John are you suffering anything more than a bloated log?
                    Is one extra connect/second causing problems?

                    --
                    Stan
                  • John Fawcett
                    ... I installed fail2ban more out of concerns for security across a number of services primarily sshd, but then extended to others including postfix. I then
                    Message 9 of 12 , Jun 30, 2013
                      On 01/07/13 04:30, Stan Hoeppner wrote:
                      > On 6/28/2013 12:31 PM, John Fawcett wrote:
                      >
                      >> One type of connection which I cannot block in fail2ban are clients that
                      >> try the AUTH command on port 25, where I have disabled it. I got 245
                      >> connections this morning in the space of 5 minutes and those are the
                      >> ones that got through despite the connection concurrency limit being hit
                      >> 277 times.
                      >
                      > Anvil did its job preventing a DOS condition on smtpd. Even if these
                      > had progressed far enough to be rejected they'd still have not put
                      > significant load on the server.
                      >
                      > Thus the sum total negative impact of this attack on my MX is a bloated
                      > log. For me, personally, it's not worth the hassle to implement
                      > fail2ban simply to keep the log tidy.
                      >
                      > In your case John are you suffering anything more than a bloated log?
                      > Is one extra connect/second causing problems?
                      >

                      I installed fail2ban more out of concerns for security across a
                      number of services primarily sshd, but then extended to
                      others including postfix.

                      I then became interested in using it to block people hammering
                      the server. I am not sure how much hammering it actual stops
                      since I don't generally see it Only a failure of fail2ban in this
                      case enabled me to investigate further.

                      The additional connection load in this case is probably
                      irrelevant, however I still prefer to block because there is
                      no guarantee that spambots will stay within acceptable
                      limits and I prefer to be cautious.

                      John
                    Your message has been successfully submitted and would be delivered to recipients shortly.