Logging suggestion

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

Logging suggestion

John Fawcett
Hi

I'd like to make two suggestions for additional logging.

The first one is to leave an explicit trace in the log when starttls is
enforced (for example on the submission port) but the client does not
issue STARTTLS.

The second one is to explicitly log that a protocol error has occurred.
Currently I get protocol errors via email to postmaster with
notify_classes = protocol setting, but I'd like to switch that off and
get an informational message in the mail log. I would find logged
messages easier to handle with automated tools.

The most frequent situations I see STARTTLS not being used on the
submission port is dictionary attacks via scripts that connect to the
submission port and blindly issue AUTH LOGIN. The same goes for protocol
errors on port 25 where AUTH is not enabled, but scripts blindly issue
AUTH LOGIN that results in the protocol error to the postmaster email.

For the second message I did think of a more general alternative, which
would be to have a "log_classes" parameter which mirrors
"notify_classes", though clearly that would be a bit more work to do and
much of what notify classes does is already logged in some way, but not
the protocol errors.

John

--- smtpd/smtpd.c.orig    2018-12-28 13:18:55.427162049 +0100
+++ smtpd/smtpd.c    2018-12-29 11:25:49.294927986 +0100
@@ -5677,6 +5677,8 @@
         if (var_smtpd_enforce_tls &&
         !state->tls_context &&
         (cmdp->flags & SMTPD_CMD_FLAG_PRE_TLS) == 0) {
+        msg_warn("Missing required STARTTLS command from %s",
+                   state->namaddr);
         smtpd_chat_reply(state,
                "530 5.7.0 Must issue a STARTTLS command first");
         state->error_count++;
@@ -5699,8 +5701,12 @@
              cmdp->name, state->namaddr, STR(state->expand_buf));
         state->flags |= SMTPD_FLAG_ILL_PIPELINING;
         }
