Fw: Crazy retries for bounced (and a small number of successful) emails

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

Fw: Crazy retries for bounced (and a small number of successful) emails

Bob Jones



Our mail server (kolab 16 with postfix) has gone into a loop of some kind leading to constant retrying of bounced emails.


Here is a segment of what I see in the maillog:

Jan 12 00:36:14 mail postfix/discard[3091]: warning: unexpected attribute nrequest from bounce socket (expecting: flags)
Jan 12 00:36:14 mail postfix/discard[3091]: warning: deliver_request_get: error receiving common attributes
Jan 12 00:36:14 mail postfix/smtp[3090]: 5937C8DFA2: to=<[hidden email]>, relay=mx01.mail.icloud.com[17.56.9.17]:25, delay=25, delays=25/0/0.28/0, dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552 of server mx01.mail.icloud.com[17.56.9.17])
Jan 12 00:36:14 mail postfix/qmgr[1569]: 5937C8DFA2: removed
Jan 12 00:36:16 mail postfix/smtpd[3068]: connect from xxx[127.0.0.1]
Jan 12 00:36:16 mail postfix/smtpd[3068]: 636058DFA2: client=xxx[127.0.0.1]
Jan 12 00:36:18 mail postfix/cleanup[3071]: 636058DFA2: message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan 12 00:36:23 mail ctl_cyrusdb[3097]: checkpointing cyrus databases
Jan 12 00:36:23 mail ctl_cyrusdb[3097]: done checkpointing cyrus databases
Jan 12 00:36:31 mail clamd[1187]: SelfCheck: Database status OK.
Jan 12 00:36:40 mail opendkim[1181]: 636058DFA2: DKIM-Signature field added (s=20201004, d=xxx)
Jan 12 00:36:40 mail postfix/qmgr[1569]: 636058DFA2: from=<support@xxx>, size=35379321, nrcpt=1 (queue active)
Jan 12 00:36:40 mail postfix/smtpd[3068]: disconnect from xxx[127.0.0.1]
Jan 12 00:36:41 mail postfix/discard[3091]: warning: unexpected attribute nrequest from bounce socket (expecting: flags)
Jan 12 00:36:41 mail postfix/discard[3091]: warning: deliver_request_get: error receiving common attributes
Jan 12 00:36:41 mail postfix/smtp[3090]: 636058DFA2: to=<[hidden email]>, relay=mx02.mail.icloud.com[17.42.251.12]:25, delay=25, delays=25/0.01/0.67/0, dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552 of server mx02.mail.icloud.com[17.42.251.12])
Jan 12 00:36:41 mail postfix/qmgr[1569]: 636058DFA2: removed

Here the email is going out to a user in icloud.com domain. The email bounces with message size exceeding limit. Yet the server keeps on attempting to deliver the message.

Oddly, there is another email that goes out repeatedly as well, even though it is successful in delivering to the target domain. (the email is a couple of weeks old and they are going crazy about these emails appearing every minute or so).

We have tried changing various settings to no avail:
maximal_queue_lifetime = 0
bounce_queue_lifetime = 0
minimal_backoff_time = 6h
maximal_backoff_time = 6h
queue_run_delay = 6h

We receive and send other emails just fine.

What could be going wrong? Thanks in advance.
Reply | Threaded
Open this post in threaded view
|

Re: Fw: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 01:10:56AM +0000, Bob Jones wrote:

> Our mail server (kolab 16 with postfix) has gone into a loop of some
> kind leading to constant retrying of bounced emails.

Your master.cf file is botched, listing an invalid definition of the
"bounce" service.  You CANNOT replace the "bounce" service with the
"discard" delivery agent.

> Here is a segment of what I see in the maillog:
>
> Jan 12 00:36:14 mail postfix/discard[3091]: warning: unexpected attribute nrequest from bounce socket (expecting: flags)
> Jan 12 00:36:14 mail postfix/discard[3091]: warning: deliver_request_get: error receiving common attributes

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

Re: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
You are absolutely right about the master.cf. The bounce line looks like the following:
bounce              unix        -       -       n       -       0       discard

What is a good configuration for this? Also, what does all this mean essentially (in English)?






On Monday, January 11, 2021, 5:40:51 PM PST, Viktor Dukhovni <[hidden email]> wrote:





On Tue, Jan 12, 2021 at 01:10:56AM +0000, Bob Jones wrote:

> Our mail server (kolab 16 with postfix) has gone into a loop of some
> kind leading to constant retrying of bounced emails.

Your master.cf file is botched, listing an invalid definition of the
"bounce" service.  You CANNOT replace the "bounce" service with the
"discard" delivery agent.


> Here is a segment of what I see in the maillog:
>
> Jan 12 00:36:14 mail postfix/discard[3091]: warning: unexpected attribute nrequest from bounce socket (expecting: flags)
> Jan 12 00:36:14 mail postfix/discard[3091]: warning: deliver_request_get: error receiving common attributes


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

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 02:49:38AM +0000, Bob Jones wrote:

> You are absolutely right about the master.cf. The bounce line looks like the following:
>
> bounce              unix        -       -       n       -       0       discard

That is an invalid configuration.  Nowhere is it documented that you can
drop bounces by setting "discard" to be your "bounce" service program.
The "bounce" service is not a mail delivery transport, and its role
cannot be fulfilled by a delivery agent (discard, error, retry, smtp,
lmtp, local, virtual, pipe) program.

> What is a good configuration for this?

The only valid setting for this and related services is the stock one
that comes with Postfix:

    bounce    unix  -       -       n       -       0       bounce
    defer     unix  -       -       n       -       0       bounce
    trace     unix  -       -       n       -       0       bounce

Similarly, you can't replace "qmgr" with "tlsmgr", "flush" with
"cleanup", "smtpd" with "pickup", ...

> Also, what does all this mean essentially (in English)?

The glib/concise answer is that you shouldn't just invent plausible
looking configurations, that are not documented to do what you might
hope they'll do. :-)

The long answer is that "bounce" is not a delivery process, rather
it orchestrates non-delivery message generation, and submits these
for processing by real delivery agents.  It is a core serice for
which is there is no documented replacement.

Also, you should not be trying to discard bounces.

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

Re: Crazy retries for bounced (and a small number of successful) emails

Bill Cole-3
In reply to this post by Bob Jones
On 11 Jan 2021, at 21:49, Bob Jones wrote:

> Also, what does all this mean essentially (in English)?

The man page for master(5) is written in English and provides a standard
answer. Is there something unclear there?

--
Bill Cole
[hidden email] or [hidden email]
(AKA @grumpybozo and many *@billmail.scconsult.com addresses)
Not Currently Available For Hire
Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Mon, Jan 11, 2021 at 11:48:25PM -0500, Bill Cole wrote:
> On 11 Jan 2021, at 21:49, Bob Jones wrote:
>
> > Also, what does all this mean essentially (in English)?
>
> The man page for master(5) is written in English and provides a standard
> answer. Is there something unclear there?

