Simple (attempted) AUTH logging?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

Simple (attempted) AUTH logging?

James
Very low priority question here...

I don't announce or accept AUTH on my public port 25 postfix smtpd service, before or after STARTTLS, yet there is always a constant trickle of probes that do attempt it.

On rare occasions, there are days-long concerted efforts from a wide array of source addresses.

It would be nice to have a little bit of simple logging for these (failed/rejected) AUTH attempts.

Basically, it would be nice to be able to quickly decide between "oh yeah, of course that's hopeless, ignore it" and "hmmm, that looks disturbing, I'd better dig into what's going on there".

I don't see any postfix config options related to this sort of thing.  (Well, almost, but smtpd_sasl_authenticated_header doesn't do any good in this situation.)

Am I missing something?

Thanks.

  - James
Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Noel Jones-2
On 2/24/2017 1:05 PM, James wrote:

> Very low priority question here...
>
> I don't announce or accept AUTH on my public port 25 postfix smtpd
> service, before or after STARTTLS, yet there is always a constant
> trickle of probes that do attempt it.
>
> On rare occasions, there are days-long concerted efforts from a wide
> array of source addresses.
>
> It would be nice to have a little bit of simple logging for these
> (failed/rejected) AUTH attempts.
>
> Basically, it would be nice to be able to quickly decide between "oh
> yeah, of course that's hopeless, ignore it" and "hmmm, that looks
> disturbing, I'd better dig into what's going on there".
>
> I don't see any postfix config options related to this sort of
> thing.  (Well, almost, but smtpd_sasl_authenticated_header doesn't
> do any good in this situation.)
>
> Am I missing something?
>
> Thanks.
>
>  - James


Current versions of postfix will log that AUTH was attempted, but do
not log what the client sends.  You can grep the logs for 'auth=0'
to see unsuccessful auth attempts.

postfix/smtpd[58629]: disconnect from unknown[192.168.0.33] ehlo=1
auth=0/1 commands=1/2



  -- Noel Jones
Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

James
> Current versions of postfix will log that AUTH was attempted, but do
> not log what the client sends.  You can grep the logs for 'auth=0'
> to see unsuccessful auth attempts.
>
> postfix/smtpd[58629]: disconnect from unknown[192.168.0.33] ehlo=1
> auth=0/1 commands=1/2
>
>   -- Noel Jones

Yes, that's exactly what I have, hence my comments about seeing it happening.

I have a few entries in my bash history that I call up a few times a day to pull "interesting" lines from several logs.

I was hoping there might be some setting that would cause log entries like:

postfix/smtpd[12345]: NOQUEUE: AUTH rejected from client.example.com[0.1.2.3], sasl_method=PLAIN, sasl_username=spam_r_us

As long as the sasl_username was obviously hopeless then I wouldn't worry... but if they started using something that I thought they shouldn't know about then I'd start getting worried.

If no such setting exists then how many folks would consider it to be a reasonable feature request?

  - James

Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Noel Jones-2
On 2/24/2017 5:55 PM, James wrote:

>> Current versions of postfix will log that AUTH was attempted, but do
>> not log what the client sends.  You can grep the logs for 'auth=0'
>> to see unsuccessful auth attempts.
>>
>> postfix/smtpd[58629]: disconnect from unknown[192.168.0.33] ehlo=1
>> auth=0/1 commands=1/2
>>
>>   -- Noel Jones
>
> Yes, that's exactly what I have, hence my comments about seeing it
> happening.
>
> I have a few entries in my bash history that I call up a few times a
> day to pull "interesting" lines from several logs.
>
> I was hoping there might be some setting that would cause log
> entries like:
>
> postfix/smtpd[12345]: NOQUEUE: AUTH rejected from
> client.example.com[0.1.2.3], sasl_method=PLAIN, sasl_username=spam_r_us
>
> As long as the sasl_username was obviously hopeless then I wouldn't
> worry... but if they started using something that I thought they
> shouldn't know about then I'd start getting worried.
>
> If no such setting exists then how many folks would consider it to
> be a reasonable feature request?
>
>  - James
>


I'm pretty sure the sasl_username part of the log (and probably the
method too) is supplied by the sasl library, which is never called
when sasl isn't offered.

