Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

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

Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Dominic Raferd
I am puzzling over why postfix fails to pass a response from gmail at
the end of an outgoing transmission through to
smtp_delivery_status_filter.

I am trying to trap a transient failure code response from gmail and
replace it with a permanent code and to do this I am using
smtp_delivery_status_filter=pcre:/etc/postfix/smtp_dsn_filter. To
debug it I am running smtp with -v.

I give two real-life (obfuscated) examples below which happened
seconds apart. In example 1 - a message successfully sent to gmail -
the final response from gmail is passed to the filter, which
(correctly) fails to find the text in the filter.. In example 2 - with
the dsn code I want to rewrite - nothing is passed to the filter. I am
wondering if postfix gets confused either by the length of the
response or by gmail's use of a dash between the 3 digit dsn code and
enhanced dsn code that follows (although the final line of the
response does not have this dash)?

# Example 1: response from gmail at end of smtp transmission is
checked using dns_filter_lookup - as intended, and not found - as
intended
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: >
gmail-smtp-in.l.google.com[74.125.195.27]:25: QUIT
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: smtp_stream_setup:
maxtime=600 enable_deadline=0
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 250 2.0.0 OK 1484049070
ld4si1455293wjb.62 - gsmtp
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: dsn_filter_lookup: 2.0.0
250 2.0.0 OK 1484049070 ld4si1455293wjb.62 - gsmtp
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: dict_pcre_lookup:
/etc/postfix/smtp_dsn_filter: 2.0.0 250 2.0.0 OK 1484049070
ld4si1455293wjb.62 - gsmtp
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: maps_find:
smtp_delivery_status_filter: 2.0.0 250 2.0.0 OK 1484049070
ld4si1455293wjb.62 - gsmtp: not found
2017-01-10 12:51:10 vps1 postfix/smtp[27587]: C636E43D7C:
to=<[hidden email]>, orig_to=<[hidden email]>,
relay=gmail-smtp-in.l.google.com[74.125.195.27]:25, delay=0.65,
delays=0.05/0.07/0.16/0.37, dsn=2.0.0, status=sent (250 2.0.0 OK
1484049070 ld4si1455293wjb.62 - gsmtp)

# Example 2: response from gmail at end of smtp transmission is never
checked using dns_filter_lookup - why?
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: >
gmail-smtp-in.l.google.com[74.125.195.27]:25: QUIT
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: smtp_stream_setup:
maxtime=600 enable_deadline=0
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 421-4.7.0
[163.133.227.220      15] Our system has detected that this message is
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 421-4.7.0 suspicious due
to the very low reputation of the sending domain. To
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 421-4.7.0 best protect
our users from spam, the message has been blocked.
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 421-4.7.0 Please visit
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: <
gmail-smtp-in.l.google.com[74.125.195.27]:25: 421 4.7.0
https://support.google.com/mail/answer/188131 for more information.
c28si1314741wrb.13 -
2017-01-10 12:52:40 vps1 postfix/smtp[27587]: 7A00F43D7C: host
gmail-smtp-in.l.google.com[74.125.195.27] said: 421-4.7.0
[163.133.227.220      15] Our system has detected that this message is
421-4.7.0 suspicious due to the very low reputation of the sending
domain. To 421-4.7.0 best protect our users from spam, the message has
been blocked. 421-4.7.0 Please visit 421 4.7.0
https://support.google.com/mail/answer/188131 for more information.
c28si1314741wrb.13 - gsmtp (in reply to end of DATA command)
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Wietse Venema
Dominic Raferd:
> # Example 1: response from gmail at end of smtp transmission is
> checked using dns_filter_lookup - as intended, and not found - as

$ postconf dns_filter_lookup
postconf: warning: dns_filter_lookup: unknown parameter

No surprise, then, that nothing is matched.

To cite the mailing list welcome message:

TO REPORT A PROBLEM see http://www.postfix.org/DEBUG_README.html#mail

TO (UN)SUBSCRIBE see http://www.postfix.org/lists.html

Thank you for using Postfix.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Dominic Raferd
On 10 January 2017 at 14:41, Wietse Venema <[hidden email]> wrote:
> Dominic Raferd:
>> # Example 1: response from gmail at end of smtp transmission is
>> checked using dns_filter_lookup - as intended, and not found - as
>
> $ postconf dns_filter_lookup
> postconf: warning: dns_filter_lookup: unknown parameter
>
> No surprise, then, that nothing is matched.
>

(reposting to postfix-users...)

Quite so, but finding a match once the test occurs is not the issue
here. My apologies for confusion caused by my typo putting 'dns' in
handwritten comment line when of course I meant 'dsn'.

I am using smtp_delivery_status_filter=pcre:/etc/postfix/smtp_dsn_filter,
and this file does exist and is called to test the response after a
successful delivery - my first example is the simple control case.

