Re: Duplicate mails in mailq / always_bcc

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

Re: Duplicate mails in mailq / always_bcc

Niclas Rautenhaus



Hi list,

sorry for my belated reply.

First of all: thanks for the input to everyone suggesting where / what the error may be.

What I tried so far:
1) reducing the MTU all the way down to 1400 - no change, error still persists.
2) sniffing the connection: nothing suspicious, one or two RST flags in a bunch of 1800 packets
3) Uncomment the filters we use, to rule them out as an error cause: this was partly successful; with every filter uncommented the error still persists
4) deactivate the tcp_window_scaling -> the problem still persists
5) removed the comment from this line:
relay     unix  -       -       -       -       -       smtp
#       -o smtp_helo_timeout=120 -o smtp_connect_timeout=120

6) Added the following entry to the master.cf
smtp      inet  n       -       -       -       -       smtpd
         -o content_filter=spamassassin
->>         -o receive_override_options=no_address_mappings

However, the error still persists.
I set postfix to log verbosely, to find similarities or differences between those mails that pass without any problems at all, and those which get stuck in the queue.
However, the mails which "loose connection" are neither especially big nor very small, they range from 20445 up to 82680 and sometimes get blocked, sometimes they don't.

What I could gather from the logs:
- the delay varies massively and apparently has no influence on whether a mail gets stuck or not
- the mails all hang with the status "dsn=4.4.2, status=deferred"

Thanks in advance for any input regarding this matter.
Niclas





-----Urspr√ľngliche Nachricht-----
Von: [hidden email] [mailto:[hidden email]] Im Auftrag von Wietse Venema
Gesendet: Montag, 27. November 2017 21:39
An: Postfix users <[hidden email]>
Betreff: [MASSMAIL]Re: Duplicate mails in mailq / always_bcc

Niclas Rautenhaus:
> 5086760443    35318 Mon Nov 13 16:04:20  [hidden email]<mailto:[hidden email]>
> (lost connection with 192.168.N.NN[192.168.N.NN] while sending end of
> data -- message may be sent more than once)

This is the result of Postfix reading EOF, not a Postfix timeout (that produces a different error message).

Postfix may read EOF as the result of some other error at a lower layer in the network stack.

A more precise determination would require a network sniffer. Just the packet metadata (no data content) might be sufficient.

        Wietse

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni


> On Feb 5, 2018, at 12:04 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
> What I tried so far:

Instead of blindly trying random changes that may only have unwanted
side-effects, collect the information needed to understand the problem.

What you have not yet tried is posting the complete logging for some
of the queue-ids that got "stuck", and (more importantly) posting
"tcpdump" output for a captured session.  If all else fails, then
send a complete PCAP file off-list to Wietse or me.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Niclas Rautenhaus
In reply to this post by Niclas Rautenhaus



Hi,

> Instead of blindly trying random changes that may only have unwanted
> side-effects, collect the information needed to understand the problem.

I did not change anything that I am not able to revert back to it's original settings.
I am not "blindly trying random changes" but implementing suggestions being made in this thread and / or I found elsewhere  online when I searched for keywords like "postfix", "always_bcc", "content_filter" etc.

