smtp_pix_workaround_threshold_time not working correctly?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

smtp_pix_workaround_threshold_time not working correctly?

Ralf Hildebrandt-2
In my log I found this:

Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25

According to http://www.electric-spoon.com/doc/postfix/html/postconf.5.html#smtp_pix_workaround_maps

"By default, the workaround is turned off for mail that is queued for
less than 500 seconds. In other words, the workaround is normally
turned off for the first delivery attempt."

% fgrep 3xDK0Z6RBRz1Z1wy /var/log/mail.log

Jul 21 07:22:54 mail-cvk postfix/smtpd[5374]: 3xDK0Z6RBRz1Z1wy: client=s-mx14-ht01.charite.de[10.32.37.105]
...
Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25
Jul 21 07:23:10 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: to=<[hidden email]>, relay=mail.unimed.de[62.154.176.144]:25, delay=16, delays=15/0/0.06/1.2, dsn=2.0.0, status=sent (250 Ok: queued as B51D41068C5)

Jul 21 07:23:10 mail-cvk postfix/qmgr[7149]: 3xDK0Z6RBRz1Z1wy: removed

That's 16s, why were the PIX workarounds triggered anyway?

Another:
Jul 21 08:02:48 mail-cvk postfix/smtpd[10518]: 3xDKtc5hRMz1Z2wL: client=s-mx14-ht01.charite.de[10.32.37.105]
...
Jul 21 08:02:52 mail-cvk postfix/smtp[8678]: 3xDKtc5hRMz1Z2wL: enabling PIX workarounds: disable_esmtp delay_dotcrlf for imh.rsys2.net[12.130.135.43]:25
Jul 21 08:02:53 mail-cvk postfix/smtp[8678]: 3xDKtc5hRMz1Z2wL: to=<[hidden email]>, relay=imh.rsys2.net[12.130.135.43]:25, delay=6.5, delays=5/0/0.55/0.93, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 549AF1219F4)
Jul 21 08:02:53 mail-cvk postfix/qmgr[7149]: 3xDKtc5hRMz1Z2wL: removed

That's 6s.

Is the "PIX state" cached?

# postconf -n|fgrep pix
smtp_pix_workarounds = delay_dotcrlf

# postconf -d mail_version
mail_version = 3.2-20170122


Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: smtp_pix_workaround_threshold_time not working correctly?

Ralf Hildebrandt-2
* Ralf Hildebrandt <[hidden email]>:

> In my log I found this:
>
> Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25
>
> According to http://www.electric-spoon.com/doc/postfix/html/postconf.5.html#smtp_pix_workaround_maps
>
> "By default, the workaround is turned off for mail that is queued for
> less than 500 seconds. In other words, the workaround is normally
> turned off for the first delivery attempt."
>
> % fgrep 3xDK0Z6RBRz1Z1wy /var/log/mail.log
>
> Jul 21 07:22:54 mail-cvk postfix/smtpd[5374]: 3xDK0Z6RBRz1Z1wy: client=s-mx14-ht01.charite.de[10.32.37.105]
> ...
> Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25
> Jul 21 07:23:10 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: to=<[hidden email]>, relay=mail.unimed.de[62.154.176.144]:25, delay=16, delays=15/0/0.06/1.2, dsn=2.0.0, status=sent (250 Ok: queued as B51D41068C5)
>
> Jul 21 07:23:10 mail-cvk postfix/qmgr[7149]: 3xDK0Z6RBRz1Z1wy: removed
>
> That's 16s, why were the PIX workarounds triggered anyway?
>
> Another:
> Jul 21 08:02:48 mail-cvk postfix/smtpd[10518]: 3xDKtc5hRMz1Z2wL: client=s-mx14-ht01.charite.de[10.32.37.105]
> ...
> Jul 21 08:02:52 mail-cvk postfix/smtp[8678]: 3xDKtc5hRMz1Z2wL: enabling PIX workarounds: disable_esmtp delay_dotcrlf for imh.rsys2.net[12.130.135.43]:25
> Jul 21 08:02:53 mail-cvk postfix/smtp[8678]: 3xDKtc5hRMz1Z2wL: to=<[hidden email]>, relay=imh.rsys2.net[12.130.135.43]:25, delay=6.5, delays=5/0/0.55/0.93, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 549AF1219F4)
> Jul 21 08:02:53 mail-cvk postfix/qmgr[7149]: 3xDKtc5hRMz1Z2wL: removed
>
> That's 6s.
>
> Is the "PIX state" cached?
>
> # postconf -n|fgrep pix
> smtp_pix_workarounds = delay_dotcrlf