That's much too glib, somewhat bordering on just rude. :-(  And not even
directly relevant, there's no mention of bounce, discard, ... there, nor
even mention of delivery agents.  It is just master.cf *syntax*.

A much better reference is:

    http://www.postfix.org/OVERVIEW.html

which does go over the roles of the various components.

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
I changed the last column in bounce line to bounce (it used to be discard)
in master.cf.
Now I get NDRs every minute or so because of those retrying emails. What
next?

Here is my master.cf:

# Postfix master process configuration file.  For details on the format
# of the file, see the master(5) manual page (command: "man 5 master").
# Do not forget to execute "postfix reload" after editing this file.
#
============================================================================
==
# service           type  private   unpriv  chroot  wakeup  maxproc
command
#                           (yes)    (yes)   (yes)   (never) (100)       +
args
#
============================================================================
==
smtp                inet        n       -       n       -       -
smtpd
#smtp               inet        n       -       n       -       1
postscreen
#smtpd              pass        -       -       n       -       -
smtpd
#dnsblog            unix        -       -       n       -       0
dnsblog
#tlsproxy           unix        -       -       n       -       0
tlsproxy
submission          inet        n       -       n       -       -
smtpd
    -o cleanup_service_name=cleanup_submission
    -o syslog_name=postfix/submission
    -o smtpd_tls_security_level=encrypt
    -o smtpd_sasl_auth_enable=yes
    -o smtpd_sasl_authenticated_header=yes
    -o smtpd_client_restrictions=permit_sasl_authenticated,reject
    -o smtpd_data_restrictions=$submission_data_restrictions
    -o smtpd_recipient_restrictions=$submission_recipient_restrictions
    -o smtpd_sender_restrictions=$submission_sender_restrictions

#smtps               inet        n       -       n       -       -
smtpd
#    -o syslog_name=postfix/smtps
#    -o smtpd_tls_wrappermode=yes
#    -o smtpd_sasl_auth_enable=yes
#    -o smtpd_client_restrictions=permit_sasl_authenticated,reject
#    -o milter_macro_daemon_name=ORIGINATING
#628                inet        n       -       n       -       -
qmqpd
pickup              fifo        n       -       n       60      1
pickup
cleanup             unix        n       -       n       -       0
cleanup
    -o header_checks=regexp:/etc/postfix/header_checks.inbound
    -o mime_header_checks=regexp:/etc/postfix/header_checks.inbound
cleanup_internal    unix        n       -       n       -       0
cleanup
    -o header_checks=regexp:/etc/postfix/header_checks.internal
    -o mime_header_checks=regexp:/etc/postfix/header_checks.internal
cleanup_submission  unix        n       -       n       -       0
cleanup
    -o header_checks=regexp:/etc/postfix/header_checks.submission
    -o mime_header_checks=regexp:/etc/postfix/header_checks.submission
qmgr                fifo        n       -       n       300     1       qmgr
#qmgr               fifo        n       -       n       300     1
oqmgr
tlsmgr              unix        -       -       n       1000?   1
tlsmgr
rewrite             unix        -       -       n       -       -
trivial-rewrite
bounce              unix        -       -       n       -       0
bounce
defer               unix        -       -       n       -       0
bounce
trace               unix        -       -       n       -       0
bounce
verify              unix        -       -       n       -       1
verify
flush               unix        n       -       n       1000?   0
flush
proxymap            unix        -       -       n       -       -
proxymap
proxywrite          unix        -       -       n       -       1
proxymap
smtp                unix        -       -       n       -       -       smtp
relay               unix        -       -       n       -       -       smtp
showq               unix        n       -       n       -       -
showq
error               unix        -       -       n       -       -
error
retry               unix        -       -       n       -       -
error
discard             unix        -       -       n       -       -
discard
local               unix        -       n       n       -       -
local
virtual             unix        -       n       n       -       -
virtual
lmtp                unix        -       -       n       -       -       lmtp
anvil               unix        -       -       n       -       1
anvil
scache              unix        -       -       n       -       1
scache

# Filter email through Amavisd
smtp-amavis         unix        -       -       n       -       3       smtp
    -o smtp_data_done_timeout=1800
    -o disable_dns_lookups=yes
    -o smtp_send_xforward_command=yes
    -o max_use=20
    -o smtp_bind_address=127.0.0.1

# Listener to re-inject email from Amavisd into Postfix
127.0.0.1:10025     inet        n       -       n       -       100
smtpd
    -o cleanup_service_name=cleanup_internal
    -o content_filter=smtp-wallace:[127.0.0.1]:10026
    -o local_recipient_maps=
    -o relay_recipient_maps=
    -o smtpd_restriction_classes=
    -o smtpd_client_restrictions=
    -o smtpd_helo_restrictions=
    -o smtpd_sender_restrictions=
    -o smtpd_recipient_restrictions=permit_mynetworks,reject
    -o mynetworks=127.0.0.0/8
    -o smtpd_authorized_xforward_hosts=127.0.0.0/8

# Filter email through Wallace
smtp-wallace        unix        -       -       n       -       3       smtp
    -o default_destination_recipient_limit=1
    -o smtp_data_done_timeout=1800
    -o disable_dns_lookups=yes
    -o smtp_send_xforward_command=yes
    -o max_use=20

# Listener to re-inject email from Wallace into Postfix
127.0.0.1:10027     inet        n       -       n       -       100
smtpd
    -o cleanup_service_name=cleanup_internal
    -o content_filter=
    -o local_recipient_maps=
    -o relay_recipient_maps=
    -o smtpd_restriction_classes=
    -o smtpd_client_restrictions=
    -o smtpd_helo_restrictions=
    -o smtpd_sender_restrictions=
    -o smtpd_recipient_restrictions=permit_mynetworks,reject
    -o mynetworks=127.0.0.0/8
    -o smtpd_authorized_xforward_hosts=127.0.0.0/8

recipient_policy    unix        -       n       n       -       -
spawn
    user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy
--verify-recipient

recipient_policy_incoming unix  -       n       n       -       -
spawn
    user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy
--verify-recipient --allow-unauthenticated

sender_policy       unix        -       n       n       -       -
spawn
    user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy
--verify-sender

sender_policy_incoming unix     -       n       n       -       -
spawn
    user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy
--verify-sender --allow-unauthenticated

submission_policy   unix        -       n       n       -       -
spawn
    user=kolab-n argv=/usr/libexec/postfix/kolab_smtp_access_policy
--verify-sender --verify-recipient


-----Original Message-----
From: [hidden email] <[hidden email]> On
Behalf Of Viktor Dukhovni
Sent: Monday, January 11, 2021 8:56 PM
To: [hidden email]
Subject: Re: Crazy retries for bounced (and a small number of successful)
emails

