t/s outbound 99% timeout on TBird?

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

t/s outbound 99% timeout on TBird?

lists-3
I have a user with Tbird, reports
"when replying to an email with an embeded PNG image TBird reporting:

"Sending Mssage/Status Delivering mail.../Progress 99%"
then it times out"

looking in the log (I think at the correct transaction?) I see like:
not sure where/how/what to look to t/s this ??

log:

Mar 10 00:12:42 geko amavis[4998]: (04998-13) Passed CLEAN {RelayedOutbound},
ORIGINATING LOCAL [119.42.117.134]:58287 [119.42.117.134] <[hidden email]> ->
<[hidden email]>, Queue-ID: C099F42B0143, Message-ID:
<[hidden email]>, mail_id: qJth6ESNbOwS,
Hits:
0.222, size: 240858, queued_as: 145BB42B0149, 2796 ms

Mar 10 00:12:42 geko postfix/smtp[9497]: C099F42B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=113,
delays=111/0.01/0.01/2.8, 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 145BB42B0149)

Mar 10 00:12:46 geko postfix/smtp[9502]: 145BB42B0149:
to=<[hidden email]>, relay=aspmx.l.google.com[172.217.194.26]:25,
delay=4, delays=0.01/0.02/1.9/2, dsn=2.0.0, status=sent (250 2.0.0 OK
1583759565
i6si12263894pjk.13 - gsmtp)

Mar 10 00:14:09 geko amavis[4927]: (04927-14) Passed CLEAN {RelayedOutbound},
ORIGINATING LOCAL [119.42.117.134]:58356 [119.42.117.134] <[hidden email]> ->
<[hidden email]>, Queue-ID: 1707542B0143, Message-ID:
<[hidden email]>, mail_id: Gkn3suP0kf4K,
Hits:
2.714, size: 240145, queued_as: 175C542B0146, 1052 ms

Mar 10 00:14:09 geko postfix/smtp[9497]: 1707542B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=57,
delays=55/0/0.01/1.1, 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 175C542B0146)

Mar 10 00:14:12 geko postfix/smtp[9502]: 175C542B0146:
to=<[hidden email]>, relay=aspmx.l.google.com[172.217.194.26]:25,
delay=3.6, delays=0.01/0.01/1.6/1.9, dsn=2.0.0, status=sent (250 2.0.0 OK
1583759652 y21si12154012pfm.184 - gsmtp)

Mar 10 00:20:16 geko amavis[4998]: (04998-15) Passed CLEAN {RelayedOutbound},
ORIGINATING LOCAL [119.42.117.134]:58409 [119.42.117.134] <[hidden email]> ->
<[hidden email]>, Queue-ID: 57DB841A85FC, Message-ID:
<[hidden email]>, mail_id: saXIzyV4Xh2B,
Hits:
0.12, size: 156800, queued_as: E6C8E41A8691, 1084 ms

Mar 10 00:20:16 geko postfix/smtp[9769]: 57DB841A85FC:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=26,
delays=25/0.02/0.01/1.1, 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 E6C8E41A8691)

Mar 10 00:20:19 geko postfix/smtp[9773]: E6C8E41A8691:
to=<[hidden email]>, relay=aspmx.l.google.com[74.125.130.27]:25,
delay=3.5, delays=0.06/0.04/1.9/1.6, dsn=2.0.0, status=sent (250 2.0.0 OK
1583760019 f26si12249799pfn.45 - gsmtp)



Reply | Threaded
Open this post in threaded view
|

Re: t/s outbound 99% timeout on TBird?

Wietse Venema
[hidden email]:
> Mar 10 00:12:42 geko postfix/smtp[9497]: C099F42B0143:
> to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=113,
> delays=111/0.01/0.01/2.8, 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 145BB42B0149)

This is Postfix logging while SENDING email through an after-queue
content filter (which has serious congestion, but that is not the
problem in $SUBJECT).

To come back to $SUBJECT, if you have user clients timing out, then
you should be looking at Postfix logging while RECEIVING email from
the client.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: t/s outbound 99% timeout on TBird?

Viktor Dukhovni
On Mon, Mar 09, 2020 at 07:27:29PM -0400, Wietse Venema wrote:

> [hidden email]:
> > Mar 10 00:12:42 geko postfix/smtp[9497]: C099F42B0143:
> > to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=113,
> > delays=111/0.01/0.01/2.8, 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 145BB42B0149)
>
> This is Postfix logging while SENDING email through an after-queue
> content filter (which has serious congestion, but that is not the
> problem in $SUBJECT).

One interesting tidbit however is the 111s "before active" time in the
delays= times.

    http://www.postfix.org/postconf.5.html#delay_logging_resolution_limit

This does seem to suggest that it took ~111 seconds for the message to
be accepted before it entered the active queue.  Perhaps PMTU or similar
issues?  Or a slow pre-queue filter.

> To come back to $SUBJECT, if you have user clients timing out, then
> you should be looking at Postfix logging while RECEIVING email from
> the client.

Yes, not much to learn otherwise.

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

Re: t/s outbound 99% timeout on TBird?

Ralph Seichter-2
* Viktor Dukhovni:

> Perhaps PMTU or similar issues? Or a slow pre-queue filter.

I've seen problems with Thunderbird timing out when sending attachments
over IPv6 connections. Reducing the MTU size helped some users. For a
TB-based solution, I found that adding the recipent domain causing
problems to Thunderbird's "network.dns.ipv4OnlyDomains" parameter.

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

Re: t/s outbound 99% timeout on TBird?

lists-3
In reply to this post by Wietse Venema
On Tue, March 10, 2020 10:27 am, Wietse Venema wrote:

> This is Postfix logging while SENDING email through an after-queue
> content filter (which has serious congestion, but that is not the problem
> in $SUBJECT).
>
> To come back to $SUBJECT, if you have user clients timing out, then
> you should be looking at Postfix logging while RECEIVING email from the
> client.

Wietse, thanks
oops, sorry.. I guess it the first 'section', for completeness, included
whole progress

noticed (unrelated I think) issue, user has both a_tld.com as well as
a_tld.com.au, from the log, he seems to use both, .com.au in sasl auth


# grep C099F42B0143 /var/log/maillog
Mar 10 00:10:49 geko postfix/smtpd[9483]: C099F42B0143:
client=unknown[119.42.117.134], sasl_method=PLAIN,
sasl_username=[hidden email]
Mar 10 00:10:50 geko postfix/cleanup[9389]: C099F42B0143:
message-id=<[hidden email]>
Mar 10 00:12:38 geko opendkim[1322]: C099F42B0143: DKIM-Signature field
added (s=default, d=a_tld.com)
Mar 10 00:12:39 geko opendmarc[1295]: C099F42B0143: SPF(mailfrom):
[hidden email] fail
Mar 10 00:12:39 geko opendmarc[1295]: C099F42B0143: a_tld.com fail
Mar 10 00:12:39 geko postfix/qmgr[1857]: C099F42B0143:
from=<[hidden email]>, size=240046, nrcpt=1 (queue active)
Mar 10 00:12:42 geko amavis[4998]: (04998-13) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58287
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
C099F42B0143, Message-ID:
<[hidden email]>, mail_id: qJth6ESNbOwS,
Hits: 0.222, size: 240858, queued_as: 145BB42B0149, 2796 ms
Mar 10 00:12:42 geko postfix/smtp[9497]: C099F42B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=113,
delays=111/0.01/0.01/2.8, 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 145BB42B0149)
Mar 10 00:12:42 geko postfix/qmgr[1857]: C099F42B0143: removed


# grep 145BB42B0149  /var/log/maillog
Mar 10 00:12:42 geko postfix/smtpd[9501]: 145BB42B0149:
client=localhost[127.0.0.1]
Mar 10 00:12:42 geko postfix/cleanup[9389]: 145BB42B0149:
message-id=<[hidden email]>
Mar 10 00:12:42 geko postfix/qmgr[1857]: 145BB42B0149:
from=<[hidden email]>, size=241161, nrcpt=1 (queue active)
Mar 10 00:12:42 geko amavis[4998]: (04998-13) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58287
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
C099F42B0143, Message-ID:
<[hidden email]>, mail_id: qJth6ESNbOwS,
Hits: 0.222, size: 240858, queued_as: 145BB42B0149, 2796 ms
Mar 10 00:12:42 geko postfix/smtp[9497]: C099F42B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=113,
delays=111/0.01/0.01/2.8, 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 145BB42B0149)
Mar 10 00:12:46 geko postfix/smtp[9502]: 145BB42B0149:
to=<[hidden email]>, relay=aspmx.l.google.com[172.217.194.26]:25,
delay=4, delays=0.01/0.02/1.9/2, dsn=2.0.0, status=sent (250 2.0.0 OK
1583759565 i6si12263894pjk.13 - gsmtp)
Mar 10 00:12:46 geko postfix/qmgr[1857]: 145BB42B0149: removed

