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

classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
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

Reply | Threaded
Open this post in threaded view
|

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

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.

        Wietse
Reply | Threaded
Open this post in threaded view
|

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

Wietse Venema
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();
  }
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
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.
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
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
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
In reply to this post by Wietse Venema
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);

Reply | Threaded
Open this post in threaded view
|

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

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.

        Wietse
Reply | Threaded
Open this post in threaded view
|

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

Wietse Venema
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
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
In reply to this post by Wietse Venema
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
Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
In reply to this post by Wietse Venema
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.
Reply | Threaded
Open this post in threaded view
|

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

Stan Hoeppner
In reply to this post by John Fawcett-4
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

Reply | Threaded
Open this post in threaded view
|

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

John Fawcett-4
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