domain bin (catch all) forwarding to gmail attempts to deliver locally resulting in 'User doesn't exist:' error.

[Former user]

hi,

i have a domain bin setup to handle mail for any addresses that are not setup on my postie server.

i am using Poste Free (2.0.7)

the mail flow i expect is

[e-mail]                      ->       [e-mail]
(does not exist and is caught by domain bin)              (sent to gmail)

This was working correctly on previous versions of poste (1.0.4) with qsmtpd

Since upgrading to the latest version of Poste (2.0.7) i now see

2018-05-23T09:39:43.283Z [1] [PROTOCOL] [outbound] S: 550 5.1.1 <[e-mail]> User doesn't exist: [e-mail]\r\n

It appears mail is getting delivered locally rather than to the remote gmail servers.

root@29071010ae3b:/# cat /data/log/delivery/2018-05-23-total | grep -i phan
2018-05-23T09:39:41.926Z [EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1] 167.89.37.79:45539%o4.em.bitbucket.org () <bounces+2418806-d28c-bitbucket=[e-mail]> -> <[e-mail]> - [2.5][<[e-mail]>] 250 Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)
2018-05-23T10:07:23.017Z [9CFD1D78-1E9D-4655-B119-0D82079C437A.1] 145.249.105.25:43104%NXDOMAIN () <[e-mail]> -> <[e-mail]> - [21.2][] 250 Quarantined! (9CFD1D78-1E9D-4655-B119-0D82079C437A.1)


root@29071010ae3b:/# cat /data/log/delivery/del/E/F/EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1 
2018-05-23T09:39:41.862Z [1] [DEBUG] [outbound] running send_email hooks
2018-05-23T09:39:41.862Z [1] [DEBUG] [outbound] Sending mail: 1527068381748_1527068381748_0_615_hnneWU_1_29071010ae3b
2018-05-23T09:39:41.862Z [1] [DEBUG] [outbound] running get_mx hooks
2018-05-23T09:39:41.862Z [1] [DEBUG] [outbound] running get_mx hook in relay plugin
2018-05-23T09:39:41.863Z [1] [DEBUG] [outbound] hook=get_mx plugin=relay function=force_routing params=gmail.com retval=CONT msg=""
2018-05-23T09:39:41.863Z [1] [DEBUG] [outbound] running get_mx hook in rcpt_database plugin
2018-05-23T09:39:41.866Z [1] [DEBUG] [outbound] hook=get_mx plugin=rcpt_database function=hook_get_mx params=gmail.com retval=CONT msg=""
2018-05-23T09:39:41.866Z [1] [DEBUG] [outbound] running get_mx hook in queue/lmtp plugin
2018-05-23T09:39:41.866Z [1] [INFO] [outbound] hook=get_mx plugin=queue/lmtp function=hook_get_mx params=gmail.com retval=OK msg="[object Object]"
2018-05-23T09:39:41.867Z [1] [DEBUG] [outbound] Got an MX from Plugin: gmail.com => 0 [object Object]
2018-05-23T09:39:41.869Z [1] [INFO] [outbound] Attempting to deliver to: 127.0.0.1:24 using LMTP (0) (0)
2018-05-23T09:39:42.463Z [1] [PROTOCOL] [outbound] S: 220 mx.mydomainname.com Dovecot ready.\r\n
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] C: LHLO mx.mydomainname.com
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] S: 250-mx.mydomainname.com\r\n
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] S: 250-STARTTLS\r\n
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] S: 250-8BITMIME\r\n
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] S: 250-ENHANCEDSTATUSCODES\r\n
2018-05-23T09:39:42.464Z [1] [PROTOCOL] [outbound] S: 250 PIPELINING\r\n
2018-05-23T09:39:42.465Z [1] [PROTOCOL] [outbound] C: STARTTLS
2018-05-23T09:39:42.466Z [1] [PROTOCOL] [outbound] S: 220 2.0.0 Begin TLS negotiation now.\r\n
2018-05-23T09:39:43.023Z [1] [INFO] [outbound] secured verified=false cipher=DHE-RSA-AES256-GCM-SHA384 version=TLSv1/SSLv3 error="Hostname/IP doesn't match certificate's altnames: \"IP: 127.0.0.1 is not in the cert's list: \"" cn=mx.mydomainname.com organization="" issuer="Let's Encrypt" expires="Aug 11 04:28:22 2018 GMT" fingerprint=D5:89:77:94:44:1B:A5:95:F1:9F:D5:F8:35:47:A1:34:AF:31:56:3D
2018-05-23T09:39:43.023Z [1] [PROTOCOL] [outbound] C: LHLO mx.mydomainname.com
2018-05-23T09:39:43.024Z [1] [PROTOCOL] [outbound] S: 250-mx.mydomainname.com\r\n
2018-05-23T09:39:43.061Z [1] [PROTOCOL] [outbound] S: 250-8BITMIME\r\n
2018-05-23T09:39:43.061Z [1] [PROTOCOL] [outbound] S: 250-ENHANCEDSTATUSCODES\r\n
2018-05-23T09:39:43.061Z [1] [PROTOCOL] [outbound] S: 250 PIPELINING\r\n
2018-05-23T09:39:43.061Z [1] [PROTOCOL] [outbound] C: MAIL FROM:<bounces+2418806-d28c-bitbucket=[e-mail]>
2018-05-23T09:39:43.062Z [1] [PROTOCOL] [outbound] S: 250 2.1.0 OK\r\n
2018-05-23T09:39:43.062Z [1] [PROTOCOL] [outbound] C: RCPT TO:<[e-mail]>
2018-05-23T09:39:43.283Z [1] [PROTOCOL] [outbound] S: 550 5.1.1 <[e-mail]> User doesn't exist: [e-mail]\r\n
2018-05-23T09:39:43.283Z [1] [NOTICE] [outbound] recipient <[e-mail]> rejected: 550 5.1.1 <[e-mail]> User doesn't exist: [e-mail]
2018-05-23T09:39:43.298Z [1] [INFO] [outbound] bouncing mail: Some recipients failed: <[e-mail]>
2018-05-23T09:39:43.298Z [1] [DEBUG] [outbound] running bounce hooks
2018-05-23T09:39:43.298Z [1] [DEBUG] [outbound] running bounce hook in stats plugin
2018-05-23T09:39:43.299Z [1] [PROTOCOL] [outbound] C: RSET
2018-05-23T09:39:43.299Z [1] [PROTOCOL] [outbound] S: 250 2.0.0 OK\r\n
2018-05-23T09:39:43.304Z [1] [DEBUG] [outbound] hook=bounce plugin=stats function=hook_bounce params="" retval=CONT msg=""
2018-05-23T09:39:43.304Z [1] [DEBUG] [outbound] running bounce hook in srs plugin
2018-05-23T09:39:43.304Z [1] [DEBUG] [outbound] hook=bounce plugin=srs function=hook_bounce params="" retval=CONT msg=""
root@29071010ae3b:/# 


