Re: postfix 2.8 and upper don't close connection with smtpd_proxy_filter

Ludovic LEVET Tue, 23 Apr 2013 04:02:01 -0700

Hi Bastian,

The transcription is on mail first mail :


A copy :

Debug :

Before with postfix 2.6.18 :
----------------------------
...

Apr 22 14:36:47 dedi dkimproxy.in[18373]: DKIM verify - none; from=<t...@ludosoft.org> Apr 22 14:36:47 dedi postfix/cleanup[4973]: B2FCF261729: message-id=<20130422123631.b2fcf261...@dedi.ludosoft.org> Apr 22 14:36:47 dedi postfix/qmgr[4966]: B2FCF261729: from=<t...@ludosoft.org>, size=651, nrcpt=1 (queue active) Apr 22 14:36:47 dedi postfix/smtpd[4972]: public/cleanup socket: wanted attribute: status

Apr 22 14:36:47 dedi postfix/smtpd[4972]: input attribute name: status
Apr 22 14:36:47 dedi postfix/smtpd[4972]: input attribute value: 0

Apr 22 14:36:47 dedi postfix/smtpd[4972]: public/cleanup socket: wanted attribute: reason

Apr 22 14:36:47 dedi postfix/smtpd[4972]: input attribute name: reason
Apr 22 14:36:47 dedi postfix/smtpd[4972]: input attribute value: (end)

Apr 22 14:36:47 dedi postfix/smtpd[4972]: public/cleanup socket: wanted attribute: (list terminator)

Apr 22 14:36:47 dedi postfix/smtpd[4972]: input attribute name: (end)

Apr 22 14:36:47 dedi postfix/smtpd[4972]: > dedi.ludosoft.org[127.0.0.1]: 250 2.0.0 Ok: queued as B2FCF261729

Apr 22 14:36:47 dedi postfix/smtpd[4972]: watchdog_pat: 0x8d721b8

Apr 22 14:36:47 dedi postfix/smtpd[4968]: < 127.0.0.1:10025: 250 2.0.0 Ok: queued as B2FCF261729 Apr 22 14:36:47 dedi postfix/smtpd[4968]: > dedi.ludosoft.org[127.0.0.1]: 250 2.0.0 Ok: queued as B2FCF261729

Apr 22 14:36:47 dedi postfix/smtpd[4968]: > 127.0.0.1:10025: QUIT
Apr 22 14:36:47 dedi postfix/smtpd[4968]: watchdog_pat: 0x9fea028

Apr 22 14:36:47 dedi postfix/smtpd[4972]: < dedi.ludosoft.org[127.0.0.1]: QUIT Apr 22 14:36:47 dedi postfix/smtpd[4972]: > dedi.ludosoft.org[127.0.0.1]: 221 2.0.0 Bye Apr 22 14:36:47 dedi postfix/smtpd[4972]: match_hostname: dedi.ludosoft.org ~? 127.0.0.0/8 Apr 22 14:36:47 dedi postfix/smtpd[4972]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8 Apr 22 14:36:47 dedi postfix/smtpd[4972]: disconnect from dedi.ludosoft.org[127.0.0.1] Apr 22 14:36:48 dedi postfix/smtp[4974]: B2FCF261729: to=<t...@ludosoft.org>, relay=filenet.ludosoft.org[82.236.203.193]:25, delay=17, delays=16/0.08/0.27/0.52, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 9F6BE122798B)

Apr 22 14:36:48 dedi postfix/qmgr[4966]: B2FCF261729: removed

Apr 22 14:36:52 dedi postfix/smtpd[4968]: < dedi.ludosoft.org[127.0.0.1]: QUIT Apr 22 14:36:52 dedi postfix/smtpd[4968]: > dedi.ludosoft.org[127.0.0.1]: 221 2.0.0 Bye Apr 22 14:36:52 dedi postfix/smtpd[4968]: match_hostname: dedi.ludosoft.org ~? 127.0.0.0/8 Apr 22 14:36:52 dedi postfix/smtpd[4968]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8 Apr 22 14:36:52 dedi postfix/smtpd[4968]: disconnect from dedi.ludosoft.org[127.0.0.1]



Now with postfix 2.10.0 :
----------------------------
...

Apr 22 14:15:08 dedi dkimproxy.in[1459]: DKIM verify - none; from=<t...@ludosoft.org> Apr 22 14:15:08 dedi postfix/cleanup[2975]: C0BBC261729: message-id=<20130422121456.c0bbc261...@dedi.ludosoft.org> Apr 22 14:15:08 dedi postfix/qmgr[2966]: C0BBC261729: from=<t...@ludosoft.org>, size=651, nrcpt=1 (queue active) Apr 22 14:15:08 dedi postfix/smtpd[2974]: public/cleanup socket: wanted attribute: status

Apr 22 14:15:08 dedi postfix/smtpd[2974]: input attribute name: status
Apr 22 14:15:08 dedi postfix/smtpd[2974]: input attribute value: 0

Apr 22 14:15:08 dedi postfix/smtpd[2974]: public/cleanup socket: wanted attribute: reason

Apr 22 14:15:08 dedi postfix/smtpd[2974]: input attribute name: reason
Apr 22 14:15:08 dedi postfix/smtpd[2974]: input attribute value: (end)

Apr 22 14:15:08 dedi postfix/smtpd[2974]: public/cleanup socket: wanted attribute: (list terminator)

Apr 22 14:15:08 dedi postfix/smtpd[2974]: input attribute name: (end)

