added milter (opendmarc). not processing, postfix logs show "abort all milters"?

[PGNd]

I've added an opendmarc milter to a service

[127.0.0.1]:10031 inet n - n - - smtpd
-o syslog_name=postfix/postQ-rcv
> -o milter_protocol=6
> -o smtpd_milters=inet:localhost:8893
> -o non_smtpd_milters=inet:localhost:8893
-o content_filter=relay2vpn:[internal.mail-backend.DDDD.com]:12345
-o receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_address_mappings
-o mynetworks=127.0.0.0/8,10.1.0.25
-o smtpd_authorized_xforward_hosts=127.0.0.0/8
-o smtpd_helo_restrictions=
-o smtpd_client_restrictions=permit_mynetworks,reject
-o smtpd_sender_restrictions=
-o smtpd_relay_restrictions=permit_mynetworks,reject
-o smtpd_recipient_restrictions=permit_mynetworks,reject
-o smtpd_data_restrictions=
-o smtpd_end_of_data_restrictions=
-o smtpd_etrn_restrictions=

opendmarc is listening

telnet localhost 8893
Trying ::1...
telnet: connect to address ::1: Connection refused
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.

on message receipt, I'm not seeing any DMARC verification or header-adds.

on message submit, postfix logs show nothing milter-port-related in non-verbose mode

...
Jun 26 15:24:17 mailhost postfix/postQ-rcv/smtpd[16863]: connect from localhost[127.0.0.1]
Jun 26 15:24:17 mailhost postfix/postQ-rcv/smtpd[16863]: E35FC607D8: client=localhost[127.0.0.1], orig_queue_id=16493607B9, orig_client=out5-smtp.messagingengine.com[66.111.4.29]
Jun 26 15:24:17 mailhost postfix/cleanup[16858]: E35FC607D8: message-id=<1435365254.2685866...@webmail.messagingengine.com>
Jun 26 15:24:17 mailhost postfix/qmgr[16816]: E35FC607D8: from=<te...@XYZW.com>, size=4466, nrcpt=1 (queue active)
Jun 26 15:24:17 mailhost postfix/postQ-rcv/smtpd[16863]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 quit=1 commands=6
Jun 26 15:24:17 mailhost postfix/amavis-feed/smtp[16859]: 16493607B9: to=<postm...@DDDD1.com>, relay=127.0.0.1[127.0.0.1]:20002, delay=0.86, delays=0.01/0.01/0/0.83, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10031): 250 2.0.0 Ok: queued as E35FC607D8)
Jun 26 15:24:17 mailhost postfix/qmgr[16816]: 16493607B9: removed
Jun 26 15:24:18 mailhost postfix/relay2vpn/smtp[16865]: E35FC607D8: to=<postm...@DDDD1.com>, relay=internal.mail-backend.DDDD.com[10.2.0.25]:12345, delay=0.55, delays=0/0.01/0.31/0.22, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 57377102846)
Jun 26 15:24:18 mailhost postfix/qmgr[16816]: E35FC607D8: removed

turning on verbose log for the service, it appears the milter's being skipped & aborted,