root@29071010ae3b:/# cat /data/log/delivery/tx/E/F/EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1 
2018-05-23T09:39:31.532Z [DEBUG] [core] running mail hooks
2018-05-23T09:39:31.533Z [DEBUG] [core] running mail hook in limits plugin
2018-05-23T09:39:31.533Z [DEBUG] [core] hook=mail plugin=limits function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.533Z [DEBUG] [core] running mail hook in mail_from.is_resolvable plugin
2018-05-23T09:39:31.584Z [DEBUG] [mail_from.is_resolvable] em.bitbucket.org: MX 20 mx.sendgrid.net => 167.89.118.48
2018-05-23T09:39:31.585Z [DEBUG] [mail_from.is_resolvable] em.bitbucket.org: 167.89.118.48
2018-05-23T09:39:31.585Z [DEBUG] [core] hook=mail plugin=mail_from.is_resolvable function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.585Z [DEBUG] [core] running mail hook in spf plugin
2018-05-23T09:39:31.644Z [INFO] [spf] identity=mfrom ip=167.89.37.79 domain="em.bitbucket.org" mfrom=<bounces+2418806-d28c-bitbucket=[e-mail]> result=Pass
2018-05-23T09:39:31.645Z [INFO] [spf] scope: mfrom, result: Pass, domain: em.bitbucket.org
2018-05-23T09:39:31.646Z [DEBUG] [core] hook=mail plugin=spf function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.646Z [DEBUG] [core] running mail hook in data.uribl plugin
2018-05-23T09:39:31.646Z [DEBUG] [data.uribl] (envfrom) found 1 items for lookup
2018-05-23T09:39:31.646Z [DEBUG] [data.uribl] (envfrom) checking: em.bitbucket.org
2018-05-23T09:39:31.674Z [DEBUG] [data.uribl] em.bitbucket.org.dbl.spamhaus.org. => (Error: queryA ENOTFOUND em.bitbucket.org.dbl.spamhaus.org.)
2018-05-23T09:39:31.675Z [DEBUG] [core] hook=mail plugin=data.uribl function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.675Z [DEBUG] [core] running mail hook in known-senders plugin
2018-05-23T09:39:31.718Z [INFO] [known-senders] [ 'o4.em.bitbucket.org' ]
2018-05-23T09:39:31.719Z [INFO] [known-senders] +fcrdns: bitbucket.org
2018-05-23T09:39:31.720Z [DEBUG] [core] hook=mail plugin=known-senders function=is_authenticated params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.720Z [DEBUG] [core] running mail hook in bounce plugin
2018-05-23T09:39:31.720Z [DEBUG] [core] hook=mail plugin=bounce function=reject_all params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.720Z [DEBUG] [core] running mail hook in log plugin
2018-05-23T09:39:31.720Z [PROTOCOL] [core] C: MAIL FROM:<bounces+2418806-d28c-bitbucket=[e-mail]> state=1
2018-05-23T09:39:31.723Z [DEBUG] [core] hook=mail plugin=log function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.723Z [DEBUG] [core] running mail hook in dovecot_quota plugin
2018-05-23T09:39:31.725Z [DEBUG] [core] hook=mail plugin=dovecot_quota function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.725Z [DEBUG] [core] running mail hook in karma plugin
2018-05-23T09:39:31.725Z [DEBUG] [core] hook=mail plugin=karma function=hook_mail params="<bounces+2418806-d28c-bitbucket=[e-mail]>" retval=CONT msg=""
2018-05-23T09:39:31.734Z [NOTICE] [core] sender <bounces+2418806-d28c-bitbucket=[e-mail]> code=CONT msg=""
2018-05-23T09:39:31.735Z [PROTOCOL] [core] S: 250 sender <bounces+2418806-d28c-bitbucket=[e-mail]> OK
2018-05-23T09:39:31.906Z [PROTOCOL] [core] C: RCPT TO:<[e-mail]> state=1
2018-05-23T09:39:31.907Z [DEBUG] [core] running rcpt hooks
2018-05-23T09:39:31.907Z [DEBUG] [core] running rcpt hook in srs plugin
2018-05-23T09:39:31.907Z [DEBUG] [core] hook=rcpt plugin=srs function=hook_rcpt params=<[e-mail]> retval=CONT msg=""
2018-05-23T09:39:31.907Z [DEBUG] [core] running rcpt hook in guard plugin
2018-05-23T09:39:31.908Z [DEBUG] [core] hook=rcpt plugin=guard function=hook_rcpt params=<[e-mail]> retval=CONT msg=""
2018-05-23T09:39:31.908Z [DEBUG] [core] running rcpt hook in rcpt_database plugin
2018-05-23T09:39:31.993Z [DEBUG] [rcpt_database] rewriting to domain bin from [e-mail] to [e-mail]
2018-05-23T09:39:31.994Z [INFO] [core] hook=rcpt plugin=rcpt_database function=database_rcpt params=<[e-mail]> retval=OK msg=""
2018-05-23T09:39:31.995Z [DEBUG] [core] running rcpt_ok hooks
2018-05-23T09:39:31.995Z [DEBUG] [core] running rcpt_ok hook in known-senders plugin
2018-05-23T09:39:31.998Z [INFO] [known-senders] gmail.com : bitbucket.org : null
2018-05-23T09:39:31.998Z [DEBUG] [core] hook=rcpt_ok plugin=known-senders function=check_recipient params="" retval=CONT msg=""
2018-05-23T09:39:31.998Z [DEBUG] [core] running rcpt_ok hook in karma plugin
2018-05-23T09:39:31.999Z [DEBUG] [core] hook=rcpt_ok plugin=karma function=hook_rcpt_ok params="" retval=CONT msg=""
2018-05-23T09:39:31.999Z [NOTICE] [core] recipient <[e-mail]> code=OK msg="" sender="bounces+2418806-d28c-bitbucket=[e-mail]"
2018-05-23T09:39:31.999Z [PROTOCOL] [core] S: 250 recipient <[e-mail]> OK
2018-05-23T09:39:32.170Z [PROTOCOL] [core] C: DATA state=1
2018-05-23T09:39:32.172Z [DEBUG] [core] running data hooks
2018-05-23T09:39:32.173Z [DEBUG] [core] running data hook in early_talker plugin
2018-05-23T09:39:37.174Z [DEBUG] [core] hook=data plugin=early_talker function=early_talker params="" retval=CONT msg=""
2018-05-23T09:39:37.174Z [DEBUG] [core] running data hook in data.uribl plugin
2018-05-23T09:39:37.174Z [DEBUG] [core] hook=data plugin=data.uribl function=hook_data params="" retval=CONT msg=""
2018-05-23T09:39:37.174Z [DEBUG] [core] running data hook in bounce plugin
2018-05-23T09:39:37.175Z [DEBUG] [core] hook=data plugin=bounce function=single_recipient params="" retval=CONT msg=""
2018-05-23T09:39:37.175Z [DEBUG] [core] running data hook in bounce plugin
2018-05-23T09:39:37.175Z [DEBUG] [core] hook=data plugin=bounce function=bad_rcpt params="" retval=CONT msg=""
2018-05-23T09:39:37.175Z [DEBUG] [core] running data hook in bounce plugin
2018-05-23T09:39:37.175Z [DEBUG] [core] hook=data plugin=bounce function=bounce_spf_enable params="" retval=CONT msg=""
2018-05-23T09:39:37.175Z [DEBUG] [core] running data hook in attachment plugin
2018-05-23T09:39:37.176Z [DEBUG] [core] hook=data plugin=attachment function=hook_data params="" retval=CONT msg=""
2018-05-23T09:39:37.176Z [DEBUG] [core] running data hook in clamd plugin
2018-05-23T09:39:37.176Z [DEBUG] [core] hook=data plugin=clamd function=hook_data params="" retval=CONT msg=""
2018-05-23T09:39:37.176Z [DEBUG] [core] running data hook in karma plugin
2018-05-23T09:39:37.176Z [DEBUG] [core] hook=data plugin=karma function=hook_data params="" retval=CONT msg=""
2018-05-23T09:39:37.176Z [PROTOCOL] [core] S: 354 go ahead, make my day
2018-05-23T09:39:37.441Z [DEBUG] [core] running data_post hooks
2018-05-23T09:39:37.442Z [DEBUG] [core] running data_post hook in srs plugin
2018-05-23T09:39:37.442Z [DEBUG] [srs] Remote host (167.89.37.79), skipping
2018-05-23T09:39:37.442Z [DEBUG] [core] hook=data_post plugin=srs function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:37.442Z [DEBUG] [core] running data_post hook in asn plugin
2018-05-23T09:39:37.443Z [DEBUG] [core] hook=data_post plugin=asn function=add_header_asn params="" retval=CONT msg=""
2018-05-23T09:39:37.443Z [DEBUG] [core] running data_post hook in p0f plugin
2018-05-23T09:39:37.443Z [DEBUG] [p0f] header disabled in ini
2018-05-23T09:39:37.443Z [DEBUG] [core] hook=data_post plugin=p0f function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:37.443Z [DEBUG] [core] running data_post hook in data.uribl plugin
2018-05-23T09:39:37.445Z [DEBUG] [data.uribl] (from) found 1 items for lookup
2018-05-23T09:39:37.445Z [DEBUG] [data.uribl] (from) checking: bitbucket.org
2018-05-23T09:39:37.481Z [DEBUG] [data.uribl] bitbucket.org.dbl.spamhaus.org. => (Error: queryA ENOTFOUND bitbucket.org.dbl.spamhaus.org.)
2018-05-23T09:39:37.482Z [DEBUG] [data.uribl] (msgid) found 1 items for lookup
2018-05-23T09:39:37.483Z [DEBUG] [data.uribl] (msgid) checking: app-167.ash1.bb-inf.net
2018-05-23T09:39:37.648Z [DEBUG] [data.uribl] app-167.ash1.bb-inf.net.dbl.spamhaus.org. => (Error: queryA ENOTFOUND app-167.ash1.bb-inf.net.dbl.spamhaus.org.)
2018-05-23T09:39:37.650Z [DEBUG] [data.uribl] (body) no items found for lookup
2018-05-23T09:39:37.650Z [DEBUG] [core] hook=data_post plugin=data.uribl function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:37.650Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.651Z [DEBUG] [core] hook=data_post plugin=data.headers function=duplicate_singular params="" retval=CONT msg=""
2018-05-23T09:39:37.651Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.652Z [DEBUG] [core] hook=data_post plugin=data.headers function=missing_required params="" retval=CONT msg=""
2018-05-23T09:39:37.652Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.653Z [DEBUG] [data.headers] message date: Wed, 23 May 2018 09:39:23 +0000 (UTC)
2018-05-23T09:39:37.663Z [DEBUG] [core] hook=data_post plugin=data.headers function=invalid_date params="" retval=CONT msg=""
2018-05-23T09:39:37.663Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.664Z [DEBUG] [core] hook=data_post plugin=data.headers function=invalid_return_path params="" retval=CONT msg=""
2018-05-23T09:39:37.664Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.665Z [DEBUG] [core] hook=data_post plugin=data.headers function=user_agent params="" retval=CONT msg=""
2018-05-23T09:39:37.665Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.666Z [DEBUG] [core] hook=data_post plugin=data.headers function=direct_to_mx params="" retval=CONT msg=""
2018-05-23T09:39:37.666Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.676Z [DEBUG] [core] hook=data_post plugin=data.headers function=from_match params="" retval=CONT msg=""
2018-05-23T09:39:37.676Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.677Z [DEBUG] [core] hook=data_post plugin=data.headers function=delivered_to params="" retval=CONT msg=""
2018-05-23T09:39:37.677Z [DEBUG] [core] running data_post hook in data.headers plugin
2018-05-23T09:39:37.678Z [DEBUG] [core] hook=data_post plugin=data.headers function=mailing_list params="" retval=CONT msg=""
2018-05-23T09:39:37.678Z [DEBUG] [core] running data_post hook in known-senders plugin
2018-05-23T09:39:37.678Z [ERROR] [known-senders] is_dkim_authenticated: no dkim_verify results
2018-05-23T09:39:37.679Z [DEBUG] [core] hook=data_post plugin=known-senders function=is_dkim_authenticated params="" retval=CONT msg=""
2018-05-23T09:39:37.679Z [DEBUG] [core] running data_post hook in bounce plugin
2018-05-23T09:39:37.679Z [DEBUG] [core] hook=data_post plugin=bounce function=empty_return_path params="" retval=CONT msg=""
2018-05-23T09:39:37.679Z [DEBUG] [core] running data_post hook in bounce plugin
2018-05-23T09:39:37.680Z [DEBUG] [core] hook=data_post plugin=bounce function=bounce_spf params="" retval=CONT msg=""
2018-05-23T09:39:37.680Z [DEBUG] [core] running data_post hook in bounce plugin
2018-05-23T09:39:37.680Z [DEBUG] [core] hook=data_post plugin=bounce function=non_local_msgid params="" retval=CONT msg=""
2018-05-23T09:39:37.680Z [DEBUG] [core] running data_post hook in dovecot_quota plugin
2018-05-23T09:39:37.681Z [DEBUG] [dovecot_quota] domain 'gmail.com' is remote
2018-05-23T09:39:37.681Z [DEBUG] [core] hook=data_post plugin=dovecot_quota function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:37.681Z [DEBUG] [core] running data_post hook in rspamd plugin
2018-05-23T09:39:41.041Z [INFO] [rspamd] action: no action, is_skipped: false, required_score: 15, score: 2.5, time: 3.349
2018-05-23T09:39:41.042Z [DEBUG] [core] hook=data_post plugin=rspamd function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:41.042Z [DEBUG] [core] running data_post hook in attachment plugin
2018-05-23T09:39:41.043Z [DEBUG] [core] hook=data_post plugin=attachment function=wait_for_attachment_hooks params="" retval=CONT msg=""
2018-05-23T09:39:41.043Z [DEBUG] [core] running data_post hook in attachment plugin
2018-05-23T09:39:41.085Z [DEBUG] [attachment] found content type: multipart/alternative
2018-05-23T09:39:41.085Z [DEBUG] [attachment] found content type: text/plain
2018-05-23T09:39:41.085Z [DEBUG] [attachment] found content type: text/html
2018-05-23T09:39:41.085Z [DEBUG] [core] hook=data_post plugin=attachment function=check_attachments params="" retval=CONT msg=""
2018-05-23T09:39:41.085Z [DEBUG] [core] running data_post hook in clamd plugin
2018-05-23T09:39:41.086Z [DEBUG] [clamd] trying host: /var/run/clamav/clamd.ctl
2018-05-23T09:39:41.139Z [DEBUG] [clamd] connected to host undefined:undefined
2018-05-23T09:39:41.689Z [PROTOCOL] [clamd] C:stream: OK
2018-05-23T09:39:41.690Z [INFO] [clamd] pass:clean
2018-05-23T09:39:41.690Z [DEBUG] [core] hook=data_post plugin=clamd function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:41.690Z [DEBUG] [core] running data_post hook in karma plugin
2018-05-23T09:39:41.690Z [DEBUG] [karma] adding header: score: 1, awards: 131,183,182
2018-05-23T09:39:41.690Z [DEBUG] [core] hook=data_post plugin=karma function=hook_data_post params="" retval=CONT msg=""
2018-05-23T09:39:41.691Z [DEBUG] [core] running data_post hook in strict_from plugin
2018-05-23T09:39:41.691Z [DEBUG] [strict_from] plugin disabled
2018-05-23T09:39:41.691Z [DEBUG] [core] hook=data_post plugin=strict_from function=from_check params="" retval=CONT msg=""
2018-05-23T09:39:41.691Z [DEBUG] [core] running data_post hook in queue/quarantine-decide plugin
2018-05-23T09:39:41.692Z [INFO] [core] hook=data_post plugin=queue/quarantine-decide function=hook_data_post params="" retval=OK msg=""
2018-05-23T09:39:41.692Z [NOTICE] [core] message mid=<[e-mail]> size=6217 rcpts=1/0/0 delay=4.251 code=OK msg=""
2018-05-23T09:39:41.692Z [DEBUG] [core] running queue hooks
2018-05-23T09:39:41.692Z [DEBUG] [core] running queue hook in karma plugin
2018-05-23T09:39:41.692Z [DEBUG] [core] hook=queue plugin=karma function=hook_queue params="" retval=CONT msg=""
2018-05-23T09:39:41.692Z [DEBUG] [core] running queue hook in queue/dmarc-report-save plugin
2018-05-23T09:39:41.693Z [DEBUG] [core] hook=queue plugin=queue/dmarc-report-save function=hook_queue params="" retval=CONT msg=""
2018-05-23T09:39:41.693Z [DEBUG] [core] running queue hook in queue/quarantine plugin
2018-05-23T09:39:41.693Z [DEBUG] [core] running queue hook in queue/lmtp plugin
2018-05-23T09:39:41.693Z [DEBUG] [core] hook=queue plugin=queue/quarantine function=quarantine params="" retval=CONT msg=""
2018-05-23T09:39:41.819Z [INFO] [core] hook=queue plugin=queue/lmtp function=hook_queue params="" retval=OK msg="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)"
2018-05-23T09:39:41.826Z [DEBUG] [core] running queue_ok hooks
2018-05-23T09:39:41.826Z [DEBUG] [core] running queue_ok hook in limits plugin
2018-05-23T09:39:41.857Z [DEBUG] [core] hook=queue_ok plugin=limits function=hook_queue_ok params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.857Z [DEBUG] [core] running queue_ok hook in stats plugin
2018-05-23T09:39:41.922Z [DEBUG] [core] hook=queue_ok plugin=stats function=hook_queue_ok params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.922Z [DEBUG] [core] running queue_ok hook in block_bad_connections plugin
2018-05-23T09:39:41.923Z [DEBUG] [core] hook=queue_ok plugin=block_bad_connections function=hook_queue_ok params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.923Z [DEBUG] [core] running queue_ok hook in known-senders plugin
2018-05-23T09:39:41.923Z [DEBUG] [core] hook=queue_ok plugin=known-senders function=update_sender params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.924Z [DEBUG] [core] running queue_ok hook in queue/quarantine-decide plugin
2018-05-23T09:39:41.924Z [DEBUG] [core] hook=queue_ok plugin=queue/quarantine-decide function=hook_queue_ok params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.924Z [DEBUG] [core] running queue_ok hook in watch plugin
2018-05-23T09:39:41.924Z [DEBUG] [core] hook=queue_ok plugin=watch function=queue_ok params="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)" retval=CONT msg=""
2018-05-23T09:39:41.924Z [NOTICE] [core] queue code=OK msg="Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)"
2018-05-23T09:39:41.924Z [PROTOCOL] [core] S: 250 Message Queued (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1) (EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1)
2018-05-23T09:39:41.925Z [DEBUG] [core] running reset_transaction hooks
2018-05-23T09:39:41.925Z [DEBUG] [core] running reset_transaction hook in stats plugin
2018-05-23T09:39:41.926Z [DEBUG] [core] hook=reset_transaction plugin=stats function=hook_reset_transaction params="" retval=CONT msg=""
2018-05-23T09:39:41.926Z [DEBUG] [core] running reset_transaction hook in log plugin
2018-05-23T09:39:41.938Z [DEBUG] [core] hook=reset_transaction plugin=log function=hook_reset_transaction params="" retval=CONT msg=""
2018-05-23T09:39:41.938Z [DEBUG] [core] running reset_transaction hook in karma plugin
2018-05-23T09:39:41.938Z [INFO] [karma] score: 1, awards: 131,183,182
2018-05-23T09:39:41.938Z [DEBUG] [core] hook=reset_transaction plugin=karma function=hook_reset_transaction params="" retval=CONT msg=""
2018-05-23T09:39:43.597Z [PROTOCOL] [core] C: QUIT state=1
2018-05-23T09:39:43.597Z [DEBUG] [core] running quit hooks
2018-05-23T09:39:43.597Z [PROTOCOL] [core] S: 221 mx.mydomainname.com closing connection. Have a jolly good day.
2018-05-23T09:39:43.600Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.600Z [DEBUG] [core] running disconnect hooks
2018-05-23T09:39:43.600Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.600Z [DEBUG] [core] running disconnect hook in stats plugin
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [INFO] [core] hook=disconnect plugin=stats function=hook_disconnect params="" retval=OK msg=""
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [DEBUG] [core] running disconnect hook in block_bad_connections plugin
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [INFO] [core] hook=disconnect plugin=block_bad_connections function=hook_disconnect params="" retval=OK msg=""
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [DEBUG] [core] running disconnect hook in log plugin
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [INFO] [core] hook=disconnect plugin=log function=hook_disconnect params="" retval=OK msg=""
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.602Z [DEBUG] [core] running disconnect hook in tls plugin
2018-05-23T09:39:43.602Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.603Z [DEBUG] [core] hook=disconnect plugin=tls function=hook_disconnect params="" retval=CONT msg=""
2018-05-23T09:39:43.603Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.603Z [DEBUG] [core] running disconnect hook in karma plugin
2018-05-23T09:39:43.603Z [INFO] [karma] score: 1, awards: 131,183,182
2018-05-23T09:39:43.603Z [DEBUG] [core] client has disconnected
2018-05-23T09:39:43.603Z [DEBUG] [core] hook=disconnect plugin=karma function=hook_disconnect params="" retval=CONT msg=""
2018-05-23T09:39:43.604Z [NOTICE] [core] disconnect ip=167.89.37.79 rdns=o4.em.bitbucket.org helo=o4.em.bitbucket.org relay=N early=N esmtp=Y tls=Y pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=6217 lr="" time=19.051
2018-05-23T09:39:43.605Z [DEBUG] [karma] unsubsubscribed from result-EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0*
root@29071010ae3b:/# 