When sasl isn't offered but the client sends AUTH anyway, it should
be possible for postfix to log the (sanitized) AUTH command the
client sends, but it will be encoded.  The encoding as recorded in
the log may be (I think likely) broken by the log sanitizer.

My impression is this won't be as useful as you hope. Or my analysis
could be flawed.

Maybe Wietse or others has something to add.



  -- Noel Jones
Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Dominic Raferd
On 25/02/2017 05:28, Noel Jones wrote:

> On 2/24/2017 5:55 PM, James wrote:
>>> Current versions of postfix will log that AUTH was attempted, but do
>>> not log what the client sends.  You can grep the logs for 'auth=0'
>>> to see unsuccessful auth attempts.
>>>
>>> postfix/smtpd[58629]: disconnect from unknown[192.168.0.33] ehlo=1
>>> auth=0/1 commands=1/2
>>>
>>>    -- Noel Jones
>> I was hoping there might be some setting that would cause log
>> entries like:
>>
>> postfix/smtpd[12345]: NOQUEUE: AUTH rejected from
>> client.example.com[0.1.2.3], sasl_method=PLAIN, sasl_username=spam_r_us
>>
>> As long as the sasl_username was obviously hopeless then I wouldn't
>> worry... but if they started using something that I thought they
>> shouldn't know about then I'd start getting worried.
>
> I'm pretty sure the sasl_username part of the log (and probably the
> method too) is supplied by the sasl library, which is never called
> when sasl isn't offered.
>
> When sasl isn't offered but the client sends AUTH anyway, it should
> be possible for postfix to log the (sanitized) AUTH command the
> client sends, but it will be encoded.  The encoding as recorded in
> the log may be (I think likely) broken by the log sanitizer.
>
> My impression is this won't be as useful as you hope. Or my analysis
> could be flawed.
>
> Maybe Wietse or others has something to add.

If you use dovecot for SASL authentication with settings log_path =
syslog, auth_verbose = yes, then you can see attempted logins and the
reason for failure easily enough:

# grep "dovecot: auth: " /var/log/mail.log

2017-02-17 13:17:03 vps344433 dovecot: auth:
passwd-file(test,211.110.17.172): unknown user (SHA1 of given password:
a94a8fe5ccb19ba61c4c0873d391e987982fbbd3)

2017-02-17 13:17:14 vps344433 dovecot: auth:
passwd-file(test,211.110.17.172): unknown user (SHA1 of given password:
5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8)

2017-02-17 13:17:29 vps344433 dovecot: auth:
passwd-file(test,211.110.17.172): unknown user (SHA1 of given password:
7c4a8d09ca3762af61e59520943dc26494f8941b)

2017-02-17 13:19:27 vps344433 dovecot: auth: Warning: auth client 0
disconnected with 1 pending requests: Connection reset by peer

Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

/dev/rob0
On Sat, Feb 25, 2017 at 08:23:44AM +0000, Dominic Raferd wrote:

> On 25/02/2017 05:28, Noel Jones wrote:
> >On 2/24/2017 5:55 PM, James wrote:
> >>I was hoping there might be some setting that would cause log
> >>entries like:
> >>
> >>postfix/smtpd[12345]: NOQUEUE: AUTH rejected from
> >>client.example.com[0.1.2.3], sasl_method=PLAIN,
> >>sasl_username=spam_r_us
> >>
> >>As long as the sasl_username was obviously hopeless then I
> >>wouldn't worry... but if they started using something that
> >>I thought they shouldn't know about then I'd start getting
> >>worried.

A comment here: at any kind of scale it will not be easy (I am
tempted to say "not possible") to make such a determination of a
worrisome condition other than by manual reading of these logs.

> >I'm pretty sure the sasl_username part of the log (and probably
> >the method too) is supplied by the sasl library, which is never
> >called when sasl isn't offered.
> >
> >When sasl isn't offered but the client sends AUTH anyway, it
> >should be possible for postfix to log the (sanitized) AUTH
> >command the client sends, but it will be encoded.  The
> >encoding as recorded in the log may be (I think likely)
> >broken by the log sanitizer.