For the sake of keeping this mail readable, please refer to this link (https://pastebin.com/nUz5BEdB) , there you will find an excerpt of the maillog from two mails stuck in the queue.

I could try and generate a logfile, when postfix logs verbosely again (but as the system is quite active I presume there will be many non-related information in the excerpt). Would that be of any help?
I could also provide PCAP files and / or wireshark data, when there is a chance to anonymise the information.

Thanks,
Niclas





-----Urspr√ľngliche Nachricht-----
Von: [hidden email] [mailto:[hidden email]] Im Auftrag von Viktor Dukhovni
Gesendet: Montag, 5. Februar 2018 20:01
An: Postfix users <[hidden email]>
Betreff: [MASSMAIL]Re: Duplicate mails in mailq / always_bcc



> On Feb 5, 2018, at 12:04 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
> What I tried so far:

Instead of blindly trying random changes that may only have unwanted side-effects, collect the information needed to understand the problem.

What you have not yet tried is posting the complete logging for some of the queue-ids that got "stuck", and (more importantly) posting "tcpdump" output for a captured session.  If all else fails, then send a complete PCAP file off-list to Wietse or me.

--
        Viktor.


Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni


> On Feb 5, 2018, at 3:00 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
> I did not change anything that I am not able to revert back to it's original settings.
> I am not "blindly trying random changes" but implementing suggestions being made in this
> thread and / or I found elsewhere online when I searched for keywords like "postfix",
> "always_bcc", "content_filter" etc.

Sadly, none of those things are immediately plausible work-arounds or
get you closer to isolating the problem.  At this time just collect
sufficient logs and network captures to distinguish between the failure
and success cases.

> For the sake of keeping this mail readable, please refer to this link
> (https://pastebin.com/nUz5BEdB) , there you will find an excerpt of the
> maillog from two mails stuck in the queue.

One thing that is interesting is that the message generates two BCC
copies with the *same* recipient address:

   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
     relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
     status=deferred (lost connection with 192.168.1.23[192.168.1.23]
     while sending end of data -- message may be sent more than once)

   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
    relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
    status=deferred (lost connection with 192.168.1.23[192.168.1.23]
    while sending end of data -- message may be sent more than once)

   Feb 5 17:28:52 mail postfix/smtp[22773]: 363BD601EE: to=<[hidden email]>,
     relay=smtp.ext-hoster.tld[XX.XXX.XXX.XXX]:25, delay=1.1, delays=0.01/0/0.24/0.8, dsn=2.0.0,
     status=sent (250 2.0.0 queued as V03a1fu15GSpL0R)

Perhaps the appliance mishandles messages with duplicate recipient addresses?
Is there any correlation between messages that repeatedly fail and messages
that have a duplicate recipient?  Is the same feature observed in successful
archive deliveries?

Note also that for this to be a meaningful mail archive, you should lose the
original envelope recipient addresses (which happens with always_bcc) and
instead use a recipe based on "recipient_bcc_maps" with regular expression
mappings that capture each unique recipient as a unique archive recipient
address.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni


> On Feb 5, 2018, at 3:16 PM, Viktor Dukhovni <[hidden email]> wrote:
>
> Note also that for this to be a meaningful mail archive, you should lose the
> original envelope recipient addresses (which happens with always_bcc) and
> instead use a recipe based on "recipient_bcc_maps" with regular expression
> mappings that capture each unique recipient as a unique archive recipient
> address.

s/should lose/should not lose/

Sorry about any confusion.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni
In reply to this post by Viktor Dukhovni


> On Feb 5, 2018, at 3:16 PM, Viktor Dukhovni <[hidden email]> wrote:
>
> One thing that is interesting is that the message generates two BCC
> copies with the *same* recipient address:
>
>   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
>     relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
>     status=deferred (lost connection with 192.168.1.23[192.168.1.23]
>     while sending end of data -- message may be sent more than once)
>
>   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
>    relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
>    status=deferred (lost connection with 192.168.1.23[192.168.1.23]
>    while sending end of data -- message may be sent more than once)

This is very likely a result of having "always_bcc" enabled on both sides of
the content filter.  So while "recipient_bcc_maps" is generally a better way
to archive email than "always_bcc", if it is "always_bcc" you have for now,
then you should indeed enable it only on the far side of the content filter,
which amounts to:

   -o receive_override_options=no_address_mappings

in master.cf for the smtpd(8) service that accepts the original message
for handing off to amavis.  This should generate new BCC messages with
just one instance of the BCC recipient.  Post log observations for those,
and any relevant tcpdump data (for just one extracted TCP session that
fails, not everything that comes off the wire at the time).

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Niclas Rautenhaus
In reply to this post by Niclas Rautenhaus

> One thing that is interesting is that the message generates two BCC
> copies with the *same* recipient address:

This is *only* the case with mails that later get deferred. Messages that are sucessfully sent to the appliance that archives the mails are only logged once, with the status "sent" obviously.
The recipients address in this and all other cases is always the appliances address ([hidden email]) . The "real" recipients never appear as a duplicate.

> Perhaps the appliance mishandles messages with duplicate recipient addresses?

Could you please specify what you mean?

> Is there any correlation between messages that repeatedly fail and messages
> that have a duplicate recipient?  Is the same feature observed in successful
> archive deliveries?

There is no correlation I am able to see yet, I guess that I have to take a more detailed look at the logfiles.
But the behaviour sometimes is erratic, when I send two mails for test purposes, to the same recipient, one mail gets deferred and the other is archived just fine.
The issue affects both incoming and outgoing messages, with both single and multiple recipients. A pattern or a link between these mails still needs to be found (and deducted from the logs)

> Note also that for this to be a meaningful mail archive, you should lose the
> original envelope recipient addresses (which happens with always_bcc) and
> instead use a recipe based on "recipient_bcc_maps" with regular expression
> mappings that capture each unique recipient as a unique archive recipient
> address.

I did already state this in the original post:
I followed the instructions that the manufacturer of the appliance states on its website
1) Modify the transport_maps and include "mailarchive.local smtp:[192.168.1.30]:1025"  - adapted of course
2) In the master.cf include "always_bcc = [hidden email]"

