Loading ...
Sorry, an error occurred while loading the content.

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

Expand Messages
  • Ludovic LEVET
    Apr 23 4:01 AM
      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=<test@...>
      Apr 22 14:36:47 dedi postfix/cleanup[4973]: B2FCF261729: message-id=<20130422123631.B2FCF261729@...>
      Apr 22 14:36:47 dedi postfix/qmgr[4966]: B2FCF261729: from=<test@...>, 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@...>, 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@...>
      Apr 22 14:15:08 dedi postfix/cleanup[2975]: C0BBC261729: message-id=<20130422121456.C0BBC261729@...>
      Apr 22 14:15:08 dedi postfix/qmgr[2966]: C0BBC261729: from=<test@...>, 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@...> to=<test@...> 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@...>, 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
      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]
      ...

      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
      
      

    • Show all 17 messages in this topic