On Mon, Jan 11, 2021 at 11:48:25PM -0500, Bill Cole wrote:
> On 11 Jan 2021, at 21:49, Bob Jones wrote:
>
> > Also, what does all this mean essentially (in English)?
>
> The man page for master(5) is written in English and provides a
> standard answer. Is there something unclear there?

That's much too glib, somewhat bordering on just rude. :-(  And not even
directly relevant, there's no mention of bounce, discard, ... there, nor
even mention of delivery agents.  It is just master.cf *syntax*.

A much better reference is:

    http://www.postfix.org/OVERVIEW.html

which does go over the roles of the various components.

--
    Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Mon, Jan 11, 2021 at 09:59:36PM -0800, [hidden email] wrote:

> I changed the last column in bounce line to bounce (it used to be
> discard) in master.cf.

Once your master.cf file is correct, it is no longer of much
interest.  What matters now is logs and main.cf.

> Now I get NDRs every minute or so because of those retrying emails. What
> next?

Once the notifications are sent, the associated message is deleted from
the queue.  If you're not generating new bounces every minute, the
volume will dissipate.  If you're generating a lot of bounces, that's
the problem to solve, i.e. the *generating* part.  Instead of working
on throwing them away, find out why you have a high bounce rate and
fix that.

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
>Once your master.cf file is correct, it is no longer of much interest.
What matters now is logs and main.cf.

Here is what I see now with the same email going out again and again:

Jan 12 17:56:26 mail postfix/smtpd[17788]: connect from xxx[127.0.0.1]
Jan 12 17:56:26 mail postfix/smtpd[17788]: AED108DFA2: client=xxx[127.0.0.1]
Jan 12 17:56:28 mail postfix/cleanup[17791]: AED108DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: from=<support@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan 12 17:56:51 mail postfix/smtpd[17788]: disconnect from xxx[127.0.0.1]
Jan 12 17:56:51 mail postfix/smtp[18159]: AED108DFA2: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25, delays=25/0.01/0.4/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx02.mail.icloud.com[17.57.152.14])
Jan 12 17:56:51 mail postfix/cleanup[17853]: A0E418DFA4:
message-id=<20210112175651.A0E418DFA4@xxx>
Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: from=<>, size=3867,
nrcpt=1 (queue active)
Jan 12 17:56:51 mail postfix/bounce[18161]: AED108DFA2: sender non-delivery
notification: A0E418DFA4
Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: removed

Jan 12 18:05:16 mail postfix/smtpd[18647]: disconnect from xxx[127.0.0.1]
Jan 12 18:05:17 mail postfix/smtp[18775]: 9BA7A8DFA2: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.56.9.17]:25, delay=25, delays=24/0.03/0.93/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx01.mail.icloud.com[17.56.9.17])
Jan 12 18:05:17 mail postfix/cleanup[18778]: D21298DFA4:
message-id=<20210112180517.D21298DFA4@xxx>
Jan 12 18:05:17 mail postfix/qmgr[4667]: D21298DFA4: from=<>, size=3863,
nrcpt=1 (queue active)
Jan 12 18:05:17 mail postfix/bounce[18777]: 9BA7A8DFA2: sender non-delivery
notification: D21298DFA4
Jan 12 18:05:17 mail postfix/qmgr[4667]: 9BA7A8DFA2: removed

>Once the notifications are sent, the associated message is deleted from the
queue.  If you're not generating new bounces every minute, the volume will
dissipate.  If you're generating a lot of bounces, that's the problem to
>solve, i.e. the *generating* part.  Instead of working on throwing them
away, find out why you have a high bounce rate and fix that.

I am not sure why the same emails are going out even with the non-delivery
reports. The clients are clearly not sending these. So, not sure what to
look for. Please note that all other emails are fine (incoming and
outgoing). It is just these emails that bounce that keep on getting resent.
(there are also a couple of internal emails being resent, as far as I can
tell from the logs, but those sends are successful yet keeps repeating)


Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 10:18:33AM -0800, [hidden email] wrote:

> Here is what I see now with the same email going out again and again:

The logs are rather a jumble, please collate the logs by queue-id,
avoiding mixing different messages together, and show all logs for
any queue-id that's relevant.

> Jan 12 17:56:26 mail postfix/smtpd[17788]: connect from xxx[127.0.0.1]
> Jan 12 17:56:26 mail postfix/smtpd[17788]: AED108DFA2: client=xxx[127.0.0.1]
> Jan 12 17:56:28 mail postfix/cleanup[17791]: AED108DFA2: message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan 12 17:56:51 mail postfix/smtpd[17788]: disconnect from xxx[127.0.0.1]
> Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: from=<support@xxx>, size=35379321, nrcpt=1 (queue active)
> Jan 12 17:56:51 mail postfix/smtp[18159]: AED108DFA2: to=<[hidden email]>, relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25, delays=25/0.01/0.4/0, dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552 of server mx02.mail.icloud.com[17.57.152.14])
> Jan 12 17:56:51 mail postfix/bounce[18161]: AED108DFA2: sender non-delivery notification: A0E418DFA4
> Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: removed

Where did this message come from?  The message-id is not generated by
Postfix (different format), and yet you're reporting 127.0.0.1 as
the source.  So where did this message originate?  This message bounced,
with the non-delivery queued as:

    AED108DFA2: sender non-delivery notification: A0E418DFA4

> Jan 12 17:56:51 mail postfix/cleanup[17853]: A0E418DFA4: message-id=<20210112175651.A0E418DFA4@xxx>
> Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: from=<>, size=3867, nrcpt=1 (queue active)

All you show for that is above.  Below is some other message that also
bounces:

> Jan 12 18:05:17 mail postfix/smtp[18775]: 9BA7A8DFA2: to=<[hidden email]>, relay=mx01.mail.icloud.com[17.56.9.17]:25, delay=25, delays=24/0.03/0.93/0, dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552 of server mx01.mail.icloud.com[17.56.9.17])
> Jan 12 18:05:17 mail postfix/bounce[18777]: 9BA7A8DFA2: sender non-delivery notification: D21298DFA4
> Jan 12 18:05:17 mail postfix/qmgr[4667]: 9BA7A8DFA2: removed

You also show fragementary logs for this bounce.

> Jan 12 18:05:17 mail postfix/cleanup[18778]: D21298DFA4: message-id=<20210112180517.D21298DFA4@xxx>
> Jan 12 18:05:17 mail postfix/qmgr[4667]: D21298DFA4: from=<>, size=3863, nrcpt=1 (queue active)

> I am not sure why the same emails are going out even with the non-delivery
> reports.

They are not "the same".  Is there a mail loop somewhere?  Are the
bounces delivered?  Do they elicit new responses?  The logs posted are
far from complete.  They don't even consistently show the message-ids.
See my "collate" program:

    https://github.com/vdukhovni/postfix/tree/master/postfix/auxiliary/collate

> The clients are clearly not sending these.

I don't see how you reached that conclusion.