...
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: process generation: 14 (14)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: smtpd_client_event_limit_exceptions ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: smtpd_client_event_limit_exceptions: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: mynetworks ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: mynetworks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: host
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: been_here: X.X.X.142/32: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: been_here: X.X.X.143/32: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: mynetworks_core: X.X.X.142/32 X.X.X.143/32
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: mynetworks ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: mynetworks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: relay_domains ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: relay_domains: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: database lmdb:/etc/postfix/relay_transports: using size limit 16777216 during open
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: dict_open: lmdb:/etc/postfix/relay_transports
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: permit_mx_backup_networks ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: permit_mx_backup_networks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: database lmdb:/etc/postfix/aliases: using size limit 16777216 during open
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: dict_open: lmdb:/etc/postfix/aliases
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: database lmdb:/etc/postfix/canonical: using size limit 16777216 during open
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: dict_open: lmdb:/etc/postfix/canonical
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: smtpd_access_maps ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: smtpd_access_maps: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: unknown_helo_hostname_tempfail_action = defer_if_permit
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: unknown_address_tempfail_action = defer_if_permit
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: unverified_recipient_tempfail_action = defer_if_permit
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: unverified_sender_tempfail_action = defer_if_permit
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: auto_clnt_create: transport=local endpoint=private/tlsmgr
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: auto_clnt_open: connected to private/tlsmgr
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = seed
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr size = 32
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: seed
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: seed
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: DNM6Z7LQhf4qkvDtx61j1cJe5z2N5YButGRFw3IPD3I=
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = policy
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr cache_type = smtpd
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: cachable
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: cachable
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: timeout
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: timeout
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 3600
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/tlsmgr: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_string: parent_domain_matches_subdomains: fast_flush_domains ~? debug_peer_list
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: fast_flush_domains: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: no_header_body_checks
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: no_unknown_recipient_checks
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: no_address_mappings
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: auto_clnt_create: transport=local endpoint=private/anvil
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: connection established
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: master_notify: status 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: resource
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: software
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: connect from localhost[127.0.0.1]
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: localhost: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: 127.0.0.1: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: smtpd_authorized_xforward_hosts: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: smtpd_authorized_xforward_hosts: 127.0.0.1 ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: smtp_stream_setup: maxtime=300 enable_deadline=0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: smtpd_client_event_limit_exceptions: 127.0.0.1 ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: silent-discard
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: etrn
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: dsn
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> START Client host RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: permit_mynetworks: localhost 127.0.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: mynetworks: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: mynetworks: 127.0.0.1 ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: permit_mynetworks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks status=1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> END Client host RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: report connect to all milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "j"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "mailhost.DDDD.com"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{daemon_name}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "mailhost.DDDD.com"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "v"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "Postfix 3.0.1"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: non-protocol events for protocol version 4:
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: transport=inet endpoint=localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: trying... [127.0.0.1]
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: vstream_tweak_tcp: TCP_MAXSEG 21845
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: fd=17: stream buffer size old=0 new=43690
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: my_version=0x4
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: my_events=0x37f SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH SMFIP_NOUNKNOWN SMFIP_NODATA
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: milter inet:localhost:8893 version 4
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: events SMFIP_NOHELO SMFIP_NOBODY SMFIP_NOUNKNOWN SMFIP_NODATA
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_ADDRCPT SMFIF_QUARANTINE
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_conn_event: milter inet:localhost:8893: connect localhost/127.0.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: event: SMFIC_CONNECT; macros: j=mailhost.DDDD.com {daemon_name}=mailhost.DDDD.com v=Postfix 3.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: reply: SMFIR_ACCEPT data 0 bytes
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 220 mail.DDDD.com ESMTP . No UCE permitted.
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: EHLO localhost
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: report helo to all milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{tls_version}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{cipher}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{cipher_bits}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{cert_subject}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{cert_issuer}"
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_helo_event: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: localhost: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: 127.0.0.1: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-mailhost.DDDD.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-PIPELINING
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-SIZE 10240000
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-VRFY
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-STARTTLS
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250-ENHANCEDSTATUSCODES
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250 8BITMIME
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: XFORWARD ADDR=66.111.4.29 NAME=out5-smtp.messagingengine.com PORT=52682 PROTO=ESMTP HELO=out5-smtp.messagingengine.com SOURCE=REMOTE IDENT=4C82B607B9
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250 2.0.0 Ok
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: MAIL FROM:<te...@XYZW.com> BODY=7BIT
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: extract_addr: input: <te...@XYZW.com>
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: smtpd_check_addr: addr=te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: connect to subsystem private/rewrite
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = rewrite
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr rule = local
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr address = te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: rewrite_clnt: local: te...@XYZW.com -> te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = resolve
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr sender =
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr address = te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: transport
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: transport
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: amavisfeed
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: nexthop
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: nexthop
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: [127.0.0.1]:20003
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: recipient
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: recipient
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 4096
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: resolve_clnt: `' -> `te...@XYZW.com' -> transp=`amavisfeed' host=`[127.0.0.1]:20003' rcpt=`te...@XYZW.com' flags= class=default
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: install entry key te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: extract_addr: in: <te...@XYZW.com>, result: te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = rewrite
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr rule = local
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr address = double-bounce
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: double...@mail.DDDD.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: rewrite_clnt: local: double-bounce -> double...@mail.DDDD.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: report sender to all milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "i"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{auth_type}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{auth_authen}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{auth_author}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{mail_addr}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "te...@XYZW.com"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{mail_host}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "[127.0.0.1]:20003"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{mail_mailer}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key te...@XYZW.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "amavisfeed"
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_mail_event: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: smtpd_check_rewrite: trying: permit_inet_interfaces
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: permit_inet_interfaces: localhost 127.0.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: fsspace: .: block size 4096, blocks free 1216777
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: smtpd_check_queue: blocks 4096 avail 1216777 min_free 0 msg_size_limit 10240000
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250 2.1.0 Ok
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: RCPT TO:<postm...@DDDD1.com>
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: extract_addr: input: <postm...@DDDD1.com>
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: smtpd_check_addr: addr=postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = rewrite
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr rule = local
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr address = postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: address
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: rewrite_clnt: local: postm...@DDDD1.com -> postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr request = resolve
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr sender =
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr address = postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: transport
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: transport
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: relay2vpn
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: nexthop
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: nexthop
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: [internal.mail-backend.DDDD.com]:12345
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: recipient
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: recipient
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: flags
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 2048
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: private/rewrite socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: resolve_clnt: `' -> `postm...@DDDD1.com' -> transp=`relay2vpn' host=`[internal.mail-backend.DDDD.com]:12345' rcpt=`postm...@DDDD1.com' flags= class=relay
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: install entry key postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: extract_addr: in: <postm...@DDDD1.com>, result: postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> START Recipient address RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: permit_mynetworks: localhost 127.0.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: mynetworks: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: mynetworks: 127.0.0.1 ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: permit_mynetworks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks status=1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> END Recipient address RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> START Recipient address RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: permit_mynetworks: localhost 127.0.0.1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: mynetworks: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: mynetworks: 127.0.0.1 ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_list_match: permit_mynetworks: no match
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: generic_checks: name=permit_mynetworks status=1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: >>> END Recipient address RESTRICTIONS <<<
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: report recipient to all milters (flags=0x0)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "i"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{rcpt_addr}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "postm...@DDDD1.com"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{rcpt_host}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "[internal.mail-backend.DDDD.com]:12345"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "{rcpt_mailer}"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: ctable_locate: leave existing entry key postm...@DDDD1.com
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "relay2vpn"
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_rcpt_event: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: after input_transp_cleanup: cleanup flags = enable_milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: sendmail
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: name_mask: verify
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: connect to subsystem public/cleanup
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: public/cleanup socket: wanted attribute: queue_id
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: queue_id
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 3538F607D8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: public/cleanup socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send attr flags = 192
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send 0 milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: 3538F607D8: client=localhost[127.0.0.1], orig_queue_id=4C82B607B9, orig_client=out5-smtp.messagingengine.com[66.111.4.29]
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250 2.1.5 Ok
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: DATA
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: report data to all milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: "i"
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter_macro_lookup: result "3538F607D8"
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_data_event: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: send 0 milters
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 354 End data with <CR><LF>.<CR><LF>
Jun 26 15:27:19 mailhost postfix/cleanup[17014]: 3538F607D8: message-id=<1435365432.2686125...@webmail.messagingengine.com>
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: public/cleanup socket: wanted attribute: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: status
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: 0
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: public/cleanup socket: wanted attribute: reason
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: reason
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute value: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: public/cleanup socket: wanted attribute: (list terminator)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: input attribute name: (end)
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 250 2.0.0 Ok: queued as 3538F607D8
Jun 26 15:27:19 mailhost postfix/qmgr[16972]: 3538F607D8: from=<te...@XYZW.com>, size=4462, nrcpt=1 (queue active)