On Sat, Feb 25, 2017 at 08:23:44AM +0000, Dominic Raferd wrote:
> If you use dovecot for SASL authentication with settings log_path =
> syslog, auth_verbose = yes, then you can see attempted logins and
> the reason for failure easily enough:
>
> # grep "dovecot: auth: " /var/log/mail.log

But we are talking here about a case in which AUTH is not offered.
Again, as Noel pointed out, smtpd is not going to pass that forbidden
AUTH command to Dovecot.

What the OP wants is perhaps most closely related to the
reject_unauth_pipelining restriction, but for a specific ESMTP
command.  But pipelining is different, as although it is enabled also
by virtue of an EHLO keyword, it's not a specific command; it's the
method by which a client presents multiple commands at once.

So in this case I suspect the actual code path is in the area of
smtpd_{hard,soft}_error_limit.  At this point does smtpd know
anything about AUTH, or is it just one of infinite possible protocol
errors?  Would it be feasible to treat it specially?

I don't think the OP's request is entirely without merit.  Anything
which gathers information on botnets is good.  This looks like a
possible case for log parsing and fail2ban.  But I bet we usually
already know we're looking at a zombie without this extra bit of
information, so I wouldn't consider it a high priority.
--
  http://rob0.nodns4.us/
  Offlist GMX mail is seen only if "/dev/rob0" is in the Subject:
Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Wietse Venema
In reply to this post by James
James:
> I was hoping there might be some setting that would cause log entries like:
>
> postfix/smtpd[12345]: NOQUEUE: AUTH rejected from client.example.com[0.1.2.3], sasl_method=PLAIN, sasl_username=spam_r_us

Postfix does not implement SASL - the SASL SASL library does.
Therefore, details of failed logins are not available to Postfix,
only the successful ones.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Wietse Venema
Wietse Venema:
> James:
> > I was hoping there might be some setting that would cause log entries like:
> >
> > postfix/smtpd[12345]: NOQUEUE: AUTH rejected from client.example.com[0.1.2.3], sasl_method=PLAIN, sasl_username=spam_r_us
>
> Postfix does not implement SASL - the SASL SASL library does.
> Therefore, details of failed logins are not available to Postfix,
> only the successful ones.

The Postfix SMTP server supports SASL authentication with Dovecot
and with the Cyrus SASL library.

As someone pointed out, Dovecot can log information about failed
logins.

The Cyrus SASL library has a function sasl_errdetail() to report
the "last" error. When I change Postfix to call that function,
this this is what is with AUTH PLAIN, for a bad username or bad
password:

postfix/smtpd[8726]: SASL library: SASL(-13): user not found: Password verification failed
postfix/smtpd[8726]: SASL library: SASL(-13): authentication failure: Password verification failed

As you see, that function will not report the username, so logging
this does not make Postfix logging more useful.

        Wietse

Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

James
Thank you for all the replies.

I was wondering if I was missing a postfix setting that would log this info and the answer is that I'm not.

So, question answered.

I am highly confident that if I could see this logged then the vast majority of it would indeed be "oh yeah, random/hopeless attempts that don't stand a chance, ignore them".

And it's not really a postfix-specific issue, it's more holistic.

But because these AUTH attempts against postfix *are* happening constantly, I was thinking that it might offer a chance to spot (potential) problems with credentials leaking from something/somewhere else ("crap, where are they getting *that* userid from?").

It's fascinating to see the spam aimed at me using email addresses that I provided to companies that I stopped having anything to do with over a decade ago... what about credentials?

  - James

Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

James
In reply to this post by /dev/rob0
> which gathers information on botnets is good.  This looks like a
> possible case for log parsing and fail2ban.  But I bet we usually

All good comments.  Thank you.

Log parsing: exactly, but how do I log it?  (Answer from elsewhere in this topic is that I don't, in this case.)

fail2ban: instead, I went with swatchd -> nftables -> set elements with timeouts

  - James

Reply | Threaded
Open this post in threaded view
|

Re: Simple (attempted) AUTH logging?

Viktor Dukhovni

> On Feb 25, 2017, at 1:42 PM, James <[hidden email]> wrote:
>
> Log parsing: exactly, but how do I log it?

You don't need per-event log entries for this.  It suffices to identify
the "auth=0/n" log entries at the end of each SMTP connection.

--
        Viktor.