> So, not sure what to look for. Please note that all other emails are
> fine (incoming and outgoing). It is just these emails that bounce that
> keep on getting resent.  (there are also a couple of internal emails
> being resent, as far as I can tell from the logs, but those sends are
> successful yet keeps repeating)

Nothing is "resent", new messages are showing up, bouncing and ...
(you don't show what happens with the bounces).

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
>The logs are rather a jumble, please collate the logs by queue-id, avoiding
mixing different messages together, and show all logs for any queue-id
that's relevant.

Here is the collated output from the script:


Jan 12 17:56:26 mail postfix/smtpd[17788]: connect from xxx[127.0.0.1]
Jan 12 17:56:26 mail postfix/smtpd[17788]: AED108DFA2: client=xxx[127.0.0.1]
Jan 12 17:56:28 mail postfix/cleanup[17791]: AED108DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: from=<xxx>,
size=35379321, nrcpt=1 (queue active)
Jan 12 17:56:51 mail postfix/smtpd[17788]: disconnect from xxx[127.0.0.1]
Jan 12 17:56:51 mail postfix/smtp[18159]: AED108DFA2: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25, delays=25/0.01/0.4/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx02.mail.icloud.com[17.57.152.14])
Jan 12 17:56:51 mail postfix/bounce[18161]: AED108DFA2: sender non-delivery
notification: A0E418DFA4
Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: removed

Jan 12 17:56:51 mail postfix/bounce[18161]: AED108DFA2: sender non-delivery
notification: A0E418DFA4
Jan 12 17:56:51 mail postfix/cleanup[17853]: A0E418DFA4:
message-id=<20210112175651.A0E418DFA4@xxx>
Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: from=<>, size=3867,
nrcpt=1 (queue active)
Jan 12 17:56:51 mail postfix/lmtp[17867]: A0E418DFA4: to=<xxx>,
orig_to=<xxx>, relay=xxx[/var/lib/imap/socket/lmtp], delay=0.05,
delays=0.01/0.02/0/0.02, dsn=2.1.5, status=sent (250 2.1.5 Ok
SESSIONID=<xxx-17946-1610474211-1-15717393109624973811>)
Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: removed

>Where did this message come from?  The message-id is not generated by
Postfix (different format), and yet you're reporting 127.0.0.1 as the
source.  So >where did this message originate?  This message bounced, with
the non-delivery queued as:
>    AED108DFA2: sender non-delivery notification: A0E418DFA4

I guess this the big question. The source is reported as 127.0.0.1 for these
messages. For regular outgoing mail, I see an additional orig_client for
this line showing the ip of the client. But these emails do not have that.

>They are not "the same".  Is there a mail loop somewhere?  Are the bounces
delivered?  Do they elicit new responses?  The logs posted are far from
>complete.  They don't even consistently show the message-ids.

They are the same in the sense that the content of the email is exactly
same. I understand what you mean by not the same, because it looks like
somehow another email of the same content is being submitted.

> The clients are clearly not sending these.
>I don't see how you reached that conclusion.

I know the clients are not doing this because these emails are not in client
outboxes nor do they show up with the client ip address when submitted to
server. I have also shut down the client that was the original sender of
this email weeks back with no effect.

> So, not sure what to look for. Please note that all other emails are
> fine (incoming and outgoing). It is just these emails that bounce that
> keep on getting resent.  (there are also a couple of internal emails
> being resent, as far as I can tell from the logs, but those sends are
> successful yet keeps repeating)

>Nothing is "resent", new messages are showing up, bouncing and ...
>(you don't show what happens with the bounces).

The bounces are ordinary. Here is one seen on the client:

------------------------------
This is the mail system at host xxx.

I'm sorry to have to inform you that your message could not be delivered to
one or more recipients. It's attached below.

For further assistance, please send mail to postmaster.

If you do so, please include this problem report. You can delete your own
text from the attached returned message.

                   The mail system

<[hidden email]>: message size 35379321 exceeds size limit 28311552 of
    server mx01.mail.icloud.com[17.56.9.17]
-----------------------------------

The details.txt attachment in the bounce shows the following:

-----------------------------------------------------
Reporting-MTA: dns; xxx
X-Postfix-Queue-ID: 528F8C5AC4
X-Postfix-Sender: rfc822; xxx
Arrival-Date: Tue, 12 Jan 2021 19:58:22 +0000 (UTC)

Final-Recipient: rfc822; [hidden email]
Original-Recipient: rfc822;[hidden email]
Action: failed
Status: 5.3.4
Diagnostic-Code: X-Postfix; message size 35379321 exceeds size limit
28311552
    of server mx01.mail.icloud.com[17.56.9.17]
-----------------------------------------------------------

It appears to be a loop somewhere. One bit I have since discovered is that
each of these emails (that are either succeeding in delivering to
destination address or bouncing from the destination) had bounced at some
point in the past. If this is the basis for the behavior, I would like to
think that perhaps a loop of some sort occurs on the first bounce of any
outgoing/internal email.

Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 12:36:58PM -0800, [hidden email] wrote:

> Jan 12 17:56:26 mail postfix/smtpd[17788]: connect from xxx[127.0.0.1]
> Jan 12 17:56:26 mail postfix/smtpd[17788]: AED108DFA2: client=xxx[127.0.0.1]
> Jan 12 17:56:28 mail postfix/cleanup[17791]: AED108DFA2: message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: from=<xxx>, size=35379321, nrcpt=1 (queue active)
> Jan 12 17:56:51 mail postfix/smtpd[17788]: disconnect from xxx[127.0.0.1]
> Jan 12 17:56:51 mail postfix/smtp[18159]: AED108DFA2: to=<[hidden email]>, relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25, delays=25/0.01/0.4/0, dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552 of server mx02.mail.icloud.com[17.57.152.14])
> Jan 12 17:56:51 mail postfix/bounce[18161]: AED108DFA2: sender non-delivery notification: A0E418DFA4
> Jan 12 17:56:51 mail postfix/qmgr[4667]: AED108DFA2: removed

The message was created by something other than local submission, since
it arrived via SMTP to 127.0.0.1.

> Jan 12 17:56:51 mail postfix/cleanup[17853]: A0E418DFA4: message-id=<20210112175651.A0E418DFA4@xxx>
> Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: from=<>, size=3867, nrcpt=1 (queue active)
> Jan 12 17:56:51 mail postfix/lmtp[17867]: A0E418DFA4: to=<xxx>, orig_to=<xxx>, relay=xxx[/var/lib/imap/socket/lmtp], delay=0.05,
> delays=0.01/0.02/0/0.02, dsn=2.1.5, status=sent (250 2.1.5 Ok SESSIONID=<xxx-17946-1610474211-1-15717393109624973811>)
> Jan 12 17:56:51 mail postfix/qmgr[4667]: A0E418DFA4: removed

The bounce is delivered to via LMTP, perhaps to a mailbox, so the
message has a local sender?

