search

haraka / Haraka

A fast, highly extensible, and event driven SMTP server
https://haraka.github.io
MIT License
5.08k stars 661 forks source link

SPF timeout on RELAY context=myself #1112

Closed sstraus closed 9 years ago

sstraus commented 9 years ago

I get a timeout error with context=myself configuration in SPF.ini.

The error is fired at line:

Connection.haproxy_hosts_ipv4 as logerror

Any suggestion?

smfreegard commented 9 years ago

Set your loglevel to LOGDEBUG and then reproduce this error and the post the full session log here.

Also check that you aren't blocking STUN packets on your firewall as it is used to determine the external IP when context=myself.

sstraus commented 9 years ago

I've set the public ip in the SMTP config to avoid STUN problems. I'll post the log asap. Thank you.

sstraus commented 9 years ago

Here is the full session:

haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hooks
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hook in access plugin
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] checking somedomain@somedomain.com against mail_from.access.whitelist
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] checking somedomain@somedomain.com against mail_from.access.whitelist_regex
[DEBUG] [-] [access] checking somedomain@somedomain.com against undefined
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] checking somedomain@somedomain.com against mail_from.access.blacklist_regex
[DEBUG] [-] [access] checking somedomain@somedomain.com against undefined
[INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] pass:unlisted(mail)
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=mail plugin=access function=mail_from_access params="<somedomain@somedomain.com>" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hook in access plugin
[INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] pass:helo:any, mf/rt:any
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=mail plugin=access function=any params="<somedomain@somedomain.com>" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hook in mail_from.is_resolvable plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [mail_from.is_resolvable] somedomain.com: MX 10 mail1.mymailserver.com => 154.176.106.131
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [mail_from.is_resolvable] somedomain.com: 154.176.106.131
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=mail plugin=mail_from.is_resolvable function=hook_mail params="<somedomain@somedomain.com>" retval=CO NT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hook in spfplugin
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=mail plugin=spf function=hook_mail params="<somedomain@somedomain.com>" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running mail hook in rcpt_to.in_host_list plugin
[DEBUG] [-] [rcpt_to.in_host_list] checking somedomain.com in config/host_list
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=mail plugin=rcpt_to.in_host_list function=hook_mail params="<somedomain@somedomain.com>" retval=CONT msg=""
[NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] sender <somedomain@somedomain.com> code=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running rcpt hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running rcpt hook in access plugin
haraka-1 [DEBUG] [-] [access] checking bill@hotmail.com against undefined
haraka-1 [DEBUG] [-] [access] checking bill@hotmail.com against undefined
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] pass:unlisted(mail), unlisted(rcpt)
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=rcpt plugin=access function=rcpt_to_access params="<bill@hotmail.com>" retval=CONT msg=" "
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running rcpt hook in access plugin
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [access] pass:helo:any,mf/rt:any, mf/rt:any
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=rcpt plugin=access function=any params="<bill@hotmail.com>" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running rcpt hook in rcpt_to.in_host_list plugin
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [rcpt_to.in_host_list] Checkingif <bill@hotmail.com> host is in host_list
[DEBUG] [-] [rcpt_to.in_host_list] checking hotmail.com in config/host_list
[INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=rcpt plugin=rcpt_to.in_host_list function=hook_rcpt params="<bill@hotmail.com>" retval=OK msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running rcpt_ok hooks
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] recipient <bill@hotmail.com> code=CONT msg="" sender="somedomain@somedomain.com"
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in access plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=access function=data_any params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in my_proxy plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=duplicate_singular params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=missing_required params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [data.headers] message date: Sat, 22 Aug 2015 21:56:39 +0000
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=invalid_date params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=invalid_return_path params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=user_agent params="" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=direct_to_mx params="" retval=CONT msg=""
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=from_match params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=delivered_to params="" retval=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running data_post hook in data.headers plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=data_post plugin=data.headers function=mailing_list params="" retval=CONT msg=""
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] message mid="<1440280599784-2cf083b3-cd61f3c6-76896680@somedomain.com>" size=1948 rcpts=1/0/0 d elay=0.012 code=CONT msg=""
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running queue_outbound hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running queue_outbound hook in dkim_sign plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [dkim_sign] [ '/home/ec2-user/nodeproject/smtp/haraka/config/dkim/somedomain.com',
 '/home/ec2-user/nodeproject/smtp/haraka/config/dkim/com' ]
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [dkim_sign] [ '/home/ec2-user/nodeproject/smtp/haraka/config/dkim/somedomain.com' ]
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [dkim_sign] dkim_domain: somedomain.com
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [dkim_sign] signed for somedomain.com
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=queue_outbound plugin=dkim_sign function=hook_queue_outbound params="" retval=CONT msg=""
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] queue code=CONT msg=""
haraka-1 [INFO] [-] [core] [outbound] Sending email as a transaction
haraka-1 [INFO] [-] [core] [outbound] Processing domain: hotmail.com
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running queue_ok hooks
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] queue_ok code=CONT msg="Message Queued (81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1)"
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running reset_transaction hooks
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] client [127.0.0.1] half closed connection
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running disconnect hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] running disconnect hook in my_proxy plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] hook=disconnectplugin=my_proxy function=my_hook_disconnect params="" retval=CONT msg=""
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] disconnect ip=127.0.0.1 rdns="localhost.localdomain" helo="somedomain.com" relay=Y early=N esmt p=Y tls=N pipe=N txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=1948 lr="" time=0.155
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] running send_email hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] Sending mail: 1440280599915_0_20672_3508.ip-172-31-23-55
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] running get_mx hooks
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] running get_mx hook in relay plugin
haraka-1 [DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] hook=get_mx plugin=relay function=force_routing params="hotmail.com" retval=CONT msg=""
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] Looking upA records for: mx3.hotmail.com
haraka-1 [INFO] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] Attemptingto deliver to: 65.55.37.72:25 (0) (0)
haraka-1 [NOTICE] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] delivered file=1440280599915_0_20672_3508.ip-172-31-23-55 domain="hotmail.com" host="mx3.hotmail.com" ip=65.55.37.72 port=25 mode=SMTP tls=N auth=N response=" <144028059 9784-2cf083b3-cd61f3c6-76896680@somedomain.com> Queued mail for delivery" delay=1 .545 fails=0 rcpts=1/0/0
[DEBUG] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1.1] [outbound] running delivered hooks
haraka-1 [ERROR] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [spf] timeout
[ERROR] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] spf plugin ran callback multiple times - ignoring subsequent calls
[ERROR] [81DE2842-B40D-4B22-9D7C-3E9EFAE0102C.1] [core] Error
 at callback (/usr/lib/node_modules/Haraka/plugins.js:284:34)
 at null._onTimeout (/usr/lib/node_modules/Haraka/plugins/spf.js:142:16)
 at Timer.listOnTimeout [as ontimeout] (timers.js:121:15)
smfreegard commented 9 years ago

Ok - I've taken a look at this; did forcing the public IP in smtp.ini prevent this? If so - I can see the fix.

sstraus commented 9 years ago

No, fixing the ip doesn't solve the problem. Is the same behavior with or without.

Stefano

Il giorno 27/ago/2015, alle ore 14:40, Steve Freegard notifications@github.com<mailto:notifications@github.com> ha scritto:

Ok - I've taken a look at this; did forcing the public IP in smtp.ini prevent this? If so - I can see the fix.

— Reply to this email directly or view it on GitHubhttps://github.com/baudehlo/Haraka/issues/1112#issuecomment-135409557.

smfreegard commented 9 years ago

Ok - I think this has already been fixed. Grab plugins/spf.js from master and it should work.