Apr 22 14:15:08 dedi postfix/smtpd[2974]: > dedi.ludosoft.org[127.0.0.1]: 250 2.0.0 Ok: queued as C0BBC261729

Apr 22 14:15:08 dedi postfix/smtpd[2974]: watchdog_pat: 0x8e10870

Apr 22 14:15:08 dedi postfix/smtpd[2970]: < 127.0.0.1:10025: 250 2.0.0 Ok: queued as C0BBC261729 Apr 22 14:15:08 dedi postfix/smtpd[2970]: > dedi.ludosoft.org[127.0.0.1]: 250 2.0.0 Ok: queued as C0BBC261729 Apr 22 14:15:08 dedi postfix/smtpd[2970]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 Ok: queued as C0BBC261729; from=<t...@ludosoft.org> to=<t...@ludosoft.org> proto=ESMTP helo=<dedi.ludosoft.org>

Apr 22 14:15:08 dedi postfix/smtpd[2970]: watchdog_pat: 0x839f800

Apr 22 14:15:09 dedi postfix/smtp[2976]: C0BBC261729: to=<t...@ludosoft.org>, relay=filenet.ludosoft.org[82.236.203.193]:25, delay=13, delays=12/0.08/0.25/0.78, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as BAC10122195B)

Apr 22 14:15:09 dedi postfix/qmgr[2966]: C0BBC261729: removed

Apr 22 14:15:11 dedi postfix/smtpd[2970]: < dedi.ludosoft.org[127.0.0.1]: QUIT Apr 22 14:15:11 dedi postfix/smtpd[2970]: > dedi.ludosoft.org[127.0.0.1]: 221 2.0.0 Bye Apr 22 14:15:11 dedi postfix/smtpd[2970]: match_hostname: dedi.ludosoft.org ~? 127.0.0.0/8 Apr 22 14:15:11 dedi postfix/smtpd[2970]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8 Apr 22 14:15:11 dedi postfix/smtpd[2970]: disconnect from dedi.ludosoft.org[127.0.0.1]

Apr 22 14:20:08 dedi postfix/smtpd[2974]: smtp_get: timeout

Apr 22 14:20:08 dedi postfix/smtpd[2974]: > dedi.ludosoft.org[127.0.0.1]: 421 4.4.2 dedi.ludosoft.org Error: timeout exceeded Apr 22 14:20:08 dedi postfix/smtpd[2974]: match_hostname: dedi.ludosoft.org ~? 127.0.0.0/8 Apr 22 14:20:08 dedi postfix/smtpd[2974]: match_hostaddr: 127.0.0.1 ~? 127.0.0.0/8 Apr 22 14:20:08 dedi postfix/smtpd[2974]: timeout after END-OF-MESSAGE from dedi.ludosoft.org[127.0.0.1] Apr 22 14:20:08 dedi postfix/smtpd[2974]: disconnect from dedi.ludosoft.org[127.0.0.1]




My master.cf :

#
# Postfix master process configuration file.  For details on the format
# of the file, see the Postfix master(5) manual page.
#
# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (100)
# ==========================================================================
#smtp      inet  n       -       n       -       -       smtpd
smtp      inet  n       -       n       -       20      smtpd
    -o smtpd_proxy_filter=127.0.0.1:10025
    -o smtpd_client_connection_count_limit=20
    -o smtpd_proxy_timeout=600s
    -o smtp_connection_cache_on_demand=no

...



Why nobody complain ? the response is in the session transcription :
...
Apr 22 14:20:08 dedi postfix/smtpd[2974]: smtp_get: timeout

...

During this time (define by smtpd_proxy_timeout=600s ), there is a lot of pending process from smtpd and perl dkim, this 2 process wait for end of communication, until postfix close the connection by time out. But, normaly postfix smtp must send a 'QUIT' command if the socket is not reuse (cache connexion process) but the param 'smtp_connection_cache_on_demand=no' is not take care.


The mail is transfered well, but the connexion is not terminate properly.

So, like you said in 3.8 of RFC5321 confirm what i said :

3.8.  Terminating Sessions and Connections

   An SMTP connection is terminated when the client sends a QUIT
   command.  The server responds with a positive reply code, after which
   it closes the connection.

   An SMTP server MUST NOT intentionally close the connection under
   normal operational circumstances (see Section 7.8) except:

   o  After receiving a QUIT command and responding with a 221 reply.

   o  After detecting the need to shut down the SMTP service and
      returning a 421 response code.  This response code can be issued
      after the server receives any command or, if necessary,
      asynchronously from command receipt (on the assumption that the
      client will receive it after the next command is issued).

_o  After a timeout, as specified in Section 4.5.3.2, occurs waiting__
__      for the client to send a command or data_

But in this case, dkimproxy is the server, and postfix smpt the client ! Postfix smtp must send 'QUIT' command !


Ludo.

Le 23/04/2013 12:12, Bastian Blank a écrit :

Please fix your MUA, it produces TOFU.

On Tue, Apr 23, 2013 at 11:48:42AM +0200, Ludovic LEVET wrote:

This is not a reply ...

Not showing what the actual problem is, is no question either.
Especially, why are you the only person experiencing this in over three
years?

http://www.ietf.org/rfc/rfc5321.txt
Chapter 4.1.1.10.

You miss 3.8.

Please show a session _transcripts_ for the problem you are talking
about.

Bastian

smime.p7s
Description: Signature cryptographique S/MIME

Re: postfix 2.8 and upper don't close connection with smtpd_proxy_filter

Reply via email to