Changed this just that moment, was set to the default before.

--
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Schleißheimer Straße 26/MG, 80333 München
                                           
Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer
Aufsichtsratsvorsitzender: Florian Kirstein
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: smtp_pix_workaround_threshold_time not working correctly?

Wietse Venema
In reply to this post by Ralf Hildebrandt-2
Ralf Hildebrandt:
> In my log I found this:
>
> Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25
>

The "220 greeting" handler logs this when the server looks like
PIX, and was correct when PIX workarounds were always in effect.
The time threshold was added later, deep down in the guts of the
pipelined code, and the 220 greeting handler was not updated.

        Wietse
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: smtp_pix_workaround_threshold_time not working correctly?

Wietse Venema
Wietse Venema:

> Ralf Hildebrandt:
> > In my log I found this:
> >
> > Jul 21 07:23:09 mail-cvk postfix/smtp[7329]: 3xDK0Z6RBRz1Z1wy: enabling PIX workarounds: disable_esmtp delay_dotcrlf for mail.unimed.de[62.154.176.144]:25
> >
>
> The "220 greeting" handler logs this when the server looks like
> PIX, and was correct when PIX workarounds were always in effect.
> [smtp_pix_workaround_threshold_time support] was added later, deep
> down in the guts of the pipelined code, and the 220 greeting handler
> was not updated.

This patch changes only the logging, by moving some code before the
logging call.

As before, the smtp_pix_workaround_threshold_time setting affects
only the 'delay_dotcrlf' workaround, and has no effect on the
'disable_esmtp' workaround.

Also part of postfix-3.3-20170722.

        Wietse

diff -ur /var/tmp/postfix-3.3-20170716/src/smtp/smtp_proto.c src/smtp/smtp_proto.c
--- /var/tmp/postfix-3.3-20170716/src/smtp/smtp_proto.c 2017-01-09 18:10:07.000000000 -0500
+++ src/smtp/smtp_proto.c 2017-07-22 17:28:36.000000000 -0400
@@ -403,6 +403,10 @@
  pix_bug_mask = name_mask_opt(pix_bug_source, pix_bug_table,
      pix_bug_words,
      NAME_MASK_ANY_CASE | NAME_MASK_IGNORE);
+ if ((pix_bug_mask & SMTP_FEATURE_PIX_DELAY_DOTCRLF)
+    && request->msg_stats.incoming_arrival.tv_sec
+    > vstream_ftime(state->session->stream) - var_smtp_pix_thresh)
+    pix_bug_mask &= ~SMTP_FEATURE_PIX_DELAY_DOTCRLF;
  msg_info("%s: enabling PIX workarounds: %s for %s",
  request->queue_id,
  str_name_mask("pix workaround bitmask",
@@ -2147,9 +2151,7 @@
     }
  } else if (prev_type == REC_TYPE_CONT) /* missing newline */
     smtp_fputs("", 0, session->stream);
- if ((session->features & SMTP_FEATURE_PIX_DELAY_DOTCRLF) != 0
-    && request->msg_stats.incoming_arrival.tv_sec
-  <= vstream_ftime(session->stream) - var_smtp_pix_thresh) {
+ if (session->features & SMTP_FEATURE_PIX_DELAY_DOTCRLF) {
     smtp_flush(session->stream);/* hurts performance */
     sleep(var_smtp_pix_delay); /* not to mention this */
  }
Loading...