# grep 1707542B0143  /var/log/maillog
Mar 10 00:13:13 geko postfix/smtpd[9491]: 1707542B0143:
client=unknown[119.42.117.134], sasl_method=PLAIN,
sasl_username=[hidden email]
Mar 10 00:13:16 geko postfix/cleanup[9389]: 1707542B0143:
message-id=<[hidden email]>
Mar 10 00:14:07 geko opendkim[1322]: 1707542B0143: DKIM-Signature field
added (s=default, d=a_tld.com)
Mar 10 00:14:08 geko opendmarc[1295]: 1707542B0143: SPF(mailfrom):
[hidden email] fail
Mar 10 00:14:08 geko opendmarc[1295]: 1707542B0143: a_tld.com fail
Mar 10 00:14:08 geko postfix/qmgr[1857]: 1707542B0143:
from=<[hidden email]>, size=239372, nrcpt=1 (queue active)
Mar 10 00:14:09 geko amavis[4927]: (04927-14) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58356
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
1707542B0143, Message-ID:
<[hidden email]>, mail_id: Gkn3suP0kf4K,
Hits: 2.714, size: 240145, queued_as: 175C542B0146, 1052 ms
Mar 10 00:14:09 geko postfix/smtp[9497]: 1707542B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=57,
delays=55/0/0.01/1.1, 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 175C542B0146)
Mar 10 00:14:09 geko postfix/qmgr[1857]: 1707542B0143: removed

# grep 175C542B0146  /var/log/maillog
Mar 10 00:14:09 geko postfix/smtpd[9501]: 175C542B0146:
client=localhost[127.0.0.1]
Mar 10 00:14:09 geko postfix/cleanup[9389]: 175C542B0146:
message-id=<[hidden email]>
Mar 10 00:14:09 geko postfix/qmgr[1857]: 175C542B0146:
from=<[hidden email]>, size=240448, nrcpt=1 (queue active)
Mar 10 00:14:09 geko amavis[4927]: (04927-14) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58356
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
1707542B0143, Message-ID:
<[hidden email]>, mail_id: Gkn3suP0kf4K,
Hits: 2.714, size: 240145, queued_as: 175C542B0146, 1052 ms
Mar 10 00:14:09 geko postfix/smtp[9497]: 1707542B0143:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=57,
delays=55/0/0.01/1.1, 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 175C542B0146)
Mar 10 00:14:12 geko postfix/smtp[9502]: 175C542B0146:
to=<[hidden email]>, relay=aspmx.l.google.com[172.217.194.26]:25,
delay=3.6, delays=0.01/0.01/1.6/1.9, dsn=2.0.0, status=sent (250 2.0.0 OK
1583759652 y21si12154012pfm.184 - gsmtp)
Mar 10 00:14:12 geko postfix/qmgr[1857]: 175C542B0146: removed

# grep 57DB841A85FC  /var/log/maillog
Mar 10 00:19:50 geko postfix/smtpd[9693]: 57DB841A85FC:
client=unknown[119.42.117.134], sasl_method=PLAIN,
sasl_username=[hidden email]
Mar 10 00:19:51 geko postfix/cleanup[9698]: 57DB841A85FC:
message-id=<[hidden email]>
Mar 10 00:20:14 geko opendkim[1322]: 57DB841A85FC: DKIM-Signature field
added (s=default, d=a_tld.com)
Mar 10 00:20:14 geko opendmarc[1295]: 57DB841A85FC: SPF(mailfrom):
[hidden email] fail
Mar 10 00:20:14 geko opendmarc[1295]: 57DB841A85FC: a_tld.com fail
Mar 10 00:20:14 geko postfix/qmgr[1857]: 57DB841A85FC:
from=<[hidden email]>, size=156097, nrcpt=1 (queue active)
Mar 10 00:20:16 geko amavis[4998]: (04998-15) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58409
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
57DB841A85FC, Message-ID:
<[hidden email]>, mail_id: saXIzyV4Xh2B,
Hits: 0.12, size: 156800, queued_as: E6C8E41A8691, 1084 ms
Mar 10 00:20:16 geko postfix/smtp[9769]: 57DB841A85FC:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=26,
delays=25/0.02/0.01/1.1, 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 E6C8E41A8691)
Mar 10 00:20:16 geko postfix/qmgr[1857]: 57DB841A85FC: removed