> The bounces are ordinary. Here is one seen on the client:

You're showing only the irrelevant portion of the bounce. What
matters is the full headers of the returned message.

> -----------------------------------------------------
> Reporting-MTA: dns; xxx
> X-Postfix-Queue-ID: 528F8C5AC4
> X-Postfix-Sender: rfc822; xxx
> Arrival-Date: Tue, 12 Jan 2021 19:58:22 +0000 (UTC)
>
> Final-Recipient: rfc822; [hidden email]
> Original-Recipient: rfc822;[hidden email]
> Action: failed
> Status: 5.3.4
> Diagnostic-Code: X-Postfix; message size 35379321 exceeds size limit 28311552 of server mx01.mail.icloud.com[17.56.9.17]
> -----------------------------------------------------------

The third part of the message is the content, which will have
the full set of "Received" headers that show how the message
got to the point at which it bounced.

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
> The message was created by something other than local submission, since it
arrived via SMTP to 127.0.0.1.

You are perhaps right. The message id appears to be same for this
problematic email (i.e. for every attempt to deliver this email to
[hidden email] the message id is 2f18001d6e499$48eeff40$daccfdc0$@xxx).
There are 2 other emails that are getting constantly retried with success
and NDR (respectively) as well and the message id does not change from
attempt to attempt.

I would guess that this was the message id generated by the original email
client.

What might be going wrong here?

>You're showing only the irrelevant portion of the bounce. What matters is
the full headers of the returned message.

Here are the mail headers of the non-delivery email:
-------------------------------

Return-Path: <>
Received: from xxx ([unix socket])
         by xxx (Cyrus
2.5.15-28-g7d1550bfa-Kolab-2.5.15.28-1.16.el7.kolab_16) with LMTPA;
         Tue, 12 Jan 2021 20:50:11 +0000
X-Sieve: CMU Sieve 2.4
Received: by xxx (Postfix)
        id E78E48DFA4; Tue, 12 Jan 2021 20:50:11 +0000 (UTC)
Date: Tue, 12 Jan 2021 20:50:11 +0000 (UTC)
From: MAILER-DAEMON@xxx (Mail Delivery System)
Subject: Undelivered Mail Returned to Sender
To: xxx
Auto-Submitted: auto-replied
MIME-Version: 1.0
Content-Type: multipart/report; report-type=delivery-status;
        boundary="571528DFA2.1610484611/xxx"
Message-Id: <20210112205011.E78E48DFA4@xxx>
-----------------------------------------------

>The third part of the message is the content, which will have the full set
of "Received" headers that show how the message got to the point at which it
>bounced.

Here is what is in Undelivered Message Headers.txt

--------------------------------------------------------
Return-Path: <xxx>
X-Virus-Scanned: amavisd-new at xxx
DKIM-Filter: OpenDKIM Filter v2.11.0 xxx 571528DFA2
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=xxx;
        s=202xxx4; t=1610xxx9;
        bh=D1Mnjy211JSi+7Gw2IHLfCuXjOXR1Ecwt0pY0n1yzig=;
        h=From:To:References:In-Reply-To:Subject:Date:From;
        b=c6EV2/sY1vVJmJA8AL97aUG3E4JcTfCLrPA/sBsWYJRRVEIW9L+jW9qOlOOAAfu3M
         /KSHNwazr1i7ReT8LX+/tzduN13PzyJ0T/4rfyrnXhQ64HrNxfYYPD/DZSMNJQ7TyH
         XQ1FcadR7g6cp+U6nSELaezqUFJjhk+fMmS43AyrCrijCyZKPsmpxKmJNpCgIIlf6Z
         GXL8c2iZaS+1onOQhMC5dV+J3veoZdX8kH7h0PtYewPOFIX35ye8TOHrvgayZiZUs/
         YpQ5LASbA91h2L95tQ3fVkd058bPLMwnHZdB5q08vuC0DmLC3rK6NZRpa1UidkwsnF
         WIlGSbw5Xfmew==
DKIM-Filter: OpenDKIM Filter v2.11.0 xxx 9AE9C281
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=xxx;
 s=2020xxxx; t=16099xxxxx;
 bh=D1Mnjy211JSi+7Gw2IHLfCuXjOXR1Ecwt0pY0n1yzig=;
 h=From:To:References:In-Reply-To:Subject:Date:From;
 b=AGQGDSbgN7VFixbZFb8nyXfcTxkVNBQiLDszb37BD++pEBupuvIYw7qiUZmrOc4ay
 zPqGs/zwB9g5t9BWCCcI8+Ddu6pNYjs+Eq1/EHVeHbLf5+6eqWVlQyplqRn9rCxJL9
 +MeM67AnXWbx12WK4TZcsaNrtnRxUwO5DT9oVaeApl0JSYcR+4HJmaKFx+g88svXK5
 ienchwlIzfXL12T8vABa2a3RRw91rTBZ+SiK4K7gO0aCClbPn9G0JrXkx0tParoxVc
 W4onwQeV7Dnhj9Uqepsxmp9F3nHXaRfrLNOTH3bt/W1nvVxGyPA0UiGAZvtyWG9Vak
 Qo/1PtaFIOHdQ==
From: <xxx>
To: "'yyy zzz'" <[hidden email]>
References: <[hidden email]>
In-Reply-To: <[hidden email]>
Subject: RE: XXX
Date: Wed, 6 Jan 2021 18:03:24 -0800
Message-ID: <2f18001d6e499$48eeff40$daccfdc0$@xxx>
MIME-Version: 1.0
Content-Type: multipart/mixed;
 boundary="----=_NextPart_000_2F181_01D6E456.3ACC8290"
Content-Language: en-us
----------------------------------------------
Thread-Index: AQKkAI6o4zpXvsvRdcbl2BfmNJLnZKiBLOog

Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 01:17:34PM -0800, [hidden email] wrote:
> > The message was created by something other than local submission, since it
> arrived via SMTP to 127.0.0.1.

> Here are the mail headers of the non-delivery email:
> -------------------------------
>
> Return-Path: <>
> Received: from xxx ([unix socket])
> by xxx (Cyrus 2.5.15-28-g7d1550bfa-Kolab-2.5.15.28-1.16.el7.kolab_16) with LMTPA;
> Tue, 12 Jan 2021 20:50:11 +0000
> X-Sieve: CMU Sieve 2.4
> Received: by xxx (Postfix)
> id E78E48DFA4; Tue, 12 Jan 2021 20:50:11 +0000 (UTC)

Bounce received on the 12th of January.