My puzzle is in the second example where no test is performed upon the
final response code.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Wietse Venema
Dominic Raferd:

> On 10 January 2017 at 14:41, Wietse Venema <[hidden email]> wrote:
> > Dominic Raferd:
> >> # Example 1: response from gmail at end of smtp transmission is
> >> checked using dns_filter_lookup - as intended, and not found - as
> >
> > $ postconf dns_filter_lookup
> > postconf: warning: dns_filter_lookup: unknown parameter
> >
> > No surprise, then, that nothing is matched.
> >
>
> (reposting to postfix-users...)
>
> Quite so, but finding a match once the test occurs is not the issue
> here. My apologies for confusion caused by my typo putting 'dns' in
> handwritten comment line when of course I meant 'dsn'.
>
> I am using smtp_delivery_status_filter=pcre:/etc/postfix/smtp_dsn_filter,
> and this file does exist and is called to test the response after a
> successful delivery - my first example is the simple control case.
>
> My puzzle is in the second example where no test is performed upon the
> final response code.

If you wonder why a 421 response does not match your PCRE file,
show your PCRE file.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Dominic Raferd
On 11 January 2017 at 00:29, Wietse Venema <[hidden email]> wrote:

> Dominic Raferd:
>> On 10 January 2017 at 14:41, Wietse Venema <[hidden email]> wrote:
>> > Dominic Raferd:
>> >> # Example 1: response from gmail at end of smtp transmission is
>> >> checked using dns_filter_lookup - as intended, and not found - as
>> >
>> > $ postconf dns_filter_lookup
>> > postconf: warning: dns_filter_lookup: unknown parameter
>> >
>> > No surprise, then, that nothing is matched.
>> >
>>
>> (reposting to postfix-users...)
>>
>> Quite so, but finding a match once the test occurs is not the issue
>> here. My apologies for confusion caused by my typo putting 'dns' in
>> handwritten comment line when of course I meant 'dsn'.
>>
>> I am using smtp_delivery_status_filter=pcre:/etc/postfix/smtp_dsn_filter,
>> and this file does exist and is called to test the response after a
>> successful delivery - my first example is the simple control case.
>>
>> My puzzle is in the second example where no test is performed upon the
>> final response code.
>
> If you wonder why a 421 response does not match your PCRE file,
> show your PCRE file.
>
>         Wietse

I could do so, but this is not what I am wondering. I am wondering why
in my example 2 postfix never even attempts to look up the PCRE file.
Of course it does not find a match because it does not attempt the
lookup.

In my example 1 the single-line gmail response (which happens to be
250) is followed by the pcre lookup:
12:51:10 postfix/smtp: <gmail-smtp-in.l.google.com[74.125.195.27]:25:
250 2.0.0 OK 1484049070 ld4si1455293wjb.62 - gsmtp
12:51:10 postfix/smtp: dsn_filter_lookup: 2.0.0 250 2.0.0 OK
1484049070 ld4si1455293wjb.62 - gsmtp

In my example 2 the final line of the multi-line gmail response (which
happens to be 421) is not followed by the pcre lookup, instead the
message from gmail goes direct to the log and the lookup never
happens:
12:52:40 postfix/smtp: <gmail-smtp-in.l.google.com[74.125.195.27]:25:
421 4.7.0 https://support.google.com/mail/answer/188131 for more
information. c28si1314741wrb.13 -
12:52:40 postfix/smtp: 7A00F43D7C: host
gmail-smtp-in.l.google.com[74.125.195.27] said: 421-4.7.0 ...

