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

239211milter troubles with dkim-filter-2.5.5 / postfix 2.4.6

Expand Messages
  • Daniel Black
    May 31, 2008
    • 0 Attachment
      Well i'm still trying to solve this problem:
      http://www.mail-archive.com/dkim-milter-discuss%40lists.sourceforge.net/msg00687.html

      The milter fails out logging:
      May 31 06:40:10 lists postfix/cleanup[30657]: 405C8108D9A: milter-reject: END-OF-MESSAGE from lists.cacert.org[172.16.2.17]: 4.7.1 Service
      unavailable - try again later; from=<cacert-support-bounces@...> to=<blue@...> proto=ESMTP

      I've got a later dkim-filter version (2.5.5), moved to inet sockets, added milter debugging.
      I couldn't get a tcpdump as its in a vserver configuration and I don't have the host access.
      Hope the strace at the end is helpful.

      As suggested by the DKIM-milter author a connection resent is caused by trying to talk to a closed socket. The strace doesn't indicate this.
      (http://www.mail-archive.com/dkim-milter-discuss%40lists.sourceforge.net/msg00714.html)

      uname -a
      Linux lists.cacert.org 2.6.18-4-vserver-686 #1 SMP Mon Mar 26 19:55:22 UTC 2007 i686 GNU/Linux

      dkim-filter is listening on inet:172.16.2.17:5000

      dkim-filter -V
      dkim-filter: Sendmail DKIM Filter v2.5.5
      Compiled with OpenSSL 0.9.8c 05 Sep 2006
      Supported signing algorithms:
      rsa-sha1
      rsa-sha256
      Supported canonicalization algorithms:
      relaxed
      simple
      Active code options:
      _FFR_DNS_UPGRADE
      _FFR_REQUIRED_HEADERS
      _FFR_SELECTOR_HEADER
      _FFR_STATS
      _FFR_ZTAGS
      compiled with libmilter-dev 8.13.8-3


      cat /etc/dkim-filter.conf
      MilterDebug 6
      Syslog yes
      LogWhy yes
      SyslogSuccess yes
      UMask 002
      Domain lists.cacert.org
      KeyFile /etc/mail/lists.private
      Selector lists
      InternalHosts /etc/mail/internal.txt
      Statistics /var/run/dkim-filter/dkim-stats

      smtpd -v is used

      May 31 06:40:07 lists postfix/smtpd[30652]: report connect to all milters
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "j"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: result "lists.cacert.org"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{daemon_name}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: result "lists.cacert.org"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "v"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: result "Postfix 2.4.6"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: non-protocol events for protocol version 2: SMFIP_NOUNKNOWN SMFIP_NODATA
      0xfffffc00
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: transport=inet endpoint=172.16.2.17:5000
      May 31 06:40:07 lists postfix/smtpd[30652]: trying... [172.16.2.17]
      May 31 06:40:07 lists postfix/smtpd[30652]: vstream_tweak_tcp: TCP_MAXSEG 16384
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: my_version=0x2
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: my_actions=0x3f SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT
      SMFIF_CHGHDRS SMFIF_QUARANTINE
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: my_events=0x7f SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT
      SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: milter inet:172.16.2.17:5000 version 2
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: events SMFIP_NOHELO SMFIP_NORCPT
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_CHGHDRS SMFIF_QUARANTINE
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_conn_event: milter inet:172.16.2.17:5000: connect lists.cacert.org/172.16.2.17
      May 31 06:40:07 lists postfix/smtpd[30652]: event: SMFIC_CONNECT; macros: j=lists.cacert.org {daemon_name}=lists.cacert.org v=Postfix 2.4.6
      May 31 06:40:07 lists postfix/smtpd[30652]: reply: SMFIR_CONTINUE data 0 bytes
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 220 lists.cacert.org ESMTP Postfix (Debian/GNU)
      May 31 06:40:07 lists postfix/smtpd[30652]: < lists.cacert.org[172.16.2.17]: ehlo lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: report helo to all milters
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{tls_version}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{cipher}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{cipher_bits}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{cert_subject}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{cert_issuer}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_helo_event: milter inet:172.16.2.17:5000: helo lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: event: SMFIC_HELO; macros: (none)
      May 31 06:40:07 lists postfix/smtpd[30652]: skipping event SMFIC_HELO for milter inet:172.16.2.17:5000
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-PIPELINING
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-SIZE 10240000
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-VRFY
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-ETRN
      May 31 06:40:07 lists postfix/smtpd[30652]: match_list_match: lists.cacert.org: no match
      May 31 06:40:07 lists postfix/smtpd[30652]: match_list_match: 172.16.2.17: no match
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-STARTTLS
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-ENHANCEDSTATUSCODES
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250-8BITMIME
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250 DSN
      May 31 06:40:07 lists postfix/smtpd[30652]: < lists.cacert.org[172.16.2.17]: mail FROM:<cacert-support-bounces@...> size=2697
      May 31 06:40:07 lists postfix/smtpd[30652]: extract_addr: input: <cacert-support-bounces@...>
      May 31 06:40:07 lists postfix/smtpd[30652]: smtpd_check_addr: addr=cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: connect to subsystem private/rewrite
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr request = rewrite
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr rule = local
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr address = cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: rewrite_clnt: local: cacert-support-bounces@... -> cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr request = resolve
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr sender =
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr address = cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: transport
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: transport
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: mailman
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: nexthop
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: nexthop
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: recipient
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: recipient
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 256
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: resolve_clnt: `' -> `cacert-support-bounces@...' -> transp=`mailman' host=`lists.cacert.org'
      rcpt=`cacert-support-bounces@...' flags= class=local
      May 31 06:40:07 lists postfix/smtpd[30652]: ctable_locate: install entry key cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: extract_addr: in: <cacert-support-bounces@...>, result:
      cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: report sender to all milters
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "i"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{auth_type}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{auth_authen}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{auth_author}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{mail_addr}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: result "cacert-support-bounces@..."
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_mail_event: milter inet:172.16.2.17:5000: mail <cacert-support-bounces@...>
      size=2697
      May 31 06:40:07 lists postfix/smtpd[30652]: event: SMFIC_MAIL; macros: {mail_addr}=cacert-support-bounces@...
      May 31 06:40:07 lists postfix/smtpd[30652]: reply: SMFIR_CONTINUE data 0 bytes
      May 31 06:40:07 lists postfix/smtpd[30652]: fsspace: .: block size 4096, blocks free 12383577
      May 31 06:40:07 lists postfix/smtpd[30652]: smtpd_check_queue: blocks 4096 avail 12383577 min_free 0 msg_size_limit 10240000
      May 31 06:40:07 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250 2.1.0 Ok
      May 31 06:40:07 lists postfix/smtpd[30652]: < lists.cacert.org[172.16.2.17]: rcpt TO:<blue@...>
      May 31 06:40:07 lists postfix/smtpd[30652]: extract_addr: input: <blue@...>
      May 31 06:40:07 lists postfix/smtpd[30652]: smtpd_check_addr: addr=blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr request = rewrite
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr rule = local
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr address = blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: rewrite_clnt: local: blue@... -> blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr request = resolve
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr sender =
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr address = blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: transport
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: transport
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: smtp
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: nexthop
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: nexthop
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: criticalintegration.com
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: recipient
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: recipient
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 4096
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: resolve_clnt: `' -> `blue@...' -> transp=`smtp' host=`criticalintegration.com'
      rcpt=`blue@...' flags= class=default
      May 31 06:40:07 lists postfix/smtpd[30652]: ctable_locate: install entry key blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: extract_addr: in: <blue@...>, result: blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr request = rewrite
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr rule = local
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr address = postmaster
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: address
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: postmaster@...
      May 31 06:40:07 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: rewrite_clnt: local: postmaster -> postmaster@...
      May 31 06:40:07 lists postfix/smtpd[30652]: >>> START Recipient address RESTRICTIONS <<<
      May 31 06:40:07 lists postfix/smtpd[30652]: generic_checks: name=permit_mynetworks
      May 31 06:40:07 lists postfix/smtpd[30652]: permit_mynetworks: lists.cacert.org 172.16.2.17
      May 31 06:40:07 lists postfix/smtpd[30652]: match_hostname: lists.cacert.org ~? 172.16.2.17
      May 31 06:40:07 lists postfix/smtpd[30652]: match_hostaddr: 172.16.2.17 ~? 172.16.2.17
      May 31 06:40:07 lists postfix/smtpd[30652]: generic_checks: name=permit_mynetworks status=1
      May 31 06:40:07 lists postfix/smtpd[30652]: >>> CHECKING RECIPIENT MAPS <<<
      May 31 06:40:07 lists postfix/smtpd[30652]: ctable_locate: leave existing entry key blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: recipient_canonical_maps: blue@...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost
      May 31 06:40:07 lists postfix/smtpd[30652]: match_list_match: criticalintegration.com: no match
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: recipient_canonical_maps: @...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: mail_addr_find: blue@... -> (not found)
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: canonical_maps: blue@...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost
      May 31 06:40:07 lists postfix/smtpd[30652]: match_list_match: criticalintegration.com: no match
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: canonical_maps: @...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: mail_addr_find: blue@... -> (not found)
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: virtual_alias_maps: blue@...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? lists.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost.cacert.org
      May 31 06:40:07 lists postfix/smtpd[30652]: match_string: criticalintegration.com ~? localhost
      May 31 06:40:07 lists postfix/smtpd[30652]: match_list_match: criticalintegration.com: no match
      May 31 06:40:07 lists postfix/smtpd[30652]: maps_find: virtual_alias_maps: @...: not found
      May 31 06:40:07 lists postfix/smtpd[30652]: mail_addr_find: blue@... -> (not found)
      May 31 06:40:07 lists postfix/smtpd[30652]: report recipient to all milters
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "i"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: "{rcpt_addr}"
      May 31 06:40:07 lists postfix/smtpd[30652]: milter_macro_lookup: result "blue@..."
      May 31 06:40:07 lists postfix/smtpd[30652]: milter8_rcpt_event: milter inet:172.16.2.17:5000: rcpt <blue@...>
      May 31 06:40:07 lists postfix/smtpd[30652]: event: SMFIC_RCPT; macros: {rcpt_addr}=blue@...
      May 31 06:40:07 lists postfix/smtpd[30652]: skipping event SMFIC_RCPT for milter inet:172.16.2.17:5000
      May 31 06:40:07 lists postfix/smtpd[30652]: smtpd_check_rewrite: trying: permit_inet_interfaces
      May 31 06:40:07 lists postfix/smtpd[30652]: permit_inet_interfaces: lists.cacert.org 172.16.2.17
      May 31 06:40:07 lists postfix/smtpd[30652]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc
      enable_address_mapping enable_milters
      May 31 06:40:07 lists postfix/smtpd[30652]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc
      enable_address_mapping enable_milters
      May 31 06:40:07 lists postfix/smtpd[30652]: connect to subsystem public/cleanup
      May 31 06:40:07 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: queue_id
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: queue_id
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 405C8108D9A
      May 31 06:40:07 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr flags = 114
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr conn_macros = j {daemon_name} v
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr helo_macros = {tls_version} {cipher} {cipher_bits} {cert_subject} {cert_issuer}
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr mail_macros = i {auth_type} {auth_authen} {auth_author} {mail_addr}
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr rcpt_macros = i {rcpt_addr}
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr data_macros = i
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr eod_macros = i
      May 31 06:40:07 lists postfix/smtpd[30652]: send attr unk_macros =
      May 31 06:40:07 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: status
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: status
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:07 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: (list terminator)
      May 31 06:40:07 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:07 lists postfix/smtpd[30652]: 405C8108D9A: client=lists.cacert.org[172.16.2.17]

      lots of other log messages

      May 31 06:40:10 lists postfix/smtpd[30652]: < lists.cacert.org[172.16.2.17]: rcpt TO:<joe.blow@...>
      May 31 06:40:10 lists postfix/smtpd[30652]: extract_addr: input: <joe.blow@...>
      May 31 06:40:10 lists postfix/smtpd[30652]: smtpd_check_addr: addr=joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: ctable_locate: purge entry key cacert-support-bounces@...
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr request = rewrite
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr rule = local
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr address = joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: address
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: address
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: rewrite_clnt: local: joe.blow@... -> joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr request = resolve
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr sender =
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr address = joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: transport
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: transport
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: smtp
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: nexthop
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: nexthop
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: trivore.com
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: recipient
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: recipient
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: flags
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: 4096
      May 31 06:40:10 lists postfix/smtpd[30652]: private/rewrite socket: wanted attribute: (list terminator)
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: resolve_clnt: `' -> `joe.blow@...' -> transp=`smtp' host=`trivore.com' rc
      pt=`joe.blow@...' flags= class=default
      May 31 06:40:10 lists postfix/smtpd[30652]: ctable_locate: install entry key joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: extract_addr: in: <joe.blow@...>, result: joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: >>> START Recipient address RESTRICTIONS <<<
      May 31 06:40:10 lists postfix/smtpd[30652]: generic_checks: name=permit_mynetworks
      May 31 06:40:10 lists postfix/smtpd[30652]: permit_mynetworks: lists.cacert.org 172.16.2.17
      May 31 06:40:10 lists postfix/smtpd[30652]: match_hostname: lists.cacert.org ~? 172.16.2.17
      May 31 06:40:10 lists postfix/smtpd[30652]: match_hostaddr: 172.16.2.17 ~? 172.16.2.17
      May 31 06:40:10 lists postfix/smtpd[30652]: generic_checks: name=permit_mynetworks status=1
      May 31 06:40:10 lists postfix/smtpd[30652]: >>> CHECKING RECIPIENT MAPS <<<
      May 31 06:40:10 lists postfix/smtpd[30652]: ctable_locate: leave existing entry key joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: recipient_canonical_maps: joe.blow@...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? lists.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost
      May 31 06:40:10 lists postfix/smtpd[30652]: match_list_match: trivore.com: no match
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: recipient_canonical_maps: @...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: mail_addr_find: joe.blow@... -> (not found)
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: canonical_maps: joe.blow@...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? lists.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost
      May 31 06:40:10 lists postfix/smtpd[30652]: match_list_match: trivore.com: no match
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: canonical_maps: @...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: mail_addr_find: joe.blow@... -> (not found)
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: virtual_alias_maps: joe.blow@...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? lists.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost.cacert.org
      May 31 06:40:10 lists postfix/smtpd[30652]: match_string: trivore.com ~? localhost
      May 31 06:40:10 lists postfix/smtpd[30652]: match_list_match: trivore.com: no match
      May 31 06:40:10 lists postfix/smtpd[30652]: maps_find: virtual_alias_maps: @...: not found
      May 31 06:40:10 lists postfix/smtpd[30652]: mail_addr_find: joe.blow@... -> (not found)
      May 31 06:40:10 lists postfix/smtpd[30652]: report recipient to all milters
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: "i"
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: result "405C8108D9A"
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: "{rcpt_addr}"
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: result "joe.blow@..."
      May 31 06:40:10 lists postfix/smtpd[30652]: milter8_rcpt_event: milter inet:172.16.2.17:5000: rcpt <joe.blow@...>
      May 31 06:40:10 lists postfix/smtpd[30652]: event: SMFIC_RCPT; macros: i=405C8108D9A {rcpt_addr}=joe.blow@...
      May 31 06:40:10 lists postfix/smtpd[30652]: skipping event SMFIC_RCPT for milter inet:172.16.2.17:5000
      May 31 06:40:10 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 250 2.1.5 Ok
      May 31 06:40:10 lists postfix/smtpd[30652]: < lists.cacert.org[172.16.2.17]: data
      May 31 06:40:10 lists postfix/smtpd[30652]: report data to all milters
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: "i"
      May 31 06:40:10 lists postfix/smtpd[30652]: milter_macro_lookup: result "405C8108D9A"
      May 31 06:40:10 lists postfix/smtpd[30652]: milter8_data_event: milter inet:172.16.2.17:5000: data command
      May 31 06:40:10 lists postfix/smtpd[30652]: skipping non-protocol event SMFIC_DATA for milter inet:172.16.2.17:5000
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr conn_macros = j {daemon_name} v
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr helo_macros = {tls_version} {cipher} {cipher_bits} {cert_subject} {cert_issuer}
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr mail_macros = i {auth_type} {auth_authen} {auth_author} {mail_addr}
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr rcpt_macros = i {rcpt_addr}
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr data_macros = i
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr eod_macros = i
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr unk_macros =
      May 31 06:40:10 lists postfix/smtpd[30652]: milter8_send: milter inet:172.16.2.17:5000
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_name = inet:172.16.2.17:5000
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_version = 2
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_actions = 49
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_events = 10
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_non_events = 4294967040
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_state = 4
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_conn_timeout = 30
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_cmd_timeout = 30
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_msg_timeout = 300
      May 31 06:40:10 lists postfix/smtpd[30652]: send attr milter_action = tempfail
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: dummy
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: dummy
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: (list terminator)
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: dummy
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: dummy
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: (list terminator)
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: status
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: status
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: 0
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: (list terminator)
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: (end)
      May 31 06:40:10 lists postfix/smtpd[30652]: > lists.cacert.org[172.16.2.17]: 354 End data with <CR><LF>.<CR><LF>
      May 31 06:40:10 lists postfix/cleanup[30657]: 405C8108D9A: message-id=<20080531062112.8F71AB02A9@...>
      May 31 06:40:10 lists postfix/cleanup[30657]: warning: milter inet:172.16.2.17:5000: can't read SMFIC_HEADER reply packet header: Connection reset
      by peer
      May 31 06:40:10 lists postfix/cleanup[30657]: 405C8108D9A: milter-reject: END-OF-MESSAGE from lists.cacert.org[172.16.2.17]: 4.7.1 Service
      unavailable - try again later; from=<cacert-support-bounces@...> to=<blue@...> proto=ESMTP
      helo=<lists.cacert.org>
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: status
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: status
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute value: 256
      May 31 06:40:10 lists postfix/smtpd[30652]: public/cleanup socket: wanted attribute: reason
      May 31 06:40:10 lists postfix/smtpd[30652]: input attribute name: reason

      strace arround the connection reset:
      30657 06:40:10 <... read resumed> "flags\0000\0address\0cacert-support-b"..., 4096) = 57
      26597 06:40:10 epoll_wait(12, <unfinished ...>
      30656 06:40:10 <... gettimeofday resumed> {1212216010, 268796}, NULL) = 0
      30657 06:40:10 gettimeofday( <unfinished ...>
      30656 06:40:10 write(5, "\300w\0\0\347\0\0\0\1\0\0\0", 12 <unfinished ...>
      26597 06:40:10 <... epoll_wait resumed> {{EPOLLIN, {u32=28, u64=4294967324}}}, 100, 21000) = 1
      30657 06:40:10 <... gettimeofday resumed> {1212216010, 268890}, NULL) = 0
      30656 06:40:10 <... write resumed> ) = 12
      26597 06:40:10 time( <unfinished ...>
      30656 06:40:10 alarm(6000 <unfinished ...>
      30657 06:40:10 write(14, "ish@...!dsn_orig_rcpt=rf"..., 4096 <unfinished ...>
      26597 06:40:10 <... time resumed> NULL) = 1212216010
      30656 06:40:10 <... alarm resumed> ) = 6000
      30657 06:40:10 <... write resumed> ) = 4096
      26597 06:40:10 read(28, <unfinished ...>
      30656 06:40:10 time( <unfinished ...>
      30657 06:40:10 write(14, "pport@...@https://"..., 109 <unfinished ...>
      26597 06:40:10 <... read resumed> "\300w\0\0\347\0\0\0\1\0\0\0", 12) = 12
      30656 06:40:10 <... time resumed> NULL) = 1212216010
      30657 06:40:10 <... write resumed> ) = 109
      26597 06:40:10 epoll_ctl(12, EPOLL_CTL_DEL, 27, {EPOLLIN, {u32=27, u64=13802072053613854747}} <unfinished ...>
      30656 06:40:10 epoll_wait(8, <unfinished ...>
      30657 06:40:10 _llseek(14, 9467, <unfinished ...>
      26597 06:40:10 <... epoll_ctl resumed> ) = 0
      30657 06:40:10 <... _llseek resumed> [9467], SEEK_SET) = 0
      26597 06:40:10 alarm(333 <unfinished ...>
      30657 06:40:10 gettimeofday( <unfinished ...>
      26597 06:40:10 <... alarm resumed> ) = 333
      30657 06:40:10 <... gettimeofday resumed> {1212216010, 269395}, NULL) = 0
      26597 06:40:10 time( <unfinished ...>
      30657 06:40:10 read(14, <unfinished ...>
      26597 06:40:10 <... time resumed> NULL) = 1212216010
      30657 06:40:10 <... read resumed> "N@Received: from lists.cacert.or"..., 4096) = 2930
      26597 06:40:10 epoll_wait(12, <unfinished ...>
      30657 06:40:10 poll([{fd=16, events=POLLOUT, revents=POLLOUT}], 1, 300000) = 1
      30657 06:40:10 write(16, "\0\0\0\20DLi\000405C8108D9A\0\0\0\0\315LReceive"..., 229) = 229
      30657 06:40:10 gettimeofday({1212216010, 269685}, NULL) = 0
      30657 06:40:10 poll([{fd=16, events=POLLIN, revents=POLLIN|POLLERR|POLLHUP}], 1, 300000) = 1
      30657 06:40:10 read(16, 0x8072c70, 4096) = -1 ECONNRESET (Connection reset by peer)
      30657 06:40:10 time([1212216010]) = 1212216010
      30657 06:40:10 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
      30657 06:40:10 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
      30657 06:40:10 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0
      30657 06:40:10 send(7, "<20>May 31 06:40:10 postfix/clea"..., 152, MSG_NOSIGNAL) = 152
      30657 06:40:10 shutdown(16, 2 /* send and receive */) = -1 ENOTCONN (Transport endpoint is not connected)

      mail_version = 2.4.6
      # postconf -n
      alias_database = hash:/etc/aliases
      alias_maps = hash:/etc/aliases
      append_dot_mydomain = no
      biff = no
      config_directory = /etc/postfix
      inet_interfaces = all
      local_transport = mailman
      mailbox_size_limit = 0
      mydestination = lists.cacert.org, localhost.cacert.org, , localhost
      myhostname = lists.cacert.org
      mynetworks = 172.16.2.17, 172.16.2.0/24
      myorigin = /etc/mailname
      non_smtpd_milters = $smtpd_milters
      recipient_delimiter = +
      relayhost =
      smtp_tls_cert_file = $smtpd_tls_cert_file
      smtp_tls_key_file = $smtpd_tls_key_file
      smtp_tls_security_level = may
      smtp_tls_session_cache_database = btree:${queue_directory}/smtp_scache
      smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
      smtpd_milters = inet:172.16.2.17:5000
      smtpd_tls_cert_file = /etc/ssl/certs/ssl-cert-lists-cacert.pem
      smtpd_tls_key_file = /etc/ssl/private/ssl-cert-lists-cacert.key
      smtpd_tls_security_level = may
      smtpd_tls_session_cache_database = btree:${queue_directory}/smtpd_scache
      smtpd_use_tls = yes
      transport_maps = hash:/etc/postfix/transport
      virtual_alias_maps = hash:/etc/postfix/virtual

      Suggestions welcome.

      --

      Daniel Black
      --
      Proudly a Gentoo Linux User.
      Gnu-PG/PGP signed and encrypted email preferred
      http://pgp.mit.edu:11371/pks/lookup?op=get&search=0x76677097
      GPG Signature D934 5397 A84A 6366 9687 9EB2 861A 4ABA 7667 7097
    • Show all 2 messages in this topic