> Here is what is in Undelivered Message Headers.txt
>
> Return-Path: <xxx>
> X-Virus-Scanned: amavisd-new at xxx
> DKIM-Filter: OpenDKIM Filter v2.11.0 xxx 571528DFA2
> DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=xxx;
> s=202xxx4; t=1610xxx9;
> bh=D1Mnjy211JSi+7Gw2IHLfCuXjOXR1Ecwt0pY0n1yzig=;
> h=From:To:References:In-Reply-To:Subject:Date:From;
> b=...
> DKIM-Filter: OpenDKIM Filter v2.11.0 xxx 9AE9C281
> DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=xxx;
>  s=2020xxxx; t=16099xxxxx;
>  bh=D1Mnjy211JSi+7Gw2IHLfCuXjOXR1Ecwt0pY0n1yzig=;
>  h=From:To:References:In-Reply-To:Subject:Date:From;
>  b=...
> From: <xxx>
> To: "'yyy zzz'" <[hidden email]>
> References: <[hidden email]>
> In-Reply-To: <[hidden email]>
> Subject: RE: XXX
> Date: Wed, 6 Jan 2021 18:03:24 -0800
> Message-ID: <2f18001d6e499$48eeff40$daccfdc0$@xxx>
> MIME-Version: 1.0
> Content-Type: multipart/mixed;
>  boundary="----=_NextPart_000_2F181_01D6E456.3ACC8290"
> Content-Language: en-us
> Thread-Index: AQKkAI6o4zpXvsvRdcbl2BfmNJLnZKiBLOog

There are no "Received:" headers here, are you sure you've posted *all*
the headers?  All messages received by Postfix get a "Received" header
prepended.  Where are they?  However, we do see that the message went
through Amavis, so ypu should have logs for that... and ideally for how
it got into Amavis as well.

It appears to be a reply to a message from icloud, sent on Jan 6th, so
delayed by 6 days.  But that delay could well be a result of the
master.cf breakage.

What's in your logs for "2f18001d6e499$48eeff40$daccfdc0$@xxx"
on "Wed, 6 Jan 2021 18:03:24 -0800"?  (With "grep" and the
like escape the '$' characters your just search for '.' instead.

You seem to be double-signing messages, before and after Amavis
perhaps?  Once is likely enough.

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
>There are no "Received:" headers here, are you sure you've posted *all* the
headers?  All messages received by Postfix get a "Received" header
prepended.  Where are they?  However, we do see that the message went
through >Amavis, so ypu should have logs for that... and ideally for how it
got into Amavis as well.

There is a Received header in the NDR email headers, look for it in the
paste above the one you looked at.

>It appears to be a reply to a message from icloud, sent on Jan 6th, so
delayed by 6 days.  But that delay could well be a result of the master.cf
breakage.
Correct. The delay is because the email has been bouncing since the message
size was too big for the recipient's server.

>What's in your logs for "2f18001d6e499$48eeff40$daccfdc0$@xxx"
>on "Wed, 6 Jan 2021 18:03:24 -0800"?  (With "grep" and the like escape the
'$' characters your just search for '.' instead.

Here is where I see the first send of this message (based on the message
id):

-----------------------------------------------------------------
Jan  7 02:03:25 mail postfix/submission/smtpd[23109]: connect from
c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
Jan  7 02:03:26 mail postfix/submission/smtpd[23109]: 09E898DFA2:
client=c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44], sasl_method=LOGIN,
sasl_username=yyy@xxx
Jan  7 02:03:26 mail postfix/cleanup[23314]: 09E898DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:04:17 mail postfix/qmgr[1576]: 09E898DFA2: from=<yyy@xxx>,
size=35378641, nrcpt=1 (queue active)
Jan  7 02:04:19 mail postfix/submission/smtpd[23109]: disconnect from
c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
Jan  7 02:04:56 mail postfix/smtp[23322]: 09E898DFA2: to=<[hidden email]>,
relay=127.0.0.1[127.0.0.1]:10024, delay=91, delays=52/0.03/0.01/39,
dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
2.0.0 Ok: queued as 9AE9C281)
Jan  7 02:04:56 mail postfix/qmgr[1576]: 09E898DFA2: removed

Jan  7 02:04:32 mail postfix/smtpd[23324]: connect from mail.xxx[127.0.0.1]
Jan  7 02:04:32 mail postfix/smtpd[23324]: 9AE9C281:
client=mail.xxx[127.0.0.1], orig_queue_id=09E898DFA2,
orig_client=c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
Jan  7 02:04:32 mail postfix/cleanup[23229]: 9AE9C281:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:04:56 mail postfix/qmgr[1576]: 9AE9C281: from=<yyy@xxx>,
size=35378688, nrcpt=1 (queue active)
Jan  7 02:04:56 mail postfix/smtpd[23324]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:04:58 mail postfix/smtp[23331]: 9AE9C281: to=<[hidden email]>,
relay=127.0.0.1[127.0.0.1]:10026, delay=26, delays=24/0.13/0/1.6, dsn=2.0.0,
status=sent (250 OK Message /var/spool/pykolab/wallace/tmpLo9c_K queued)
Jan  7 02:04:58 mail postfix/qmgr[1576]: 9AE9C281: removed

Jan  7 02:05:05 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
Jan  7 02:05:05 mail postfix/smtpd[23332]: EE2D1281:
client=mail.xxx[127.0.0.1]
Jan  7 02:05:07 mail postfix/cleanup[23229]: EE2D1281:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:05:30 mail postfix/qmgr[1576]: EE2D1281: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:05:30 mail postfix/smtpd[23332]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:05:31 mail postfix/smtp[23334]: EE2D1281: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25,
delays=25/0.03/0.45/0, dsn=5.3.4, status=bounced (message size 35379321
exceeds size limit 28311552 of server mx02.mail.icloud.com[17.57.152.14])
Jan  7 02:05:31 mail postfix/qmgr[1576]: EE2D1281: removed

Jan  7 02:05:33 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
Jan  7 02:05:33 mail postfix/smtpd[23332]: 102A0281:
client=mail.xxx[127.0.0.1]
Jan  7 02:05:34 mail postfix/cleanup[23229]: 102A0281:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:05:57 mail postfix/qmgr[1576]: 102A0281: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:05:57 mail postfix/smtpd[23332]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:05:57 mail postfix/smtp[23334]: 102A0281: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.56.9.19]:25, delay=25, delays=24/0/0.28/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx02.mail.icloud.com[17.56.9.19])
Jan  7 02:05:57 mail postfix/qmgr[1576]: 102A0281: removed

Jan  7 02:06:00 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
Jan  7 02:06:00 mail postfix/smtpd[23332]: 0CEF9281:
client=mail.xxx[127.0.0.1]
Jan  7 02:06:01 mail postfix/cleanup[23229]: 0CEF9281:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:06:25 mail postfix/smtpd[23332]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:06:25 mail postfix/qmgr[1576]: 0CEF9281: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:06:25 mail postfix/smtp[23334]: 0CEF9281: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.57.154.23]:25, delay=26,
delays=25/0.01/0.33/0, dsn=5.3.4, status=bounced (message size 35379321
exceeds size limit 28311552 of server mx01.mail.icloud.com[17.57.154.23])
Jan  7 02:06:25 mail postfix/qmgr[1576]: 0CEF9281: removed