>>>Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: abort all milters
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_abort: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: < localhost[127.0.0.1]: QUIT
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: > localhost[127.0.0.1]: 221 2.0.0 Bye
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostname: smtpd_client_event_limit_exceptions: localhost ~? 127.0.0.0/8
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: match_hostaddr: smtpd_client_event_limit_exceptions: 127.0.0.1 ~? 127.0.0.0/8
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: abort all milters
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_abort: skip milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: disconnect event to all milters
>>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_disc_event: skip quit milter inet:localhost:8893
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 quit=1 commands=6
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: master_notify: status 1
Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: connection closed
Jun 26 15:27:19 mailhost postfix/amavis-feed/smtp[17015]: 4C82B607B9: to=<postm...@DDDD1.com>, relay=127.0.0.1[127.0.0.1]:20002, delay=0.93, delays=0.01/0.01/0/0.9, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10031): 250 2.0.0 Ok: queued as 3538F607D8)
Jun 26 15:27:19 mailhost postfix/qmgr[16972]: 4C82B607B9: removed
Jun 26 15:27:19 mailhost postfix/relay2vpn/smtp[17021]: 3538F607D8: to=<postm...@DDDD1.com>, relay=internal.mail-backend.DDDD.com[10.2.0.25]:12345, delay=0.57, delays=0.03/0.01/0.3/0.23, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 9BBE2102846)
Jun 26 15:27:19 mailhost postfix/qmgr[16972]: 3538F607D8: removed
Jun 26 15:27:24 mailhost postfix/postQ-rcv/smtpd[17019]: auto_clnt_close: disconnect private/tlsmgr stream
Jun 26 15:27:24 mailhost postfix/postQ-rcv/smtpd[17019]: rewrite stream disconnect


