DKIMproxy / Bugs / #38 dkimproxy.in don't close connection on postfix 2.8 and upper

#38 dkimproxy.in don't close connection on postfix 2.8 and upper

Status: open

Owner: nobody

Labels: dkimproxy (14)

Priority: 5

Updated: 2013-08-02

Created: 2012-06-11

Creator: ludovic

Private: No

I have just update from postfix 2.6.16 to postfix 2.8.11

On postfix 2.6.16 i have :
Jun 11 18:12:14 dedi postfix/smtpd[24068]: Anonymous TLS connection established from filenet.ludosoft.org[82.236.203.193]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
Jun 11 18:12:14 dedi postfix/smtpd[24072]: connect from dedi.ludosoft.org[127.0.0.1]
Jun 11 18:12:14 dedi postfix/smtpd[24068]: NOQUEUE: client=filenet.ludosoft.org[82.236.203.193]
Jun 11 18:12:14 dedi postfix/smtpd[24072]: BD2CF260CDA: client=filenet.ludosoft.org[82.236.203.193]
Jun 11 18:12:14 dedi dkimproxy.in[10747]: DKIM verify - pass; message-id=<4FD618DD.4060208@ludosoft.org>, signer=<llevet@ludosoft.org>, from=<llevet@ludosoft.org>
Jun 11 18:12:14 dedi postfix/cleanup[24073]: BD2CF260CDA: message-id=<4FD618DD.4060208@ludosoft.org>
Jun 11 18:12:14 dedi postfix/qmgr[24031]: BD2CF260CDA: from=<llevet@ludosoft.org>, size=10388, nrcpt=1 (queue active)
Jun 11 18:12:14 dedi postfix/smtpd[24072]: disconnect from dedi.ludosoft.org[127.0.0.1]
Jun 11 18:12:14 dedi postfix/smtpd[24068]: disconnect from filenet.ludosoft.org[82.236.203.193]
Jun 11 18:12:15 dedi lmtpunix[24041]: Delivered: <4FD618DD.4060208@ludosoft.org> to mailbox: user.llevet
Jun 11 18:12:15 dedi postfix/lmtp[24075]: BD2CF260CDA: to=<llevet@dedi.ludosoft.org>, orig_to=<root@dedi.ludosoft.org>, relay=dedi.ludosoft.org[public/lmtp], delay=0.55, delays=0.21/0.02/0.01/0.31, dsn=2.1.5, status=sent (250 2.1.5 Ok)
Jun 11 18:12:15 dedi postfix/qmgr[24031]: BD2CF260CDA: removed

So process '24072' is quit close by a disconnect.

And now with postfix 2.8.11 and upper :
Jun 11 19:40:05 dedi postfix/smtpd[4686]: connect from filenet.ludosoft.org[82.236.203.193]
Jun 11 19:40:05 dedi postfix/smtpd[4686]: Anonymous TLS connection established from filenet.ludosoft.org[82.236.203.193]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
Jun 11 19:40:05 dedi postfix/smtpd[4689]: connect from dedi.ludosoft.org[127.0.0.1]
Jun 11 19:40:05 dedi postfix/smtpd[4686]: NOQUEUE: client=filenet.ludosoft.org[82.236.203.193]
Jun 11 19:40:05 dedi postfix/smtpd[4689]: A1AFA260CCB: client=dedi.ludosoft.org[127.0.0.1], orig_client=filenet.ludosoft.org[82.236.203.193]
Jun 11 19:40:05 dedi dkimproxy.in[4669]: DKIM verify - pass; message-id=<4FD62D74.8070805@ludosoft.org>, signer=<llevet@ludosoft.org>, from=<llevet@ludosoft.org>
Jun 11 19:40:05 dedi postfix/cleanup[4690]: A1AFA260CCB: message-id=<4FD62D74.8070805@ludosoft.org>
Jun 11 19:40:05 dedi postfix/qmgr[4574]: A1AFA260CCB: from=<llevet@ludosoft.org>, size=10388, nrcpt=1 (queue active)
Jun 11 19:40:05 dedi postfix/smtpd[4686]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 Ok: queued as A1AFA260CCB; from=<llevet@ludosoft.org> to=<root@dedi.ludosoft.org> proto=ESMTP helo=<filenet.ludosoft.org>
Jun 11 19:40:05 dedi postfix/smtpd[4686]: disconnect from filenet.ludosoft.org[82.236.203.193]
Jun 11 19:40:06 dedi lmtpunix[4584]: Delivered: <4FD62D74.8070805@ludosoft.org> to mailbox: user.llevet
Jun 11 19:40:06 dedi postfix/lmtp[4692]: A1AFA260CCB: to=<llevet@dedi.ludosoft.org>, orig_to=<root@dedi.ludosoft.org>, relay=dedi.ludosoft.org[public/lmtp], delay=0.55, delays=0.25/0.02/0.01/0.26, dsn=2.1.5, status=sent (250 2.1.5 Ok)
Jun 11 19:40:06 dedi postfix/qmgr[4574]: A1AFA260CCB: removed
Jun 11 19:45:06 dedi postfix/smtpd[4689]: timeout after END-OF-MESSAGE from dedi.ludosoft.org[127.0.0.1]
Jun 11 19:45:06 dedi postfix/smtpd[4689]: disconnect from dedi.ludosoft.org[127.0.0.1]