Jan  7 02:06:27 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
Jan  7 02:06:27 mail postfix/smtpd[23332]: 152C88DFA2:
client=mail.xxx[127.0.0.1]
Jan  7 02:06:28 mail postfix/cleanup[23229]: 152C88DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:06:51 mail postfix/qmgr[1576]: 152C88DFA2: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:06:51 mail postfix/smtpd[23332]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:06:53 mail postfix/smtp[23347]: 152C88DFA2: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=26, delays=25/0.04/1.1/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx02.mail.icloud.com[17.57.152.14])
Jan  7 02:06:53 mail postfix/qmgr[1576]: 152C88DFA2: removed

Jan  7 02:06:54 mail postfix/smtpd[23339]: connect from mail.xxx[127.0.0.1]
Jan  7 02:06:54 mail postfix/smtpd[23339]: 1F2C78DFA2:
client=mail.xxx[127.0.0.1]
Jan  7 02:06:55 mail postfix/cleanup[23341]: 1F2C78DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:07:19 mail postfix/qmgr[1576]: 1F2C78DFA2: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:07:19 mail postfix/smtpd[23339]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:07:19 mail postfix/smtp[23334]: 1F2C78DFA2: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.57.152.9]:25, delay=26, delays=26/0/0.33/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx01.mail.icloud.com[17.57.152.9])
Jan  7 02:07:19 mail postfix/qmgr[1576]: 1F2C78DFA2: removed

Jan  7 02:21:15 mail postfix/smtpd[23447]: connect from mail.xxx[127.0.0.1]
Jan  7 02:21:15 mail postfix/smtpd[23447]: D13F48DFA4:
client=mail.xxx[127.0.0.1]
Jan  7 02:21:17 mail postfix/cleanup[23483]: D13F48DFA4:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:21:39 mail postfix/qmgr[1576]: D13F48DFA4: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:21:39 mail postfix/smtpd[23447]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:21:40 mail postfix/smtp[23527]: D13F48DFA4: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.42.251.10]:25, delay=25,
delays=24/0.04/0.96/0, dsn=5.3.4, status=bounced (message size 35379321
exceeds size limit 28311552 of server mx01.mail.icloud.com[17.42.251.10])
Jan  7 02:21:41 mail postfix/qmgr[1576]: D13F48DFA4: removed

Jan  7 02:21:42 mail postfix/smtpd[23484]: connect from mail.xxx[127.0.0.1]
Jan  7 02:21:42 mail postfix/smtpd[23484]: 7221C8DFA2:
client=mail.xxx[127.0.0.1]
Jan  7 02:21:44 mail postfix/cleanup[23446]: 7221C8DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:22:07 mail postfix/qmgr[1576]: 7221C8DFA2: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:22:07 mail postfix/smtpd[23484]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:22:07 mail postfix/smtp[23527]: 7221C8DFA2: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.56.9.17]:25, delay=25, delays=25/0/0.23/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx01.mail.icloud.com[17.56.9.17])
Jan  7 02:22:07 mail postfix/qmgr[1576]: 7221C8DFA2: removed

Jan  7 02:22:09 mail postfix/smtpd[23443]: connect from mail.xxx[127.0.0.1]
Jan  7 02:22:09 mail postfix/smtpd[23443]: A693B8DFA2:
client=mail.xxx[127.0.0.1]
Jan  7 02:22:11 mail postfix/cleanup[23449]: A693B8DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:22:34 mail postfix/qmgr[1576]: A693B8DFA2: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:22:34 mail postfix/smtpd[23443]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:22:34 mail postfix/smtp[23527]: A693B8DFA2: to=<[hidden email]>,
relay=mx02.mail.icloud.com[17.57.154.7]:25, delay=25, delays=25/0.01/0.23/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx02.mail.icloud.com[17.57.154.7])
Jan  7 02:22:34 mail postfix/qmgr[1576]: A693B8DFA2: removed

Jan  7 02:22:36 mail postfix/smtpd[23447]: connect from mail.xxx[127.0.0.1]
Jan  7 02:22:36 mail postfix/smtpd[23447]: BA44A8DFA2:
client=mail.xxx[127.0.0.1]
Jan  7 02:22:38 mail postfix/cleanup[23483]: BA44A8DFA2:
message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
Jan  7 02:23:01 mail postfix/qmgr[1576]: BA44A8DFA2: from=<yyy@xxx>,
size=35379321, nrcpt=1 (queue active)
Jan  7 02:23:01 mail postfix/smtpd[23447]: disconnect from
mail.xxx[127.0.0.1]
Jan  7 02:23:01 mail postfix/smtp[23527]: BA44A8DFA2: to=<[hidden email]>,
relay=mx01.mail.icloud.com[17.57.154.6]:25, delay=25, delays=25/0/0.27/0,
dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
of server mx01.mail.icloud.com[17.57.154.6])
Jan  7 02:23:01 mail postfix/qmgr[1576]: BA44A8DFA2: removed
----------------------------------------------------------------------------
--------------


>You seem to be double-signing messages, before and after Amavis perhaps?
Once is likely enough.

Once this is resolved, perhaps that needs to be looked into. Why do you
think the same message id keeps getting to postfix?

Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
On Tue, Jan 12, 2021 at 02:28:44PM -0800, [hidden email] wrote:

> > There are no "Received:" headers here, are you sure you've posted *all* the
> > headers?  All messages received by Postfix get a "Received" header
> > prepended.  Where are they?  However, we do see that the message went
> > through Amavis, so ypu should have logs for that... and ideally for how it
> > got into Amavis as well.
>
> There is a Received header in the NDR email headers, look for it in the
> paste above the one you looked at.

That's not the Received header of interest, it traces the hops the
*bounce* went through, I am looking for the hops the original message
went through.  Where are *its* Received headers?

> Here is where I see the first send of this message (based on the message id):
>
> -----------------------------------------------------------------
> Jan  7 02:03:25 mail postfix/submission/smtpd[23109]: connect from
>   c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
> Jan  7 02:03:26 mail postfix/submission/smtpd[23109]: 09E898DFA2:
>   client=c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44], sasl_method=LOGIN,
>   sasl_username=yyy@xxx
> Jan  7 02:03:26 mail postfix/cleanup[23314]: 09E898DFA2:
>   message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:04:17 mail postfix/qmgr[1576]: 09E898DFA2: from=<yyy@xxx>,
>   size=35378641, nrcpt=1 (queue active)
> Jan  7 02:04:19 mail postfix/submission/smtpd[23109]: disconnect from
>   c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
> Jan  7 02:04:56 mail postfix/smtp[23322]: 09E898DFA2: to=<[hidden email]>,
>   relay=127.0.0.1[127.0.0.1]:10024, delay=91, delays=52/0.03/0.01/39,
>   dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
>   2.0.0 Ok: queued as 9AE9C281)
> Jan  7 02:04:56 mail postfix/qmgr[1576]: 09E898DFA2: removed