Why is the message not making it to that milter for processing?

[Benny Pedersen]

PGNd skrev den 2015-06-27 02:53:
> I've added an opendmarc milter to a service
>
> [127.0.0.1]:10031 inet n - n - -
> smtpd
> -o syslog_name=postfix/postQ-rcv
>> -o milter_protocol=6
>> -o smtpd_milters=inet:localhost:8893
>> -o non_smtpd_milters=inet:localhost:8893
> -o content_filter=relay2vpn:[internal.mail-backend.DDDD.com]:12345
> -o
> receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_address_mappings
> -o mynetworks=127.0.0.0/8,10.1.0.25
> -o smtpd_authorized_xforward_hosts=127.0.0.0/8
> -o smtpd_helo_restrictions=
> -o smtpd_client_restrictions=permit_mynetworks,reject
> -o smtpd_sender_restrictions=
> -o smtpd_relay_restrictions=permit_mynetworks,reject
> -o smtpd_recipient_restrictions=permit_mynetworks,reject
> -o smtpd_data_restrictions=
> -o smtpd_end_of_data_restrictions=
> -o smtpd_etrn_restrictions=

note missing ipv6 on above ?

localhost is resolvin dual stacking, so make sure postfix accept aswell
:-)

>
> opendmarc is listening
>
> telnet localhost 8893
> Trying ::1...
> telnet: connect to address ::1: Connection refused

is opendmarc compiled with ipv6 support ?

change smtpd_milters= to be inet:[127.0.0.1]:8893 so it does not use
ipv6 there, this should all needed

> Trying 127.0.0.1...
> Connected to localhost.
> Escape character is '^]'.