Rehash, reload, add options to the main.cf if not already present and everything should be set and working fine - according to the manufacturer of the appliance.
I already had contact to the company of the software as well, they just stated that no issues are know regarding this matter. (They got similar logs from me).

As I could already rule out the filters and the MTU being an issue, there root cause apparently must be hidden elsewhere.

I will continue searching for the link that connects the mails being duplicated and thus not sent.

Regards,
Niclas


________________________________________
Von: [hidden email] [[hidden email]]&quot; im Auftrag von &quot;Viktor Dukhovni [[hidden email]]
Gesendet: Montag, 5. Februar 2018 21:16
An: Postfix users
Betreff: [MASSMAIL]Re: Duplicate mails in mailq / always_bcc

> On Feb 5, 2018, at 3:00 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
> I did not change anything that I am not able to revert back to it's original settings.
> I am not "blindly trying random changes" but implementing suggestions being made in this
> thread and / or I found elsewhere online when I searched for keywords like "postfix",
> "always_bcc", "content_filter" etc.

Sadly, none of those things are immediately plausible work-arounds or
get you closer to isolating the problem.  At this time just collect
sufficient logs and network captures to distinguish between the failure
and success cases.

> For the sake of keeping this mail readable, please refer to this link
> (https://pastebin.com/nUz5BEdB) , there you will find an excerpt of the
> maillog from two mails stuck in the queue.

One thing that is interesting is that the message generates two BCC
copies with the *same* recipient address:

   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
     relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
     status=deferred (lost connection with 192.168.1.23[192.168.1.23]
     while sending end of data -- message may be sent more than once)

   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
    relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
    status=deferred (lost connection with 192.168.1.23[192.168.1.23]
    while sending end of data -- message may be sent more than once)

   Feb 5 17:28:52 mail postfix/smtp[22773]: 363BD601EE: to=<[hidden email]>,
     relay=smtp.ext-hoster.tld[XX.XXX.XXX.XXX]:25, delay=1.1, delays=0.01/0/0.24/0.8, dsn=2.0.0,
     status=sent (250 2.0.0 queued as V03a1fu15GSpL0R)

Perhaps the appliance mishandles messages with duplicate recipient addresses?
Is there any correlation between messages that repeatedly fail and messages
that have a duplicate recipient?  Is the same feature observed in successful
archive deliveries?

Note also that for this to be a meaningful mail archive, you should lose the
original envelope recipient addresses (which happens with always_bcc) and
instead use a recipe based on "recipient_bcc_maps" with regular expression
mappings that capture each unique recipient as a unique archive recipient
address.

--
        Viktor.


Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Niclas Rautenhaus
In reply to this post by Niclas Rautenhaus



> f it is "always_bcc" you have for now,
> then you should indeed enable it only on the far side of the content filter,
> which amounts to:
>
>  -o receive_override_options=no_address_mappings

This was one of the things I already tried without resolving the issue, as stated in my feedback mail:

> 6) Added the following entry to the master.cf
> smtp      inet  n       -       -       -       -       smtpd
>         -o content_filter=spamassassin
> ->>         -o receive_override_options=no_address_mappings






