Join GitHub today
GitHub is home to over 28 million developers working together to host and review code, manage projects, and build software together.
Sign upHaraka 2.8.18 crashes when trying to deliver mail to a particular Go Daddy server #2375
Comments
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
baudehlo
Mar 24, 2018
Collaborator
|
The first part is just lame - the server sending to (not sure which
software that is) is broken. They don't support RSET after 4xx. I guess
we'll need to implement something to cope with that. I'll put in another
ticket.
The second is a straight up bug that needs more investigation.
…On Fri, Mar 23, 2018 at 8:09 AM, lnedry ***@***.***> wrote:
system info
Haraka Haraka.js — Version: 2.8.18
Node v6.12.3
OS Linux 3.10.0-693.21.1.el7.x86_64 #1
<#1> SMP Wed Mar 7 19:03:37 UTC 2018
x86_64 x86_64 x86_64 GNU/Linux
openssl OpenSSL 1.0.2k-fips 26 Jan 2017 Expected behavior Observed
behavior
Haraka crashes after trying to deliver email to a particular Go Daddy SMTP
server:
p3plibsmtp03-11.prod.phx3.secureserver.net
Steps to reproduce
Try to deliver email to p3plibsmtp03-11.prod.phx3.secureserver.net
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] Looking up A records for: smtp.secureserver.net
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] Attempting to deliver to: 68.178.213.203:25 (0) (2)
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
[outbound::25:68.178.213.203:undefined:50] dispense() clients=1
available=0
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] [outbound]
[outbound::25:68.178.213.203:undefined:50] createResource() - creating
obj - count=1 min=0 max=10
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] [outbound]
created uuid=B2C7C758-6E83-4052-876B-CB2DF5D6F208 host=68.178.213.203
port=25 pool_timeout=50
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
acquired socket B2C7C758-6E83-4052-876B-CB2DF5D6F208 for
outbound::25:68.178.213.203:undefined:50
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL]
[DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] S: 421
p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server error
(try again later)\r\n
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL]
[DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] C: RSET
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] Temp fail for:
Upstream error: 421 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp
ESMTP server error (try again later)
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] running deferred hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] Temp failing 1521758825136_1521758825136_0_
16681_OjI6On_260_outbound.example.com for 64 seconds: Upstream error: 421
p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server error
(try again later)
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL]
[DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] S: 503 5.5.0 not
available\r\n
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL]
[DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] C: RSET
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] bouncing mail: 503 5.5.0 not available
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1]
[outbound] running bounce hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
Sending email via params
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
Created transaction: 476415D0-0ED5-4E2B-BDF0-1755913AA948
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
Adding missing Message-Id header
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
Adding missing Date header
Mar 22 17:47:05 outbound haraka[16681]: [ERROR] [-] [core] adding missing
results store
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] running
pre_send_trans_email hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound]
Processing domain: printedcom.com
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] Error: Callback
was already called.
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:955:32
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
HMailItem.hmail.next_cb (/usr/lib/node_modules/Haraka/
outbound/queue.js:40:9)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
HMailItem.discard (/usr/lib/node_modules/Haraka/outbound/hmail.js:1241:18)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
outbound.send_email.origin (/usr/lib/node_modules/Haraka/
outbound/hmail.js:1203:22)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
async.forEachSeries (/usr/lib/node_modules/Haraka/
outbound/index.js:283:17)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:473:16
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at replenish
(/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:993:25)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
iterateeCallback (/usr/lib/node_modules/Haraka/
node_modules/async/dist/async.js:983:17)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:958:16
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at
/usr/lib/node_modules/Haraka/outbound/index.js:309:17
Mar 22 17:47:05 outbound haraka[16681]: [NOTICE] [-] [core] Shutting down
—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
<#2375>, or mute the thread
<https://github.com/notifications/unsubscribe-auth/AAobYxNq9DAlgx8cMZ8JzF4ak85NhExVks5thOX9gaJpZM4S4nRT>
.
|
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
smfreegard
Mar 25, 2018
Collaborator
@baudehlo: aren't both issues related here? e.g. the message was already deferred, we attempted to RSET the connection and put it back into the pool and that was incorrectly rejected, which then caused the double callback?
I reckon if we simply destroy the pool connection if RSET returns anything other than 2xx, then this should fix it.
|
@baudehlo: aren't both issues related here? e.g. the message was already deferred, we attempted to RSET the connection and put it back into the pool and that was incorrectly rejected, which then caused the double callback? I reckon if we simply destroy the pool connection if RSET returns anything other than 2xx, then this should fix it. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
baudehlo
Mar 25, 2018
Collaborator
|
Quite possibly. I mean what is lame is ever returning '503 not available'
on an RSET with a 5.5.0 extended status code (Syntax error command not
recognized). It just means that SMTP server hasn't properly implemented
RSET by the looks of things.
…On Sun, Mar 25, 2018 at 1:17 PM, Steve Freegard ***@***.***> wrote:
@baudehlo <https://github.com/baudehlo>: aren't both issues related here?
e.g. the message was already deferred, we attempted to RSET the connection
and put it back into the pool and that was incorrectly rejected, which then
caused the double callback?
I reckon if we simply destroy the pool connection if RSET returns anything
other than 2xx, then this should fix it.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
<#2375 (comment)>, or mute
the thread
<https://github.com/notifications/unsubscribe-auth/AAobY7rI4mJd8YRSU0FaL9wZzWD_bas1ks5th9EcgaJpZM4S4nRT>
.
|
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
lnedry
Mar 27, 2018
Contributor
Is there something I can do as a temporary work around? This is a big problem for me.
|
Is there something I can do as a temporary work around? This is a big problem for me. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
baudehlo
Mar 27, 2018
Collaborator
|
Yeah disable the outbound pooling.
… On Mar 27, 2018, at 3:40 PM, lnedry ***@***.***> wrote:
Is there something I can do as a temporary work around? This is a big problem for me.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.
|
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
smfreegard
Mar 28, 2018
Collaborator
Proposed fix (needs testing): https://gist.github.com/smfreegard/a24dfa99585a7bd57f8bf9382c670e0e
The behaviour of the remote host isn't actually that bad:
smf@ubuntu:~/git/Haraka$ telnet 68.178.213.203 25
Trying 68.178.213.203...
Connected to 68.178.213.203.
Escape character is '^]'.
220 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server ready
RSET
250 2.0.0 OK
QUIT
221 2.0.0 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp closing connection
Connection closed by foreign host.
However if you exceed their rate-limits:
smf@ubuntu:~/git/Haraka$ telnet 68.178.213.203 25
Trying 68.178.213.203...
Connected to 68.178.213.203.
Escape character is '^]'.
421 p3plibsmtp03-10.prod.phx3.secureserver.net bizsmtp ESMTP server error (try again later)
RSET
503 5.5.0 not available
HELP
214-2.0.0 This is bizsmtp ESMTP service help
214-2.0.0 Topics:
214-2.0.0 HELO EHLO HELP VRFY
214-2.0.0 MAIL RCPT DATA NOOP
214-2.0.0 RSET QUIT STARTTLS
214-2.0.0 To contact postmaster send email to postmaster@secureserver.net.
214-2.0.0 For local information send email to Postmaster at your site.
214 2.0.0 end of HELP info
EHLO foo
503 not available
QUIT
221 2.0.0 p3plibsmtp03-10.prod.phx3.secureserver.net bizsmtp closing connection
Connection closed by foreign host.
|
Proposed fix (needs testing): https://gist.github.com/smfreegard/a24dfa99585a7bd57f8bf9382c670e0e The behaviour of the remote host isn't actually that bad:
However if you exceed their rate-limits:
|
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
|
I'm testing your patch. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
kkr78
commented
May 10, 2018
•
|
@lnedry is the patch working for you? I m facing the same error |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
|
I haven't had an obvious issue since installing this patch. |
This comment has been minimized.
Show comment
Hide comment
This comment has been minimized.
kkr78
Aug 20, 2018
I m still running into same issue with latest Haraka 2.8.21. I m planning to apply this patch and give a try. I installed Haraka through npm and don't want to make change in the installed directory. is it possible to apply patch in service? if so, do I need to simply copy it to plugins/outbound/hmail.js and apply patch? please let me know.
are there any plans to apply this patch to the master?
kkr78
commented
Aug 20, 2018
|
I m still running into same issue with latest Haraka 2.8.21. I m planning to apply this patch and give a try. I installed Haraka through npm and don't want to make change in the installed directory. is it possible to apply patch in service? if so, do I need to simply copy it to plugins/outbound/hmail.js and apply patch? please let me know. are there any plans to apply this patch to the master? |
lnedry commentedMar 23, 2018
•
edited
system info
Expected behavior
Observed behavior
Haraka crashes after trying to deliver email to a particular Go Daddy SMTP server:
p3plibsmtp03-11.prod.phx3.secureserver.net
Steps to reproduce
Try to deliver email to p3plibsmtp03-11.prod.phx3.secureserver.net
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] Looking up A records for: smtp.secureserver.net
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] Attempting to deliver to: 68.178.213.203:25 (0) (2)
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] [outbound::25:68.178.213.203:undefined:50] dispense() clients=1 available=0
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] [outbound] [outbound::25:68.178.213.203:undefined:50] createResource() - creating obj - count=1 min=0 max=10
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] [outbound] created uuid=B2C7C758-6E83-4052-876B-CB2DF5D6F208 host=68.178.213.203 port=25 pool_timeout=50
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] acquired socket B2C7C758-6E83-4052-876B-CB2DF5D6F208 for outbound::25:68.178.213.203:undefined:50
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] S: 421 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server error (try again later)\r\n
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] C: RSET
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] Temp fail for: Upstream error: 421 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server error (try again later)
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] running deferred hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] Temp failing 1521758825136_1521758825136_0_16681_OjI6On_260_outbound.example.com for 64 seconds: Upstream error: 421 p3plibsmtp03-11.prod.phx3.secureserver.net bizsmtp ESMTP server error (try again later)
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] S: 503 5.5.0 not available\r\n
Mar 22 17:47:05 outbound haraka[16681]: [PROTOCOL] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] C: RSET
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] bouncing mail: 503 5.5.0 not available
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [DD3572D9-D0A6-48F5-8370-EC5208FF9523.1.1] [outbound] running bounce hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] Sending email via params
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] Created transaction: 476415D0-0ED5-4E2B-BDF0-1755913AA948
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] Adding missing Message-Id header
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] Adding missing Date header
Mar 22 17:47:05 outbound haraka[16681]: [ERROR] [-] [core] adding missing results store
Mar 22 17:47:05 outbound haraka[16681]: [DEBUG] [-] [core] running pre_send_trans_email hooks
Mar 22 17:47:05 outbound haraka[16681]: [INFO] [-] [core] [outbound] Processing domain: foo.com
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] Error: Callback was already called.
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:955:32
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at HMailItem.hmail.next_cb (/usr/lib/node_modules/Haraka/outbound/queue.js:40:9)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at HMailItem.discard (/usr/lib/node_modules/Haraka/outbound/hmail.js:1241:18)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at outbound.send_email.origin (/usr/lib/node_modules/Haraka/outbound/hmail.js:1203:22)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at async.forEachSeries (/usr/lib/node_modules/Haraka/outbound/index.js:283:17)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:473:16
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at replenish (/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:993:25)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at iterateeCallback (/usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:983:17)
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:958:16
Mar 22 17:47:05 outbound haraka[16681]: [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/outbound/index.js:309:17
Mar 22 17:47:05 outbound haraka[16681]: [NOTICE] [-] [core] Shutting down