this tells me something about it

> Why is the message not making it to that milter for processing?

some loves dual stacking, some hate it

[PGNd]

On Fri, Jun 26, 2015, at 06:12 PM, Benny Pedersen wrote:
> change smtpd_milters= to be inet:[127.0.0.1]:8893 so it does not use
> ipv6 there, this should all needed

Did that. Unfortunately, there's no change in behavior or logs, other than the reference, now, to 127.0.0.1 specifically,

...
milter8_abort: skip milter inet:[127.0.0.1]:8893

disconnect event to all milters

milter8_disc_event: skip quit milter inet:[127.0.0.1]:8893
...

[Benny Pedersen]

PGNd skrev den 2015-06-27 03:36:
> On Fri, Jun 26, 2015, at 06:12 PM, Benny Pedersen wrote:
>> change smtpd_milters= to be inet:[127.0.0.1]:8893 so it does not use
>> ipv6 there, this should all needed
>
> Did that. Unfortunately, there's no change in behavior or logs, other
> than the reference, now, to 127.0.0.1 specifically,

i forgot to tell remove non_smtpd_milters, since it is not used in smtpd
listners

> ...
> milter8_abort: skip milter inet:[127.0.0.1]:8893
> disconnect event to all milters
> milter8_disc_event: skip quit milter inet:[127.0.0.1]:8893
> ...

where is this ?, is it opendmarc ?

if its opendmarc follow up to that maillist

[PGNd]

On Fri, Jun 26, 2015, at 07:02 PM, Benny Pedersen wrote:
> i forgot to tell remove non_smtpd_milters, since it is not used in smtpd
> listners

Thanks for the cleanup. Although, no add'l effect on the issue.

> > milter8_abort: skip milter inet:[127.0.0.1]:8893
> > disconnect event to all milters
> > milter8_disc_event: skip quit milter inet:[127.0.0.1]:8893
> > ...
>
> where is this ?, is it opendmarc ?

Yes, it is.

> if its opendmarc follow up to that maillist

It's not clear to me that opendmarc is doing the rejection. At the moment, I'm getting no transaction logs from it.

In any case, posted to the opendmarc-users list.

[A. Schulze]

PGNd:

> I've added an opendmarc milter to a service
>
> [127.0.0.1]:10031 inet n - n - - smtpd

> -o smtpd_milters=inet:localhost:8893

>
> Why is the message not making it to that milter for processing?

just answerd on opendmarc-users but for reference here too:
opendmarc defaults to ignore connections from localhost.
It's a little uncommon to use opendmarc after amavis resubmit the message.
Usually the milter is used just behind the milter checking spf and opendkim

Andreas

[Wietse Venema]

PGNd:

> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: event: SMFIC_CONNECT; macros: j=mailhost.DDDD.com {daemon_name}=mailhost.DDDD.com v=Postfix 3.0.1
> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: reply: SMFIR_ACCEPT data 0 bytes

The milter replies to the CONNECT event with ACCEPT. That is a FINAL
decision. Therefore, the milter is skipped for the HELO, MAIL, RCPT,
etc. events.

Wietse

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_helo_event: skip milter inet:localhost:8893

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_mail_event: skip milter inet:localhost:8893

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_rcpt_event: skip milter inet:localhost:8893

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_data_event: skip milter inet:localhost:8893

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_abort: skip milter inet:localhost:8893
> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_abort: skip milter inet:localhost:8893

> >>> Jun 26 15:27:19 mailhost postfix/postQ-rcv/smtpd[17019]: milter8_disc_event: skip quit milter inet:localhost:8893

[PGNd]

On Sat, Jun 27, 2015, at 01:35 AM, A. Schulze wrote:
> just answerd on opendmarc-users but for reference here too:
> opendmarc defaults to ignore connections from localhost.

That was it. Obvious, now ...

On received messages,