Ah, finally, we see it arrive from outside your system, via
authenticated SMTP submission and get forwarded to Amavis on port 10024
(just a single recipient message).

> Jan  7 02:04:32 mail postfix/smtpd[23324]: connect from mail.xxx[127.0.0.1]
> Jan  7 02:04:32 mail postfix/smtpd[23324]: 9AE9C281:
>   client=mail.xxx[127.0.0.1], orig_queue_id=09E898DFA2,
>   orig_client=c-11-22-33-44.hsd1.ca.comcast.net[11.22.33.44]
> Jan  7 02:04:32 mail postfix/cleanup[23229]: 9AE9C281:
>   message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:04:56 mail postfix/qmgr[1576]: 9AE9C281: from=<yyy@xxx>,
>   size=35378688, nrcpt=1 (queue active)
> Jan  7 02:04:56 mail postfix/smtpd[23324]: disconnect from
>   mail.xxx[127.0.0.1]
> Jan  7 02:04:58 mail postfix/smtp[23331]: 9AE9C281: to=<[hidden email]>,
>   relay=127.0.0.1[127.0.0.1]:10026, delay=26, delays=24/0.13/0/1.6, dsn=2.0.0,
>   status=sent (250 OK Message /var/spool/pykolab/wallace/tmpLo9c_K queued)
> Jan  7 02:04:58 mail postfix/qmgr[1576]: 9AE9C281: removed

The message received from Amavis is sent to port 10026, where something
perhaps called "pykolab" accepted it into some sort of queue.

> Jan  7 02:05:05 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
> Jan  7 02:05:05 mail postfix/smtpd[23332]: EE2D1281:
>   client=mail.xxx[127.0.0.1]
> Jan  7 02:05:07 mail postfix/cleanup[23229]: EE2D1281:
>   message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:05:30 mail postfix/qmgr[1576]: EE2D1281: from=<yyy@xxx>,
>   size=35379321, nrcpt=1 (queue active)
> Jan  7 02:05:30 mail postfix/smtpd[23332]: disconnect from
>   mail.xxx[127.0.0.1]
> Jan  7 02:05:31 mail postfix/smtp[23334]: EE2D1281: to=<[hidden email]>,
>   relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=25,
>   delays=25/0.03/0.45/0, dsn=5.3.4, status=bounced (message size 35379321
>   exceeds size limit 28311552 of server mx02.mail.icloud.com[17.57.152.14])
> Jan  7 02:05:31 mail postfix/qmgr[1576]: EE2D1281: removed

Seven minutes later, the message appears again, from 127.0.0.1, so
either from Amavis or "pykolab", this time it fails an attempt to send
it to icloud.com.

> Jan  7 02:05:33 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
> Jan  7 02:05:33 mail postfix/smtpd[23332]: 102A0281: client=mail.xxx[127.0.0.1]
> Jan  7 02:05:34 mail postfix/cleanup[23229]: 102A0281:
> message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:05:57 mail postfix/qmgr[1576]: 102A0281: from=<yyy@xxx>,
> size=35379321, nrcpt=1 (queue active)
> Jan  7 02:05:57 mail postfix/smtpd[23332]: disconnect from
> mail.xxx[127.0.0.1]
> Jan  7 02:05:57 mail postfix/smtp[23334]: 102A0281: to=<[hidden email]>,
> relay=mx02.mail.icloud.com[17.56.9.19]:25, delay=25, delays=24/0/0.28/0,
> dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
> of server mx02.mail.icloud.com[17.56.9.19])
> Jan  7 02:05:57 mail postfix/qmgr[1576]: 102A0281: removed

And again, ~30 seconds later.

> Jan  7 02:06:00 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
> Jan  7 02:06:00 mail postfix/smtpd[23332]: 0CEF9281:
> client=mail.xxx[127.0.0.1]
> Jan  7 02:06:01 mail postfix/cleanup[23229]: 0CEF9281:
> message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:06:25 mail postfix/smtpd[23332]: disconnect from
> mail.xxx[127.0.0.1]
> Jan  7 02:06:25 mail postfix/qmgr[1576]: 0CEF9281: from=<yyy@xxx>,
> size=35379321, nrcpt=1 (queue active)
> Jan  7 02:06:25 mail postfix/smtp[23334]: 0CEF9281: to=<[hidden email]>,
> relay=mx01.mail.icloud.com[17.57.154.23]:25, delay=26,
> delays=25/0.01/0.33/0, dsn=5.3.4, status=bounced (message size 35379321
> exceeds size limit 28311552 of server mx01.mail.icloud.com[17.57.154.23])
> Jan  7 02:06:25 mail postfix/qmgr[1576]: 0CEF9281: removed

And again, ...

> Jan  7 02:06:27 mail postfix/smtpd[23332]: connect from mail.xxx[127.0.0.1]
> Jan  7 02:06:27 mail postfix/smtpd[23332]: 152C88DFA2:
> client=mail.xxx[127.0.0.1]
> Jan  7 02:06:28 mail postfix/cleanup[23229]: 152C88DFA2:
> message-id=<2f18001d6e499$48eeff40$daccfdc0$@xxx>
> Jan  7 02:06:51 mail postfix/qmgr[1576]: 152C88DFA2: from=<yyy@xxx>,
> size=35379321, nrcpt=1 (queue active)
> Jan  7 02:06:51 mail postfix/smtpd[23332]: disconnect from
> mail.xxx[127.0.0.1]
> Jan  7 02:06:53 mail postfix/smtp[23347]: 152C88DFA2: to=<[hidden email]>,
> relay=mx02.mail.icloud.com[17.57.152.14]:25, delay=26, delays=25/0.04/1.1/0,
> dsn=5.3.4, status=bounced (message size 35379321 exceeds size limit 28311552
> of server mx02.mail.icloud.com[17.57.152.14])
> Jan  7 02:06:53 mail postfix/qmgr[1576]: 152C88DFA2: removed

Are we bored yet...  It looks like the software that's sending
it into Postfix over and over again is likely the "pykolab"
thing on port 10026.

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

RE: Crazy retries for bounced (and a small number of successful) emails

Bob Jones
>Are we bored yet...  It looks like the software that's sending it into
Postfix over and over again is likely the "pykolab"
>thing on port 10026.

I was able to locate the files that pykolab was using to create this mayhem.
Thank you so much Viktor!

Reply | Threaded
Open this post in threaded view
|

Re: Crazy retries for bounced (and a small number of successful) emails

Viktor Dukhovni
> On Jan 12, 2021, at 10:19 PM, [hidden email] wrote:
>
> I was able to locate the files that pykolab was using to create this mayhem.
> Thank you so much Viktor!

You're welcome.  Your penance is going to be to spend a bit
more time getting familiar with how to read your logs... :-)

--
        Viktor.