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

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

Expand Messages
  • 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 following fail2ban
    Message 1 of 12 , Jun 28, 2013
    • 0 Attachment
      I use fail2ban in order to block some types of apparently malicious
      connections to postfix when the clients keep retrying. For example the
      following fail2ban regexes match cases I currently block by parsing the
      maillog.

      reject: RCPT from (.*)\[<HOST>\]: 554
      lost connection after AUTH from (.*)\[<HOST>\]\s*$
      reject: RCPT from (.*)\[<HOST>\]: 550 5.7.1 Client host rejected:
      cannot find your reverse hostname
      NOQUEUE: reject: RCPT from (.*)\[<HOST>\]:\d+: 550 5.7.1 Service
      unavailable; client \[\d+\.\d+\.\d+\.\d+\] blocked using

      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. I would prefer just to block them after that first 5 attempts
      or so.

      Only info I get is following emails to postmaster and connects and
      disconnects in the mail log.

      Transcript of session follows.

      Out: 220 mail.erba.tv ESMTP Postfix
      In: EHLO ATTACHE-SERVER
      Out: 250-mail.erba.tv
      Out: 250-PIPELINING
      Out: 250-SIZE 50000000
      Out: 250-ETRN
      Out: 250-STARTTLS
      Out: 250-ENHANCEDSTATUSCODES
      Out: 250-8BITMIME
      Out: 250 DSN
      In: AUTH LOGIN
      Out: 503 5.5.1 Error: authentication not enabled

      Session aborted, reason: lost connection

      For other details, see the local mail logfile

      Logfile
      Jun 28 09:04:37 rosalia postfix/postscreen[10170]: CONNECT from
      [202.136.109.205]:54626 to [80.237.194.64]:25
      Jun 28 09:04:43 rosalia postfix/postscreen[10170]: PASS NEW
      [202.136.109.205]:54626
      Jun 28 09:04:43 rosalia postfix/smtpd[10175]: connect from
      202-136-109-205.static.adam.com.au[202.136.109.205]
      Jun 28 09:04:47 rosalia postfix/smtpd[10175]: disconnect from
      202-136-109-205.static.adam.com.au[202.136.109.205]

      etc

      Would it be possible to have an option to log errors. Clearly this is
      not appropriate for all cases, since it can DDOS the maillog, but if
      turned on only when used in conjunction with fail2ban that would
      actually reduce connection load.

      One idea would be to make it configurable so it lists invalid commands
      to log (like AUTH when it's not allowed), so it could not write
      arbitrary strings to the maillog.

      An alternative idea would be to log disconnects differently if there was
      no email delivery email.

      Jun 28 09:04:47 rosalia postfix/smtpd[10175]: disconnect from
      202-136-109-205.static.adam.com.au[202.136.109.205] without mail

      John
    • Wietse Venema
      ... 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
      Message 2 of 12 , Jun 28, 2013
      • 0 Attachment
        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.

        Wietse
      • Wietse Venema
        ... 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
        Message 3 of 12 , Jun 28, 2013
        • 0 Attachment
          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();
          }
        • John Fawcett
          ... Thanks Wietse That looks like it will do it.
          Message 4 of 12 , Jun 28, 2013
          • 0 Attachment
            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 5 of 12 , Jun 28, 2013
            • 0 Attachment
              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 6 of 12 , Jun 30, 2013
              • 0 Attachment
                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 7 of 12 , Jun 30, 2013
                • 0 Attachment
                  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 8 of 12 , Jun 30, 2013
                  • 0 Attachment
                    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 9 of 12 , Jun 30, 2013
                    • 0 Attachment
                      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 10 of 12 , Jun 30, 2013
                      • 0 Attachment
                        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 11 of 12 , Jun 30, 2013
                        • 0 Attachment
                          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 12 of 12 , Jun 30, 2013
                          • 0 Attachment
                            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.