With example 2 I think there should be a log entry from
dsn_filter_lookup immediately after the final response line from
gmail, this would show merely that a lookup was being initiated. It
isn't there. Nor are further log lines giving lookup progress and
result (this is unsurprising, since the lookup hasn't happened). All
of these lines are present in (my original full text of) example 1 and
missing from example 2.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Wietse Venema
Sorry, I don't have time for this.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Viktor Dukhovni
In reply to this post by Dominic Raferd
On Tue, Jan 10, 2017 at 02:00:14PM +0000, Dominic Raferd wrote:

> I am puzzling over why postfix fails to pass a response from gmail at
> the end of an outgoing transmission through to
> smtp_delivery_status_filter.

This is because, unlike the case with smtp_reply_filter, the
smtp_dsn_bounce_filter applies only when a recipient is "done",
that is, no further attempts to deliver the message to the recipient
via a an alternate MX host or fallback will be attempted.

Therefore, the table is not consulted with 4XX replies from a
non-final MX host.

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Wietse Venema
Viktor Dukhovni:
> This is because, unlike the case with smtp_reply_filter, the
> smtp_dsn_bounce_filter applies only when a recipient is "done",
> that is, no further attempts to deliver the message to the recipient
> via a an alternate MX host or fallback will be attempted.

Thanks for spotting that. What about adding some text:

    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
    attempts to multiple MX or A destinations. Unlike
    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
    is applied only to the result of the last delivery attempt.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Viktor Dukhovni

> On Jan 11, 2017, at 9:44 AM, Wietse Venema <[hidden email]> wrote:
>
> Thanks for spotting that. What about adding some text:
>
>    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
>    attempts to multiple MX or A destinations. Unlike
>    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
>    is applied only to the result of the last delivery attempt.

That looks rather good to me, so go ahead.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Dominic Raferd
On 11 January 2017 at 14:53, Viktor Dukhovni <[hidden email]> wrote:

>
>> On Jan 11, 2017, at 9:44 AM, Wietse Venema <[hidden email]> wrote:
>>
>> Thanks for spotting that. What about adding some text:
>>
>>    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
>>    attempts to multiple MX or A destinations. Unlike
>>    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
>>    is applied only to the result of the last delivery attempt.
>
> That looks rather good to me, so go ahead.
>

That does indeed seem to have been the cause of my confusion, thank
you for the explanation. I am now trying with smtp_reply_filter
instead of smtp_delivery_status_filter.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Viktor Dukhovni
In reply to this post by Viktor Dukhovni
On Wed, Jan 11, 2017 at 09:53:21AM -0500, Viktor Dukhovni wrote:

> > On Jan 11, 2017, at 9:44 AM, Wietse Venema <[hidden email]> wrote:
> >
> > Thanks for spotting that. What about adding some text:
> >
> >    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
> >    attempts to multiple MX or A destinations. Unlike
> >    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
> >    is applied only to the result of the last delivery attempt.
>
> That looks rather good to me, so go ahead.

Perhaps one could mention that "last delivery attempt" is
recipient-specific.  For 2XX and 5XX responses no further MX hosts
are tried, while for a 4XX response another MX host may be tried,
and the DSN filter will apply to the either the first 2XX or 5XX
response or the last 4XX response.

Users who want to process each and every response as it happens
should use the reply filter instead.

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Jan Ceuleers
In reply to this post by Wietse Venema
On 11/01/17 15:44, Wietse Venema wrote:
> Thanks for spotting that. What about adding some text:
>     Note: The smtp(8) and lmtp(8) delivery agents can make delivery
>     attempts to multiple MX or A destinations. Unlike
>     (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
>     is applied only to the result of the last delivery attempt.
Should that be "final delivery attempt" instead of "last delivery
attempt", to avoid any possible confusion caused by the fact that "last"
could also mean "previous"?
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Viktor Dukhovni

> On Jan 11, 2017, at 10:28 AM, Jan Ceuleers <[hidden email]> wrote:
>
> Should that be "final delivery attempt" instead of "last delivery
> attempt", to avoid any possible confusion caused by the fact that "last"
> could also mean "previous"?

All these terms are potentially confusing out of context.  I think that
"last" is better than "final" however, because the delivery in question
is the last of a set of related delivery attempts, and the envelope may
be deferred and retried.  Here "related" means an initial delivery, and
possibly additional deliveries via alternate MX hosts or addresses with
any recipients that tempfail.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Wietse Venema
In reply to this post by Viktor Dukhovni
Viktor Dukhovni:

>
> > On Jan 11, 2017, at 9:44 AM, Wietse Venema <[hidden email]> wrote:
> >
> > Thanks for spotting that. What about adding some text:
> >
> >    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
> >    attempts to multiple MX or A destinations. Unlike
> >    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
> >    is applied only to the result of the last delivery attempt.
>
> That looks rather good to me, so go ahead.

Thanks again. I'll update it in the light of comments to

    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
    attempts to multiple MX or A destinations. Unlike
    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
    is applied only once per recipient, to the result from its last
    delivery attempt.

Using the mailing list as scratch pad...

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Response from gmail at end of transmisssion not passed to smtp_delivery_status_filter

Viktor Dukhovni
On Wed, Jan 11, 2017 at 04:43:47PM -0500, Wietse Venema wrote:

> Viktor Dukhovni:
> >
> > > On Jan 11, 2017, at 9:44 AM, Wietse Venema <[hidden email]> wrote:
> > >
> > > Thanks for spotting that. What about adding some text:
> > >
> > >    Note: The smtp(8) and lmtp(8) delivery agents can make delivery
> > >    attempts to multiple MX or A destinations. Unlike
> > >    (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
> > >    is applied only to the result of the last delivery attempt.
> >
> > That looks rather good to me, so go ahead.
>
> Thanks again. I'll update it in the light of comments to
>
>     Note: The smtp(8) and lmtp(8) delivery agents can make delivery
>     attempts to multiple MX or A destinations. Unlike
>     (smtp|lmtp)_reply_filter, the (smtp|lmtp)_delivery_status_filter
>     is applied only once per recipient, to the result from its last
>     delivery attempt.

I think that nails it.

--
        Viktor.