-        if (cmdp->action(state, argc, argv) != 0)
+        if (cmdp->action(state, argc, argv) != 0) {
         state->error_count++;
+                if (state->error_mask & MAIL_ERROR_PROTOCOL)
+                msg_info("smtp protocol error in %s from %s",
+                   cmdp->name, state->namaddr);
+        }
         else
         cmdp->success_count += 1;
         if ((cmdp->flags & SMTPD_CMD_FLAG_LIMIT)

Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Patrick Ben Koetter-2
* John Fawcett <[hidden email]>:
> The first one is to leave an explicit trace in the log when starttls is
> enforced (for example on the submission port) but the client does not
> issue STARTTLS.

Have you tried to set reject_plaintext_session and trace its error message in
the log?

p@rick



--
[*] sys4 AG
 
https://sys4.de, +49 (89) 30 90 46 64
Schleißheimer Straße 26/MG,80333 München
 
Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer, Wolfgang Stief
Aufsichtsratsvorsitzender: Florian Kirstein
 
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 29/12/2018 13:59, Patrick Ben Koetter wrote:

> * John Fawcett <[hidden email]>:
>> The first one is to leave an explicit trace in the log when starttls is
>> enforced (for example on the submission port) but the client does not
>> issue STARTTLS.
> Have you tried to set reject_plaintext_session and trace its error message in
> the log?
>
> p@rick
>
>
>
Thanks Patrick, as far as I can see that restriction does not have
effect when smtpd_tls_security_level=encrypt on the submission port,
since the error on lack of STARTTLS happens before evaluation of the
restrictions. If I put smtpd_tls_security_level=may then AUTH is offered
over an unencrypted connection.

John

Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
In reply to this post by John Fawcett
John Fawcett:
> Hi
>
> I'd like to make two suggestions for additional logging.
>
> The first one is to leave an explicit trace in the log when starttls is
> enforced (for example on the submission port) but the client does not
> issue STARTTLS.

There is no code in Postfix to log something that did not happen
just like header_checks etc. have no code to trigger on non-existent
information.

However the Postfix SMTP server logs all commands that are issued in a
session. For example, to find dictionary attacks, look for sessions
with unsuccessful AUTH commands:

    $ bzgrep 'auth=[0-9]*/' /var/log/maillog.201812*
    /var/log/maillog.20181212.bz2:Dec 12 23:03:45 spike
        postfix/smtpd[76684]: disconnect from unknown[203.2.114.149]
        ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4
    [and many more from that client]

Or simply grep for "auth=0" for the common case of unsuccessful
dictionary attacks.

> The second one is to explicitly log that a protocol error has occurred.
> Currently I get protocol errors via email to postmaster with
> notify_classes = protocol setting, but I'd like to switch that off and
> get an informational message in the mail log. I would find logged
> messages easier to handle with automated tools.

You may not like the email, but it is the only way to find out
what needs fixing. Postfix just knows the client screwed up but
is not always smart enough to figure out why.

        Wietse

> The most frequent situations I see STARTTLS not being used on the
> submission port is dictionary attacks via scripts that connect to the
> submission port and blindly issue AUTH LOGIN. The same goes for protocol
> errors on port 25 where AUTH is not enabled, but scripts blindly issue
> AUTH LOGIN that results in the protocol error to the postmaster email.
>
> For the second message I did think of a more general alternative, which
> would be to have a "log_classes" parameter which mirrors
> "notify_classes", though clearly that would be a bit more work to do and
> much of what notify classes does is already logged in some way, but not
> the protocol errors.
>
> John
>
> --- smtpd/smtpd.c.orig??? 2018-12-28 13:18:55.427162049 +0100
> +++ smtpd/smtpd.c??? 2018-12-29 11:25:49.294927986 +0100
> @@ -5677,6 +5677,8 @@
> ???? ??? if (var_smtpd_enforce_tls &&
> ???? ??? !state->tls_context &&
> ???? ??? (cmdp->flags & SMTPD_CMD_FLAG_PRE_TLS) == 0) {
> +??? ??? msg_warn("Missing required STARTTLS command from %s",
> +??? ??? ?????????? state->namaddr);
> ???? ??? smtpd_chat_reply(state,
> ???? ??? ??? ?? "530 5.7.0 Must issue a STARTTLS command first");
> ???? ??? state->error_count++;
> @@ -5699,8 +5701,12 @@
> ???? ??? ??? ?cmdp->name, state->namaddr, STR(state->expand_buf));
> ???? ??? state->flags |= SMTPD_FLAG_ILL_PIPELINING;
> ???? ??? }
> -??? ??? if (cmdp->action(state, argc, argv) != 0)
> +??? ??? if (cmdp->action(state, argc, argv) != 0) {
> ???? ??? state->error_count++;
> +??????????????? if (state->error_mask & MAIL_ERROR_PROTOCOL)
> +??? ??? ??????? msg_info("smtp protocol error in %s from %s",
> +??? ??? ??? ?????? cmdp->name, state->namaddr);
> +??? ??? }
> ???? ??? else
> ???? ??? cmdp->success_count += 1;
> ???? ??? if ((cmdp->flags & SMTPD_CMD_FLAG_LIMIT)
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
In reply to this post by John Fawcett
Sorry, I did not recognize the diff because all whitespace was using
UTF8 code points, and I read mail with a text editor that is optimized
for programing, not for text processing.

After fixing the whitespace:

> --- smtpd/smtpd.c.orig    2018-12-28 13:18:55.427162049 +0100
> +++ smtpd/smtpd.c    2018-12-29 11:25:49.294927986 +0100
> @@ -5677,6 +5677,8 @@
>          if (var_smtpd_enforce_tls &&
>          !state->tls_context &&
>          (cmdp->flags & SMTPD_CMD_FLAG_PRE_TLS) == 0) {
> +        msg_warn("Missing required STARTTLS command from %s",
> +                   state->namaddr);

I would not log this for EVERY command. Especially because the
logged text size by far exceeds the command size (each logfile
record takes ~100 bytes, while the client needs to send only four
characters plus CRLF.

For example, Postfix logs pipelining errors including evidence, but
it logs this at most once per session, to avoid flooding the log
with garbage.

> -        if (cmdp->action(state, argc, argv) != 0)
> +        if (cmdp->action(state, argc, argv) != 0) {
>          state->error_count++;
> +                if (state->error_mask & MAIL_ERROR_PROTOCOL)
> +                msg_info("smtp protocol error in %s from %s",
> +                   cmdp->name, state->namaddr);
> +        }

Unfortunately, once the protocol error bit is set, this will flag
all subsequent errors as protocol errors, writing O(100) byte records
and introducing the same logfile flooding opportunity as mentioned
above.

Even if you log this only once per session, it would blame the wrong
command (cmdp->name), because the protocol error bit may have been
set when the client sent an unknown command, and that code path never
reaches the code fragment shown above.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 29/12/2018 23:20, Wietse Venema wrote:
> Sorry, I did not recognize the diff because all whitespace was using
> UTF8 code points, and I read mail with a text editor that is optimized
> for programing, not for text processing.
>
> After fixing the whitespace:
Thanks for reviewing it further. I've made another attempt below based
on your comments.

>> --- smtpd/smtpd.c.orig    2018-12-28 13:18:55.427162049 +0100
>> +++ smtpd/smtpd.c    2018-12-29 11:25:49.294927986 +0100
>> @@ -5677,6 +5677,8 @@
>>          if (var_smtpd_enforce_tls &&
>>          !state->tls_context &&
>>          (cmdp->flags & SMTPD_CMD_FLAG_PRE_TLS) == 0) {
>> +        msg_warn("Missing required STARTTLS command from %s",
>> +                   state->namaddr);
> I would not log this for EVERY command. Especially because the
> logged text size by far exceeds the command size (each logfile
> record takes ~100 bytes, while the client needs to send only four
> characters plus CRLF.
>
> For example, Postfix logs pipelining errors including evidence, but
> it logs this at most once per session, to avoid flooding the log
> with garbage.
I have added a flag similar to the pipelining one, so that the warning
is output once only per session no matter how many commands are issued
prior to running STARTTLS.

>> -        if (cmdp->action(state, argc, argv) != 0)
>> +        if (cmdp->action(state, argc, argv) != 0) {
>>          state->error_count++;
>> +                if (state->error_mask & MAIL_ERROR_PROTOCOL)
>> +                msg_info("smtp protocol error in %s from %s",
>> +                   cmdp->name, state->namaddr);
>> +        }
> Unfortunately, once the protocol error bit is set, this will flag
> all subsequent errors as protocol errors, writing O(100) byte records
> and introducing the same logfile flooding opportunity as mentioned
> above.
>
> Even if you log this only once per session, it would blame the wrong
> command (cmdp->name), because the protocol error bit may have been
> set when the client sent an unknown command, and that code path never
> reaches the code fragment shown above.
>
> Wietse
I updated the patch so it logs a generic message just once per session.
I admit it doesn't add much to the info already available in the
disconnect line, but it is an explicit indication of an error in the
session, even when notify_classes are set to not send notifications to
the postmaster.

I am attaching a new diff as a text file, hopefully it will get through
the mail system better.

John


patch.txt (2K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
John Fawcett:

> > I would not log this for EVERY command. Especially because the
> > logged text size by far exceeds the command size (each logfile
> > record takes ~100 bytes, while the client needs to send only four
> > characters plus CRLF.
> >
> > For example, Postfix logs pipelining errors including evidence, but
> > it logs this at most once per session, to avoid flooding the log
> > with garbage.
>
> I have added a flag similar to the pipelining one, so that the warning
> is output once only per session no matter how many commands are issued
> prior to running STARTTLS.

Looks better, but I wonder if this could be done in a similar way
as, or combined with, the disconnect statistics. Strawman:

disconnect from host[addr] ehlo=1 mail=0/1 quit=1 commands=3 errors=pipelining,plaintext

It puts all the stats in one place, and also minimizes the amount
of additional logfile space.

> > Even if you log this only once per session, it would blame the wrong
> > command (cmdp->name), because the protocol error bit may have been
> > set when the client sent an unknown command, and that code path never
> > reaches the code fragment shown above.
>
> I updated the patch so it logs a generic message just once per session.
> I admit it doesn't add much to the info already available in the
> disconnect line, but it is an explicit indication of an error in the
> session, even when notify_classes are set to not send notifications to
> the postmaster.

Indeed, this very much duplicates information in the command summary line.
I wonder if we need to teach the world a new search pattern for that.

> I am attaching a new diff as a text file, hopefully it will get through
> the mail system better.

This patch didn't have messed-up whitespace with UTF8 code points.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 30/12/2018 01:19, Wietse Venema wrote:

> John Fawcett:
>>> I would not log this for EVERY command. Especially because the
>>> logged text size by far exceeds the command size (each logfile
>>> record takes ~100 bytes, while the client needs to send only four
>>> characters plus CRLF.
>>>
>>> For example, Postfix logs pipelining errors including evidence, but
>>> it logs this at most once per session, to avoid flooding the log
>>> with garbage.
>> I have added a flag similar to the pipelining one, so that the warning
>> is output once only per session no matter how many commands are issued
>> prior to running STARTTLS.
> Looks better, but I wonder if this could be done in a similar way
> as, or combined with, the disconnect statistics. Strawman:
>
> disconnect from host[addr] ehlo=1 mail=0/1 quit=1 commands=3 errors=pipelining,plaintext
>
> It puts all the stats in one place, and also minimizes the amount
> of additional logfile space.
>
Here's a revised patch implementing the above logging.

I did not take out the existing pipelining logging since it provides
additional info over the new error summary in the disconnect line,
though if it's no longer judged useful (postscreen can already handle
unauthorized pipelining) it could be removed.

John


patch.txt (2K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
John Fawcett:

> On 30/12/2018 01:19, Wietse Venema wrote:
> > John Fawcett:
> >>> I would not log this for EVERY command. Especially because the
> >>> logged text size by far exceeds the command size (each logfile
> >>> record takes ~100 bytes, while the client needs to send only four
> >>> characters plus CRLF.
> >>>
> >>> For example, Postfix logs pipelining errors including evidence, but
> >>> it logs this at most once per session, to avoid flooding the log
> >>> with garbage.
> >> I have added a flag similar to the pipelining one, so that the warning
> >> is output once only per session no matter how many commands are issued
> >> prior to running STARTTLS.
> > Looks better, but I wonder if this could be done in a similar way
> > as, or combined with, the disconnect statistics. Strawman:
> >
> > disconnect from host[addr] ehlo=1 mail=0/1 quit=1 commands=3 errors=pipelining,plaintext
> >
> > It puts all the stats in one place, and also minimizes the amount
> > of additional logfile space.
> >
> Here's a revised patch implementing the above logging.
>
> I did not take out the existing pipelining logging since it provides
> additional info over the new error summary in the disconnect line,
> though if it's no longer judged useful (postscreen can already handle
> unauthorized pipelining) it could be removed.

As a proof of concept this seems to work. As for redundancy, I think
it is useful to log the pipelining violation detail once per session
because it immediately answers the question 'why' Postfix did something.

However, there is a difference between proof of concept and full
implementation. For example, if RCPT TO was rejected, then one would
expect that 'errors=' always shows some error category. You can
already see where this is going.

Therefore, at this point it may be better to just log that the
client sent plaintext, once per session.

I have real work that leaves few cycles for Postfix, and a full
implementation of errors= stats may therefore have to wait until
after the stable 3.4 release.

JFTR, this is what a full implementation would look like.
A full implementation would update a new SMTP_STATE violation_mask
field for specific violation categories (syntax, pipelining,
plaintext, relay, unverified-address, unknown-user, access-deny,
dnsbl, tls-handshake, lost-connection, timeout, etc).

This has a huge code footprint, because every piece of code that
detects a violation will need to set a violation category bit. TBD
is which error categories: we don't want too few (then we could
just use the existing 'protocol', 'software', 'policy', 'resource',
etc.  break-down) or too many buckets.

For output, the implementation would use str_name_mask(), probably
called from a separate function smtpd_format_error_stats().

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 30/12/2018 18:05, Wietse Venema wrote:

> John Fawcett:
>> On 30/12/2018 01:19, Wietse Venema wrote:
>> Here's a revised patch implementing the above logging.
>>
>> I did not take out the existing pipelining logging since it provides
>> additional info over the new error summary in the disconnect line,
>> though if it's no longer judged useful (postscreen can already handle
>> unauthorized pipelining) it could be removed.
> As a proof of concept this seems to work. As for redundancy, I think
> it is useful to log the pipelining violation detail once per session
> because it immediately answers the question 'why' Postfix did something.
>
> However, there is a difference between proof of concept and full
> implementation. For example, if RCPT TO was rejected, then one would
> expect that 'errors=' always shows some error category. You can
> already see where this is going.
>
> Therefore, at this point it may be better to just log that the
> client sent plaintext, once per session.
>
> I have real work that leaves few cycles for Postfix, and a full
> implementation of errors= stats may therefore have to wait until
> after the stable 3.4 release.
>
> JFTR, this is what a full implementation would look like.
> A full implementation would update a new SMTP_STATE violation_mask
> field for specific violation categories (syntax, pipelining,
> plaintext, relay, unverified-address, unknown-user, access-deny,
> dnsbl, tls-handshake, lost-connection, timeout, etc).
>
> This has a huge code footprint, because every piece of code that
> detects a violation will need to set a violation category bit. TBD
> is which error categories: we don't want too few (then we could
> just use the existing 'protocol', 'software', 'policy', 'resource',
> etc.  break-down) or too many buckets.
>
> For output, the implementation would use str_name_mask(), probably
> called from a separate function smtpd_format_error_stats().
>
> Wietse

Thanks for the feedback.

I can take a look at it, but aside from time, I agree that any invasive
modifications would be better done in a new experimental release. I also
would not put the a temporary modification in 3.4 since people may
become accustomed to it, when it is likely to change again.

John

Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 30/12/2018 20:20, John Fawcett wrote:

> On 30/12/2018 18:05, Wietse Venema wrote:
>> John Fawcett:
>>> On 30/12/2018 01:19, Wietse Venema wrote:
>>> Here's a revised patch implementing the above logging.
>>>
>>> I did not take out the existing pipelining logging since it provides
>>> additional info over the new error summary in the disconnect line,
>>> though if it's no longer judged useful (postscreen can already handle
>>> unauthorized pipelining) it could be removed.
>> As a proof of concept this seems to work. As for redundancy, I think
>> it is useful to log the pipelining violation detail once per session
>> because it immediately answers the question 'why' Postfix did something.
>>
>> However, there is a difference between proof of concept and full
>> implementation. For example, if RCPT TO was rejected, then one would
>> expect that 'errors=' always shows some error category. You can
>> already see where this is going.
>>
>> Therefore, at this point it may be better to just log that the
>> client sent plaintext, once per session.
>>
>> I have real work that leaves few cycles for Postfix, and a full
>> implementation of errors= stats may therefore have to wait until
>> after the stable 3.4 release.
>>
>> JFTR, this is what a full implementation would look like.
>> A full implementation would update a new SMTP_STATE violation_mask
>> field for specific violation categories (syntax, pipelining,
>> plaintext, relay, unverified-address, unknown-user, access-deny,
>> dnsbl, tls-handshake, lost-connection, timeout, etc).
>>
>> This has a huge code footprint, because every piece of code that
>> detects a violation will need to set a violation category bit. TBD
>> is which error categories: we don't want too few (then we could
>> just use the existing 'protocol', 'software', 'policy', 'resource',
>> etc.  break-down) or too many buckets.
>>
>> For output, the implementation would use str_name_mask(), probably
>> called from a separate function smtpd_format_error_stats().
>>
>> Wietse
> Thanks for the feedback.
>
> I can take a look at it, but aside from time, I agree that any invasive
> modifications would be better done in a new experimental release. I also
> would not put the a temporary modification in 3.4 since people may
> become accustomed to it, when it is likely to change again.
>
> John
>
To take this one step further, I have documented the current behaviour
for errors during the smtp chat, indicating whether they are chatted to
the client, logged to maillog and whether they set existing error flags.
I did that so far for smtpd.c, smtpd_sasl_glue.c and smtpd_sasl_proto.c
from postfix-3.4-20181229-nonprod. I did not include normal smtp chats,
verbose logging or logging done outside an smtp session or done during
initializations.

I suppose that the next step would be to evalute which of these errors
are worthy of being reported in the disconnect line, with a particular
eye to errors that are currently not logged in the maillog and that
would not be available if postmaster notifications are disabled (more
likely for PROTOCOL and POLICY errors).

Any thoughts about this approach? PS the attachment is a LibreOffice
spreadsheet. Let's see if it gets through.

John



postfix smtpd errors.ods (28K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
John Fawcett:

> >> JFTR, this is what a full implementation would look like.
> >> A full implementation would update a new SMTP_STATE violation_mask
> >> field for specific violation categories (syntax, pipelining,
> >> plaintext, relay, unverified-address, unknown-user, access-deny,
> >> dnsbl, tls-handshake, lost-connection, timeout, etc).
> >>
> >> This has a huge code footprint, because every piece of code that
> >> detects a violation will need to set a violation category bit. TBD
> >> is which error categories: we don't want too few (then we could
> >> just use the existing 'protocol', 'software', 'policy', 'resource',
> >> etc.  break-down) or too many buckets.
> >>
> >> For output, the implementation would use str_name_mask(), probably
> >> called from a separate function smtpd_format_error_stats().
> >>
> >> Wietse
> > Thanks for the feedback.
> >
> > I can take a look at it, but aside from time, I agree that any invasive
> > modifications would be better done in a new experimental release. I also
> > would not put the a temporary modification in 3.4 since people may
> > become accustomed to it, when it is likely to change again.
> >
> > John
> >
> To take this one step further, I have documented the current behaviour
> for errors during the smtp chat, indicating whether they are chatted to
> the client, logged to maillog and whether they set existing error flags.
> I did that so far for smtpd.c, smtpd_sasl_glue.c and smtpd_sasl_proto.c
> from postfix-3.4-20181229-nonprod. I did not include normal smtp chats,
> verbose logging or logging done outside an smtp session or done during
> initializations.
>
> I suppose that the next step would be to evalute which of these errors
> are worthy of being reported in the disconnect line, with a particular
> eye to errors that are currently not logged in the maillog and that
> would not be available if postmaster notifications are disabled (more
> likely for PROTOCOL and POLICY errors).
>
> Any thoughts about this approach? PS the attachment is a LibreOffice
> spreadsheet. Let's see if it gets through.

Basically everything that detects a violation sets state->error_mask,
and there would need to be another line of code that sets a violation
type bit. That's about 124 places. I don't see that smtpd_chat.c
is in a violation detection code path; it reports violations that
are detected elsewhere.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

John Fawcett
On 01/01/2019 17:56, Wietse Venema wrote:
John Fawcett:
JFTR, this is what a full implementation would look like.
A full implementation would update a new SMTP_STATE violation_mask
field for specific violation categories (syntax, pipelining,
plaintext, relay, unverified-address, unknown-user, access-deny,
dnsbl, tls-handshake, lost-connection, timeout, etc).

This has a huge code footprint, because every piece of code that
detects a violation will need to set a violation category bit. TBD
is which error categories: we don't want too few (then we could
just use the existing 'protocol', 'software', 'policy', 'resource',
etc.  break-down) or too many buckets.

For output, the implementation would use str_name_mask(), probably
called from a separate function smtpd_format_error_stats().

	Wietse
Thanks for the feedback.

I can take a look at it, but aside from time, I agree that any invasive
modifications would be better done in a new experimental release. I also
would not put the a temporary modification in 3.4 since people may
become accustomed to it, when it is likely to change again.

John

To take this one step further, I have documented the current behaviour
for errors during the smtp chat, indicating whether they are chatted to
the client, logged to maillog and whether they set existing error flags.
I did that so far for smtpd.c, smtpd_sasl_glue.c and smtpd_sasl_proto.c
from postfix-3.4-20181229-nonprod. I did not include normal smtp chats,
verbose logging or logging done outside an smtp session or done during
initializations.

I suppose that the next step would be to evalute which of these errors
are worthy of being reported in the disconnect line, with a particular
eye to errors that are currently not logged in the maillog and that
would not be available if postmaster notifications are disabled (more
likely for PROTOCOL and POLICY errors).

Any thoughts about this approach? PS the attachment is a LibreOffice
spreadsheet. Let's see if it gets through.
Basically everything that detects a violation sets state->error_mask,
and there would need to be another line of code that sets a violation
type bit. That's about 124 places. I don't see that smtpd_chat.c
is in a violation detection code path; it reports violations that
are detected elsewhere.

	Wietse

smtp_chat.c wasn't one of the files I looked at but I agree it is not relevant. For clarity: the "smtp chat" column in the spreadhset is to contextualize what errors are being sent back to the client.

Grepping on MAIL_ERROR_* errors for smtpd directory, I get

MAIL_ERROR_POLICY 32

MAIL_ERROR_PROTOCOL 74 (1 is in excluded code)

MAIL_ERROR_RESOURCE 3

MAIL_ERROR_SOFTWARE 8

MAIL_ERROR_BOUNCE 2

MAIL_ERROR_DATA 1

and I've tracked all of them in the revised spreadsheet as well as correcting a copy and paste error in the last few lines of the previous version.

In column H I have added the proposal for the new violation_mask bucket. I have only done that for errors that are currently flagged as violations in error_mask, plus the following additional cases:

  • in smtpd_proto(), when smtpd_client_connection_rate_limit exceeded
  • in smtpd_proto() for improper pipelining

Maybe I put too many buckets, but they can be condensed. From the example buckets you gave, I didn't find places where the following were flagged as violations: relay, unverified-address, unknown-user, dnsbl, tls-handshake, lost connection and timeout. That needs more work. There was also one that I could not classify (see ???? in column H).

John



postfix smtpd errors.ods (29K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Logging suggestion

Wietse Venema
John Fawcett:

> On 01/01/2019 17:56, Wietse Venema wrote:
> > John Fawcett:
> >>>> JFTR, this is what a full implementation would look like.
> >>>> A full implementation would update a new SMTP_STATE violation_mask
> >>>> field for specific violation categories (syntax, pipelining,
> >>>> plaintext, relay, unverified-address, unknown-user, access-deny,
> >>>> dnsbl, tls-handshake, lost-connection, timeout, etc).
> >>>>
> >>>> This has a huge code footprint, because every piece of code that
> >>>> detects a violation will need to set a violation category bit. TBD
> >>>> is which error categories: we don't want too few (then we could
> >>>> just use the existing 'protocol', 'software', 'policy', 'resource',
> >>>> etc.  break-down) or too many buckets.
> >>>>
> >>>> For output, the implementation would use str_name_mask(), probably
> >>>> called from a separate function smtpd_format_error_stats().
> >>>>
> >>>> Wietse
> >>> Thanks for the feedback.
> >>>
> >>> I can take a look at it, but aside from time, I agree that any invasive
> >>> modifications would be better done in a new experimental release. I also
> >>> would not put the a temporary modification in 3.4 since people may
> >>> become accustomed to it, when it is likely to change again.
> >>>
> >>> John
> >>>
> >> To take this one step further, I have documented the current behaviour
> >> for errors during the smtp chat, indicating whether they are chatted to
> >> the client, logged to maillog and whether they set existing error flags.
> >> I did that so far for smtpd.c, smtpd_sasl_glue.c and smtpd_sasl_proto.c
> >> from postfix-3.4-20181229-nonprod. I did not include normal smtp chats,
> >> verbose logging or logging done outside an smtp session or done during
> >> initializations.
> >>
> >> I suppose that the next step would be to evalute which of these errors
> >> are worthy of being reported in the disconnect line, with a particular
> >> eye to errors that are currently not logged in the maillog and that
> >> would not be available if postmaster notifications are disabled (more
> >> likely for PROTOCOL and POLICY errors).
> >>
> >> Any thoughts about this approach? PS the attachment is a LibreOffice
> >> spreadsheet. Let's see if it gets through.
> > Basically everything that detects a violation sets state->error_mask,
> > and there would need to be another line of code that sets a violation
> > type bit. That's about 124 places. I don't see that smtpd_chat.c
> > is in a violation detection code path; it reports violations that
> > are detected elsewhere.
> >
> > Wietse
>
> smtp_chat.c wasn't one of the files I looked at but I agree it is not
> relevant. For clarity: the "smtp chat" column in the spreadhset is to
> contextualize what errors are being sent back to the client.
>
> Grepping on MAIL_ERROR_* errors for smtpd directory, I get
>
> MAIL_ERROR_POLICY 32

Many policy violations are reported with smtpd_check_reject()
calls, including this one:

    /*
     * Deny relaying between sites that both are not in relay_domains.
     */
    return (smtpd_check_reject(state, MAIL_ERROR_POLICY,
                               var_relay_code, "5.7.1",
                               "<%s>: %s rejected: Relay access denied",
                               reply_name, reply_class));

In my initial strawman, this would be flagged as a 'relay' violation.

> MAIL_ERROR_PROTOCOL 74 (1 is in excluded code)

Lots of 'bad syntax', disabled commands, but also pipelining.

> MAIL_ERROR_RESOURCE 3
>
> MAIL_ERROR_SOFTWARE 8
>
> MAIL_ERROR_BOUNCE 2
>
> MAIL_ERROR_DATA 1
>
> and I've tracked all of them in the revised spreadsheet as well as
> correcting a copy and paste error in the last few lines of the previous
> version.
>
> In column H I have added the proposal for the new violation_mask bucket.
> I have only done that for errors that are currently flagged as
> violations in error_mask, plus the following additional cases:
>
>   * in smtpd_proto(), when smtpd_client_connection_rate_limit exceeded
>   * in smtpd_proto() for improper pipelining
>
> Maybe I put too many buckets, but they can be condensed. From the
> example buckets you gave, I didn't find places where the following were
> flagged as violations: relay, unverified-address, unknown-user, dnsbl,
> tls-handshake, lost connection and timeout. That needs more work. There
> was also one that I could not classify (see ???? in column H).

'user unknown' is reported as a MAIL_ERROR_BOUNCE conditon
by calling smtpd_check_reject().

            return (smtpd_check_reject(state, MAIL_ERROR_BOUNCE,
                                       var_local_rcpt_code,
                               strcmp(reply_class, SMTPD_NAME_SENDER) == 0 ?
                                       "5.1.0" : "5.1.1",
                                       "<%s>: %s rejected: User unknown%s",
                                       recipient, reply_class,
                                       var_show_unk_rcpt_table ?
                                       " in local recipient table" : ""));

I don't have time to investigate the other ones but expect that
many of them will also buried in smtpd_check_reject() calls.

        Wietse