root@29071010ae3b:/# cat /data/log/delivery/conn/E/F/EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0 
2018-05-23T09:39:24.553Z [NOTICE] [core] connect ip=167.89.37.79 port=45539 local_ip=:: local_port=25
2018-05-23T09:39:24.553Z [DEBUG] [core] running connect_init hooks
2018-05-23T09:39:24.553Z [DEBUG] [core] running connect_init hook in guard plugin
2018-05-23T09:39:24.555Z [DEBUG] [core] hook=connect_init plugin=guard function=hook_connect_init params="" retval=CONT msg=""
2018-05-23T09:39:24.555Z [DEBUG] [core] running connect_init hook in early_talker plugin
2018-05-23T09:39:29.556Z [DEBUG] [core] hook=connect_init plugin=early_talker function=early_talker params="" retval=CONT msg=""
2018-05-23T09:39:29.556Z [DEBUG] [core] running connect_init hook in fcrdns plugin
2018-05-23T09:39:29.557Z [DEBUG] [core] hook=connect_init plugin=fcrdns function=initialize_fcrdns params="" retval=CONT msg=""
2018-05-23T09:39:29.557Z [DEBUG] [core] running connect_init hook in karma plugin
2018-05-23T09:39:29.560Z [DEBUG] [karma] psubscribed to result-EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0*
2018-05-23T09:39:29.561Z [DEBUG] [core] hook=connect_init plugin=karma function=results_init params="" retval=CONT msg=""
2018-05-23T09:39:29.561Z [DEBUG] [core] running connect_init hook in karma plugin
2018-05-23T09:39:29.561Z [DEBUG] [core] hook=connect_init plugin=karma function=ip_history_from_redis params="" retval=CONT msg=""
2018-05-23T09:39:29.561Z [DEBUG] [core] running connect_init_respond
2018-05-23T09:39:29.561Z [DEBUG] [core] running lookup_rdns hooks
2018-05-23T09:39:29.562Z [DEBUG] [core] running lookup_rdns hook in p0f plugin
2018-05-23T09:39:29.562Z [INFO] [p0f] os="Linux 3.11 and newer" link_type="Ethernet or modem" distance=16 total_conn=1
2018-05-23T09:39:29.563Z [DEBUG] [core] hook=lookup_rdns plugin=p0f function=hook_lookup_rdns params="" retval=CONT msg=""
2018-05-23T09:39:29.563Z [DEBUG] [core] running lookup_rdns hook in fcrdns plugin
2018-05-23T09:39:29.582Z [DEBUG] [fcrdns] rdns lookup: 167.89.37.79
2018-05-23T09:39:29.584Z [DEBUG] [fcrdns] domain: o4.em.bitbucket.org
2018-05-23T09:39:29.621Z [DEBUG] [fcrdns] o4.em.bitbucket.org => 167.89.37.79
2018-05-23T09:39:29.626Z [INFO] [fcrdns] ip=167.89.37.79  rdns="o4.em.bitbucket.org" rdns_len=1 fcrdns="o4.em.bitbucket.org" fcrdns_len=1 other_ips_len=0 invalid_tlds=0 generic_rdns=true
2018-05-23T09:39:29.626Z [DEBUG] [core] hook=lookup_rdns plugin=fcrdns function=do_dns_lookups params="" retval=CONT msg=""
2018-05-23T09:39:29.627Z [DEBUG] [core] running lookup_rdns hook in data.uribl plugin
2018-05-23T09:39:29.653Z [DEBUG] [data.uribl] (rdns) found 1 items for lookup
2018-05-23T09:39:29.653Z [DEBUG] [data.uribl] (rdns) checking: o4.em.bitbucket.org
2018-05-23T09:39:29.693Z [DEBUG] [data.uribl] o4.em.bitbucket.org.dbl.spamhaus.org. => (Error: queryA ENOTFOUND o4.em.bitbucket.org.dbl.spamhaus.org.)
2018-05-23T09:39:29.693Z [DEBUG] [core] hook=lookup_rdns plugin=data.uribl function=hook_lookup_rdns params="" retval=CONT msg=""
2018-05-23T09:39:29.693Z [DEBUG] [core] running lookup_rdns hook in asn plugin
2018-05-23T09:39:29.693Z [DEBUG] [asn] zone: origin.asn.cymru.com
2018-05-23T09:39:29.821Z [INFO] [asn] asn: 11377, net: 167.89.0.0/18
2018-05-23T09:39:29.821Z [DEBUG] [core] hook=lookup_rdns plugin=asn function=lookup_via_dns params="" retval=CONT msg=""
2018-05-23T09:39:29.857Z [DEBUG] [core] running connect hooks
2018-05-23T09:39:29.857Z [DEBUG] [core] running connect hook in limits plugin
2018-05-23T09:39:29.995Z [DEBUG] [core] hook=connect plugin=limits function=hook_connect params="" retval=CONT msg=""
2018-05-23T09:39:29.995Z [DEBUG] [core] running connect hook in guard plugin
2018-05-23T09:39:29.995Z [DEBUG] [core] hook=connect plugin=guard function=hook_connect params="" retval=CONT msg=""
2018-05-23T09:39:29.995Z [DEBUG] [core] running connect hook in dnsbl plugin
2018-05-23T09:39:30.120Z [DEBUG] [core] hook=connect plugin=dnsbl function=connect_first params="" retval=CONT msg=""
2018-05-23T09:39:30.120Z [DEBUG] [core] running connect hook in relay plugin
2018-05-23T09:39:30.120Z [DEBUG] [relay] checking 167.89.37.79 in relay_acl_allow
2018-05-23T09:39:30.120Z [DEBUG] [relay] checking if 167.89.37.79 is in 224.0.0.0/32
2018-05-23T09:39:30.121Z [DEBUG] [relay] checking if 167.89.37.79 is in 127.0.0.1/32
2018-05-23T09:39:30.121Z [DEBUG] [relay] checking if 167.89.37.79 is in 172.17.0.2/32
2018-05-23T09:39:30.121Z [DEBUG] [core] hook=connect plugin=relay function=acl params="" retval=CONT msg=""
2018-05-23T09:39:30.121Z [DEBUG] [core] running connect hook in karma plugin
2018-05-23T09:39:30.122Z [DEBUG] [core] hook=connect plugin=karma function=hook_connect params="" retval=CONT msg=""
2018-05-23T09:39:30.122Z [DEBUG] [core] running connect hook in max_unrecognized_commands plugin
2018-05-23T09:39:30.123Z [DEBUG] [core] hook=connect plugin=max_unrecognized_commands function=hook_connect params="" retval=CONT msg=""
2018-05-23T09:39:30.123Z [PROTOCOL] [core] S: 220 mx.mydomainname.com ESMTP Haraka ready
2018-05-23T09:39:30.294Z [PROTOCOL] [core] C: EHLO o4.em.bitbucket.org state=1
2018-05-23T09:39:30.295Z [DEBUG] [core] running ehlo hooks
2018-05-23T09:39:30.295Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.295Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=proto_mismatch_esmtp params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.296Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.296Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=init params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.296Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.296Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=match_re params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.296Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.297Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=bare_ip params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.297Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.297Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=dynamic params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.297Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.298Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=big_company params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.298Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.298Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=literal_mismatch params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.298Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.299Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=valid_hostname params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.299Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.299Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=rdns_match params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.299Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.328Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=forward_dns params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.328Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.328Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=host_mismatch params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.328Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:30.328Z [INFO] [helo.checks] helo_host: o4.em.bitbucket.org, ips: 167.89.37.79, pass:match_re, bare_ip, dynamic, big_co(not), literal_mismatch, valid_hostname, rdns_match, forward_dns, host_mismatch
2018-05-23T09:39:30.328Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=emit_log params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.328Z [DEBUG] [core] running ehlo hook in spf plugin
2018-05-23T09:39:30.355Z [INFO] [spf] identity=helo ip=167.89.37.79 domain="o4.em.bitbucket.org" mfrom=<[e-mail]> result=None
2018-05-23T09:39:30.356Z [INFO] [spf] scope: helo, result: None, domain: o4.em.bitbucket.org
2018-05-23T09:39:30.356Z [DEBUG] [core] hook=ehlo plugin=spf function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.356Z [DEBUG] [core] running ehlo hook in data.uribl plugin
2018-05-23T09:39:30.357Z [DEBUG] [data.uribl] (helo) found 1 items for lookup
2018-05-23T09:39:30.357Z [DEBUG] [data.uribl] (helo) checking: o4.em.bitbucket.org
2018-05-23T09:39:30.396Z [DEBUG] [data.uribl] o4.em.bitbucket.org.dbl.spamhaus.org. => (Error: queryA ENOTFOUND o4.em.bitbucket.org.dbl.spamhaus.org.)
2018-05-23T09:39:30.397Z [DEBUG] [core] hook=ehlo plugin=data.uribl function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.397Z [DEBUG] [core] running ehlo hook in karma plugin
2018-05-23T09:39:30.397Z [DEBUG] [core] hook=ehlo plugin=karma function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:30.398Z [DEBUG] [core] running capabilities hooks
2018-05-23T09:39:30.398Z [DEBUG] [core] running capabilities hook in tls plugin
2018-05-23T09:39:30.399Z [DEBUG] [core] hook=capabilities plugin=tls function=advertise_starttls params="" retval=CONT msg=""
2018-05-23T09:39:30.399Z [DEBUG] [core] running capabilities hook in auth/poste plugin
2018-05-23T09:39:30.399Z [DEBUG] [core] hook=capabilities plugin=auth/poste function=hook_capabilities params="" retval=CONT msg=""
2018-05-23T09:39:30.399Z [PROTOCOL] [core] S: 250-mx.mydomainname.com Hello o4.em.bitbucket.org [167.89.37.79], Haraka is at your service.
2018-05-23T09:39:30.400Z [PROTOCOL] [core] S: 250-PIPELINING
2018-05-23T09:39:30.400Z [PROTOCOL] [core] S: 250-8BITMIME
2018-05-23T09:39:30.400Z [PROTOCOL] [core] S: 250-SMTPUTF8
2018-05-23T09:39:30.401Z [PROTOCOL] [core] S: 250-SIZE 26214400
2018-05-23T09:39:30.401Z [PROTOCOL] [core] S: 250 STARTTLS
2018-05-23T09:39:30.572Z [PROTOCOL] [core] C: STARTTLS state=1
2018-05-23T09:39:30.572Z [DEBUG] [core] running unrecognized_command hooks
2018-05-23T09:39:30.572Z [DEBUG] [core] running unrecognized_command hook in tls plugin
2018-05-23T09:39:30.572Z [PROTOCOL] [core] S: 220 Go ahead.
2018-05-23T09:39:31.048Z [INFO] [tls] secured: cipher=ECDHE-RSA-AES256-GCM-SHA384 version=TLSv1/SSLv3 verified=false
2018-05-23T09:39:31.048Z [INFO] [core] hook=unrecognized_command plugin=tls function=upgrade_connection params=STARTTLS retval=OK msg=""
2018-05-23T09:39:31.218Z [PROTOCOL] [core] C: EHLO o4.em.bitbucket.org state=1
2018-05-23T09:39:31.219Z [DEBUG] [core] running ehlo hooks
2018-05-23T09:39:31.220Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.220Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=proto_mismatch_esmtp params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.220Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.220Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=init params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.220Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.220Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=match_re params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.220Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=bare_ip params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=dynamic params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=big_company params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=literal_mismatch params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=valid_hostname params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.221Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=rdns_match params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.221Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.222Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=forward_dns params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.222Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.222Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=host_mismatch params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.222Z [DEBUG] [core] running ehlo hook in helo.checks plugin
2018-05-23T09:39:31.222Z [INFO] [helo.checks] helo_host: o4.em.bitbucket.org, ips: 167.89.37.79, multi: true, pass:match_re, bare_ip, dynamic, big_co(not), literal_mismatch, valid_hostname, rdns_match, forward_dns, host_mismatch, host_mismatch
2018-05-23T09:39:31.222Z [DEBUG] [core] hook=ehlo plugin=helo.checks function=emit_log params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.223Z [DEBUG] [core] running ehlo hook in spf plugin
2018-05-23T09:39:31.251Z [INFO] [spf] identity=helo ip=167.89.37.79 domain="o4.em.bitbucket.org" mfrom=<[e-mail]> result=None
2018-05-23T09:39:31.251Z [INFO] [spf] scope: helo, result: None, domain: o4.em.bitbucket.org
2018-05-23T09:39:31.251Z [DEBUG] [core] hook=ehlo plugin=spf function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.251Z [DEBUG] [core] running ehlo hook in data.uribl plugin
2018-05-23T09:39:31.252Z [DEBUG] [data.uribl] (helo) found 1 items for lookup
2018-05-23T09:39:31.252Z [DEBUG] [data.uribl] (helo) checking: o4.em.bitbucket.org
2018-05-23T09:39:31.278Z [DEBUG] [data.uribl] o4.em.bitbucket.org.dbl.spamhaus.org. => (Error: queryA ENOTFOUND o4.em.bitbucket.org.dbl.spamhaus.org.)
2018-05-23T09:39:31.279Z [DEBUG] [core] hook=ehlo plugin=data.uribl function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.279Z [DEBUG] [core] running ehlo hook in karma plugin
2018-05-23T09:39:31.279Z [DEBUG] [core] hook=ehlo plugin=karma function=hook_ehlo params=o4.em.bitbucket.org retval=CONT msg=""
2018-05-23T09:39:31.279Z [DEBUG] [core] running capabilities hooks
2018-05-23T09:39:31.279Z [DEBUG] [core] running capabilities hook in tls plugin
2018-05-23T09:39:31.279Z [DEBUG] [core] hook=capabilities plugin=tls function=advertise_starttls params="" retval=CONT msg=""
2018-05-23T09:39:31.279Z [DEBUG] [core] running capabilities hook in auth/poste plugin
2018-05-23T09:39:31.280Z [DEBUG] [core] hook=capabilities plugin=auth/poste function=hook_capabilities params="" retval=CONT msg=""
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250-mx.mydomainname.com Hello o4.em.bitbucket.org [167.89.37.79], Haraka is at your service.
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250-PIPELINING
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250-8BITMIME
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250-SMTPUTF8
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250-SIZE 26214400
2018-05-23T09:39:31.280Z [PROTOCOL] [core] S: 250 AUTH PLAIN LOGIN
2018-05-23T09:39:31.452Z [PROTOCOL] [core] C: MAIL FROM:<bounces+2418806-d28c-bitbucket=[e-mail]> state=1
2018-05-23T09:39:31.723Z [TX] [core] #EF5AC73A-F46B-4AF5-A87C-C5ED51B157B0.1
root@29071010ae3b:/# 

can you advise if there is anything i am doing incorrectly or if this is actually a bug? again, this was previously working on an older version of poste (1.0.4)

[SH]

Yes, its bug. It seems that we have test for scenario where domain-bin address is local only...

Nevertheless there is simple workaround - create email/redirect within domain and then redirect emails to gmail.

[SH]

Sadly delivery to remote domains would require rewrite delivery logic (and SRS also), so next version will have form restricted only to delivery to local domains. You can simply delivery to local account or redirect.

[SH]

fix #343 restrict forwarding/domain-bin to local domains only

→ <<cset 945f1cd63e12>>