Process '30465' don't close and i'm waiting for timeout (5mn) from smtpd.

And during this 5 mn i have dkimproxy.in allways connectetd :
[root@dedi lib]# netstat -nap |grep perl
tcp 0 0 127.0.0.1:10025 0.0.0.0:* LISTEN 4667/perl
tcp 0 0 127.0.0.1:10027 0.0.0.0:* LISTEN 4676/perl
tcp 0 0 127.0.0.1:52365 127.0.0.1:10026 ESTABLISHED 4669/perl
unix 2 [ ] DGRAM 2885602 4669/perl

[root@dedi lib]# ps -ef |grep 4669
dkim 4669 4667 0 19:39 ? 00:00:00 /usr/bin/perl -I/usr/local/dkimproxy/lib /usr/local/dkimproxy/bin/dkimproxy.in --user=dkim --group=dkim --daemonize --pidfile=/usr/local/dkimproxy/var/run/dkimproxy_in.pid --hostname=dedi.ludosoft.org --conf_file=/usr/local/dkimproxy/etc/dkimproxy_in.conf

Thank's.

Ludovic.

Discussion

Jason Long - 2012-06-11

Curious behavior.

Is this causing mail delivery to be delayed or stuck? If I am reading your logs correctly, it looks like Postfix processes are staying alive an extra five minutes because of the hung connection, but this is only after it has already delivered the mail. Is that right?

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2012-06-11

Yes, you are right, the mail is deliver, and i think wait for a other mail from the socket (socket reuse). But in real life, i have lot of process who are open and wait for closing.
I think postifig wait for remote close now.

Ludovic.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2012-06-11

I want to said :

I think that postfix wait for remote close now.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2013-04-19

Any news from this problem, it still exists with postfix-2.10.0

Thank's.

Ludovic.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2013-04-19

it seen that the socket is not close after 'end-of-data' and all is ok (IN to OUT).
Before version 2.8 of postfix, the connection was close by him. But today not. So each process (dkim and postfix smtpd) wait for the other to close until postfix time out.

Ludovic.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2013-04-22

Ok, i have found the problem, so since postfix > 2.6.18, the smtpd_proxy_filter don't send command QUIT after the the response (code 250) to END-OF-MESSAGE.

Look at this :

Before with postfix 2.6.18 :
----------------------------
...
Apr 22 14:36:47 dedi dkimproxy.in[18373]: DKIM verify - none; from=<test@ludosoft.org>
Apr 22 14:36:47 dedi postfix/cleanup[4973]: B2FCF261729: message-id=<20130422123631.B2FCF261729@dedi.ludosoft.org>
Apr 22 14:36:47 dedi postfix/qmgr[4966]: B2FCF261729: from=<test@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=<test@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=<test@ludosoft.org>
Apr 22 14:15:08 dedi postfix/cleanup[2975]: C0BBC261729: message-id=<20130422121456.C0BBC261729@dedi.ludosoft.org>
Apr 22 14:15:08 dedi postfix/qmgr[2966]: C0BBC261729: from=<test@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=<test@ludosoft.org> to=<test@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=<test@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]

Ludovic.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2013-04-25

Hi Jason,
I have reported the problem to posfix, so it finish to take the door in my face ...

See the last mail :
-------- Message original --------
Sujet: Re: postfix 2.8 and upper don't close connection with smtpd_proxy_filter
Date : Tue, 23 Apr 2013 17:28:20 -0400 (EDT)
De : Wietse Venema <wietse@porcupine.org>
Répondre à : Postfix users <postfix-users@postfix.org>
Pour : Postfix users <postfix-users@postfix.org>

> > After sending END-OF-MESSAGE, the Postfix smtpd_proxy_CLIENT closes
> > the SMTP connection to the before-queue content filter.
>
> And this is exactly the problem: smtpd_proxy_CLIENT closes the

If you have a problem with "disconnect without quit", then you are
spending too much time in the company of computers.

If some software cannot handle "disconnect without quit", then
please file a bug report there.

I am done with this thread. Go out, have a beer.

Wietse

So, could you modify dkimproxy.in to propagate the lost connection (without QUIT) after the END-OF-MESSAGE to the OUT of dkimproxy.in by a proper QUIT and disconnection.

Thank's a lot.

Ludovic.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ludovic - 2013-08-02

Hi Jason,

Please could you modify the code of dkimproxy.in to detect the disconnection from remote without QUIT command to proper close the connection OUT from dkimproxy.in without waiting timeout.

Thank's.

Ludovic

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

dkimproxy.in don't close connection on postfix 2.8 and upper

Group

Searches

Help

#38 dkimproxy.in don't close connection on postfix 2.8 and upper

Discussion