________________________________________
Von: [hidden email] [[hidden email]]&quot; im Auftrag von &quot;Viktor Dukhovni [[hidden email]]
Gesendet: Montag, 5. Februar 2018 21:59
An: Postfix users
Betreff: [MASSMAIL]Re: Duplicate mails in mailq / always_bcc

> On Feb 5, 2018, at 3:16 PM, Viktor Dukhovni <[hidden email]> wrote:
>
> One thing that is interesting is that the message generates two BCC
> copies with the *same* recipient address:
>
>   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
>     relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
>     status=deferred (lost connection with 192.168.1.23[192.168.1.23]
>     while sending end of data -- message may be sent more than once)
>
>   Feb 5 17:28:51 mail postfix/smtp[22771]: 363BD601EE: to=<[hidden email]>,
>    relay=192.168.1.23[192.168.1.23]:1025, delay=0.1, delays=0.01/0/0.04/0.04, dsn=4.4.2,
>    status=deferred (lost connection with 192.168.1.23[192.168.1.23]
>    while sending end of data -- message may be sent more than once)

This is very likely a result of having "always_bcc" enabled on both sides of
the content filter.  So while "recipient_bcc_maps" is generally a better way
to archive email than "always_bcc", if it is "always_bcc" you have for now,
then you should indeed enable it only on the far side of the content filter,
which amounts to:

   -o receive_override_options=no_address_mappings

in master.cf for the smtpd(8) service that accepts the original message
for handing off to amavis.  This should generate new BCC messages with
just one instance of the BCC recipient.  Post log observations for those,
and any relevant tcpdump data (for just one extracted TCP session that
fails, not everything that comes off the wire at the time).

--
        Viktor.


Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni
In reply to this post by Niclas Rautenhaus


> On Feb 5, 2018, at 4:28 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
>> One thing that is interesting is that the message generates two BCC
>> copies with the *same* recipient address:
>
> This is *only* the case with mails that later get deferred. Messages that are sucessfully sent to the appliance that archives the mails are only logged once, with the status "sent" obviously.
> The recipients address in this and all other cases is always the appliances address ([hidden email]) . The "real" recipients never appear as a duplicate.

You elided the log entries that show that the message to the archive had
two identical recipients in the same delivery attempt.  It is difficult to
discuss this if you trim the data under discussion.

With "always_bcc", and without "receive_override_options=no_address_mappings"
the bcc processing happens twice, once on either side of the content_filter.
An original message with a single recipient then ends up having three recipients,
one the original recipient, and two that are the BCC address.  This is what your
logs show.

My question is whether the delivery failures are also observed when there's only
one BCC recipient.  Despite whatever perceptions you may have of my tone, which
is a consequence of limited time, not disrespect, please take the time to read my
posts *carefully*, and follow the suggestions posting the requested results.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Duplicate mails in mailq / always_bcc

Viktor Dukhovni
In reply to this post by Niclas Rautenhaus


> On Feb 5, 2018, at 4:38 PM, Niclas Rautenhaus <[hidden email]> wrote:
>
> This was one of the things I already tried without resolving the issue, as stated in my feedback mai

Show evidence of this in logs.  The resulting messages should have only one
archive recipient.  Are these also deferred.  Also, show logs of messages to
the archive that are not deferred.  And of course the tcpdump output on-list
or PCAP file off-list.

--
        Viktor.