# grep E6C8E41A8691  /var/log/maillog
Mar 10 00:20:15 geko postfix/smtpd[9772]: E6C8E41A8691:
client=localhost[127.0.0.1]
Mar 10 00:20:15 geko postfix/cleanup[9708]: E6C8E41A8691:
message-id=<[hidden email]>
Mar 10 00:20:15 geko postfix/qmgr[1857]: E6C8E41A8691:
from=<[hidden email]>, size=157103, nrcpt=1 (queue active)
Mar 10 00:20:16 geko amavis[4998]: (04998-15) Passed CLEAN
{RelayedOutbound}, ORIGINATING LOCAL [119.42.117.134]:58409
[119.42.117.134] <[hidden email]> -> <[hidden email]>, Queue-ID:
57DB841A85FC, Message-ID:
<[hidden email]>, mail_id: saXIzyV4Xh2B,
Hits: 0.12, size: 156800, queued_as: E6C8E41A8691, 1084 ms
Mar 10 00:20:16 geko postfix/smtp[9769]: 57DB841A85FC:
to=<[hidden email]>, relay=127.0.0.1[127.0.0.1]:10026, delay=26,
delays=25/0.02/0.01/1.1, 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 E6C8E41A8691)
Mar 10 00:20:19 geko postfix/smtp[9773]: E6C8E41A8691:
to=<[hidden email]>, relay=aspmx.l.google.com[74.125.130.27]:25,
delay=3.5, delays=0.06/0.04/1.9/1.6, dsn=2.0.0, status=sent (250 2.0.0 OK
1583760019 f26si12249799pfn.45 - gsmtp)
Mar 10 00:20:19 geko postfix/qmgr[1857]: E6C8E41A8691: removed



Reply | Threaded
Open this post in threaded view
|

Re: t/s outbound 99% timeout on TBird?

lists-3
In reply to this post by Viktor Dukhovni
On Tue, March 10, 2020 12:33 pm, Viktor Dukhovni wrote:

>
> One interesting tidbit however is the 111s "before active" time in the
> delays= times.
>
> http://www.postfix.org/postconf.5.html#delay_logging_resolution_limit
>
>
> This does seem to suggest that it took ~111 seconds for the message to
> be accepted before it entered the active queue.  Perhaps PMTU or similar
> issues?  Or a slow pre-queue filter.

Viktor, thanks

maybe the default amavisd value of 'pre forked children' of '2' was
causing this, have increased it now to '10'

V


Reply | Threaded
Open this post in threaded view
|

Re: t/s outbound 99% timeout on TBird?

Wietse Venema
In reply to this post by lists-3
[hidden email]:
> Mar 10 00:10:50 geko postfix/cleanup[9389]: C099F42B0143:
> message-id=<[hidden email]>
> Mar 10 00:12:38 geko opendkim[1322]: C099F42B0143: DKIM-Signature field
> added (s=default, d=a_tld.com)

You need to find out why this took TWO MINUTES.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: t/s outbound 99% timeout on TBird?

Viktor Dukhovni
In reply to this post by lists-3
On Tue, Mar 10, 2020 at 10:53:02PM +1100, [hidden email] wrote:

> Mar 10 00:10:50 geko postfix/cleanup[9389]: C099F42B0143:
> message-id=<[hidden email]>
> Mar 10 00:12:38 geko opendkim[1322]: C099F42B0143: DKIM-Signature field
> added (s=default, d=a_tld.com)
> Mar 10 00:12:39 geko opendmarc[1295]: C099F42B0143: SPF(mailfrom):
> [hidden email] fail
> Mar 10 00:12:39 geko opendmarc[1295]: C099F42B0143: a_tld.com fail

So were the milters slow, or the message transmission slow?

Also, while you may want to DKIM-sign submission traffic, what's the
purpose of DMARC in this case?  I'd expect that SPF and DMARC checks are
not relevant for submission, and not should not be turned on.

--
    Viktor.