...
DMARC-Filter: OpenDMARC Filter v1.3.1 mailhost.DDDD.com 73D12117C8
Authentication-Results: mail.DDDD.com; dmarc=pass header.from=gmail.com
...

Thanks for the catch!

> It's a little uncommon to use opendmarc after amavis resubmit the message.
> Usually the milter is used just behind the milter checking spf and opendkim

In my current setup, amavisd is doing the DKIM verification. I found some discussion on amavsid list re: the possibility of integrating DMARC, but afaik that did not occcur.

Hence, in this case Opendmarc needs to exec after.

[Steve Jenkins]

On Sat, Jun 27, 2015 at 1:35 AM, A. Schulze <s...@andreasschulze.de> wrote:

It's a little uncommon to use opendmarc after amavis resubmit the message.
Usually the milter is used just behind the milter checking spf and opendkim

And now that OpenDMARC can use libspf2, I don't use a separate SPF checker in my Postfix setup. Just running OpenDKIM and OpenDMARC milters.

SteveJ 

[PGNd]

On Sat, Jun 27, 2015, at 08:18 AM, Steve Jenkins wrote:
> And now that OpenDMARC can use libspf2, I don't use a separate SPF checker
> in my Postfix setup. Just running OpenDKIM and OpenDMARC milters.

Good point.

Unfortunately, after rebuilding opendmarc with spf enabled, using libspf2, on exec of the milter from within postfix the session returns:

...
In: MAIL FROM:<XX...@gmail.com> SIZE=1764
Out: 250 2.1.0 Ok
In: RCPT TO:<te...@DDDD1.com>
Out: 250 2.1.5 Ok
In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
In: QUIT
Out: 221 2.0.0 Bye

I seem to recall mention about this -- perhaps, needing to add some header? Now to find whatever it was ...

[Viktor Dukhovni]

On Sat, Jun 27, 2015 at 10:03:10AM -0700, PGNd wrote:
>
>
> On Sat, Jun 27, 2015, at 08:18 AM, Steve Jenkins wrote:
> > And now that OpenDMARC can use libspf2, I don't use a separate SPF checker
> > in my Postfix setup. Just running OpenDKIM and OpenDMARC milters.
>
> Good point.
>
> Unfortunately, after rebuilding opendmarc with spf enabled, using libspf2, on exec of the milter from within postfix the session returns:
>
> ...
> In: MAIL FROM:<XX...@gmail.com> SIZE=1764
> Out: 250 2.1.0 Ok
> In: RCPT TO:<te...@DDDD1.com>
> Out: 250 2.1.5 Ok
> In: DATA
> Out: 354 End data with <CR><LF>.<CR><LF>
> Out: 451 4.3.0 Error: queue file write error
> In: QUIT
> Out: 221 2.0.0 Bye

The Postfix logs will contain more specific details. Always look
there, and turn off the postmaster notices.

--
Viktor.

[PGNd]

On Sat, Jun 27, 2015, at 10:21 AM, Viktor Dukhovni wrote:
> The Postfix logs will contain more specific details. Always look
> there,

Certainly. Poking at it now.

> turn off the postmaster notices.

To what specifically are you referring? My testmail was TO my postmaster address, so we see it logged.

Have I missed some unnecessary noise?

[Viktor Dukhovni]

On Sat, Jun 27, 2015 at 12:34:06PM -0700, PGNd wrote:

> > turn off the postmaster notices.
>
> To what specifically are you referring? My testmail was TO my postmaster
> address, so we see it logged.

You posted a chat transcript of an SMTP session, that looks remarkably
like a postmaster notice that results from a non-empty "notify_classes":

http://www.postfix.org/postconf.5.html#notify_classes

You're likely better off setting this empty, and looking for trouble
in the logs instead.

--
Viktor.

[PGNd]

You are correct, It's at its default

notify_classes = resource, software

I hadn't gotten around to that one yet ...

Thanks.