outbound: socket connection timeout, callback called twice: timeout and error

[shurli]

system info

Haraka	Haraka.js — Version: 2.8.23
Node	v6.11.4
OS	Linux mailgateway 4.4.0-142-generic #168-Ubuntu SMP Wed Jan 16 21:00:45 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
openssl	OpenSSL 1.0.2g 1 Mar 2016

Observed behavior

Using Haraka as Outbound server.
Timeout on outbound socket establishment.

Event timeout is fired on socket and callback is called.
Later Event error is fired on socket and callback is called again.

now processing is forked an leads to further errors an breakdown.

my idea about possible fixes

improve outbound/client_pool.js at line 36
on timeout event, the error eventhandler should be removed

Steps to reproduce

highly reproduceable with mails to domain aon.at which is a big austrian isp.
because first mx record mx10.aon.at is normally not reachable

Log

2019-03-04T15:10:27.446Z [INFO] [-] [core] [outbound] Sending email as a transaction
2019-03-04T15:10:27.446Z [DEBUG] [-] [core] running pre_send_trans_email hooks
2019-03-04T15:10:27.446Z [DEBUG] [-] [outbound] always split
2019-03-04T15:10:27.447Z [INFO] [-] [core] [outbound] Processing delivery for domain: aon.at
2019-03-04T15:10:27.632Z [DEBUG] [-] [outbound] todo header length: 453
2019-03-04T15:10:27.633Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] running send_email hooks
2019-03-04T15:10:27.634Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Sending mail: 1551712227447_1551712227447_0_22880_dyU6ln_105_mailgateway
2019-03-04T15:10:27.634Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] running get_mx hooks
2019-03-04T15:10:27.693Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Looking up A records for: mx10.aon.at
2019-03-04T15:10:27.694Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Attempting to deliver to: 213.33.98.148:25 (0) (0)
2019-03-04T15:10:27.695Z [DEBUG] [B1101D5D-F0C4-4446-84C0-173F0A620F96] [core] [outbound] created
2019-03-04T15:10:57.696Z [NOTICE] [-] [core] [outbound] Failed to get pool entry: Outbound connection timed out to 213.33.98.148:25
2019-03-04T15:10:57.696Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Looking up A records for: mx20.aon.at
2019-03-04T15:10:57.698Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Attempting to deliver to: 195.3.96.71:25 (0) (0)
2019-03-04T15:10:57.698Z [DEBUG] [C4D00EA9-C316-45A1-B74A-5C1DBD6392D0] [core] [outbound] created
2019-03-04T15:11:08.985Z [NOTICE] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] delivered file=1551712227447_1551712227447_0_22880_dyU6ln_105_mailgateway domain=aon.at host=mx20.aon.at ip=195.3.96.71 port=25 mode=SMTP tls=N auth=N response="ok 1551712268 qp 26412 by smarthub78.res.a1.net" delay=41.538 fails=0 rcpts=1/0/0
2019-03-04T15:11:08.985Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] running delivered hooks
2019-03-04T15:11:09.019Z [DEBUG] [-] [core] [outbound] release_client: C4D00EA9-C316-45A1-B74A-5C1DBD6392D0 195.3.96.71:25 to undefined
2019-03-04T15:12:34.919Z [ERROR] [-] [core] [outbound] Failed to get pool entry: Outbound connection error: Error: connect ETIMEDOUT 213.33.98.148:25
2019-03-04T15:12:34.921Z [DEBUG] [-] [core] Temp fail for: Tried all MXs
2019-03-04T15:12:34.921Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] running deferred hooks
2019-03-04T15:12:35.346Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Temp failing 1551712227447_1551712227447_0_22880_dyU6ln_105_mailgateway for 64 seconds: Tried all MXs
2019-03-04T15:12:35.347Z [INFO] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] bouncing mail: Error re-queueing email: Error: ENOENT: no such file or directory, rename '/var/spool/haraka/outbound/queue/1551712227447_1551712227447_0_22880_dyU6ln_105_mailgateway' -> '/var/spool/haraka/outbound/queue/1551712227447_1551712419346_1_22880_dyU6ln_106_mailgateway'
2019-03-04T15:12:35.347Z [DEBUG] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] running bounce hooks
2019-03-04T15:12:35.654Z [NOTICE] [EEB174E7-F8AA-4712-8CA1-F155BD06A55F.1.1] [outbound] Double bounce: Error populating bounce message: Error: ENOENT: no such file or directory, open '/var/spool/haraka/outbound/queue/1551712227447_1551712227447_0_22880_dyU6ln_105_mailgateway'
2019-03-04T15:12:35.660Z [CRIT] [-] [core] Error: Callback was already called.
2019-03-04T15:12:35.660Z [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/node_modules/async/dist/async.js:966:32
2019-03-04T15:12:35.660Z [CRIT] [-] [core] at HMailItem.hmail.next_cb (/usr/lib/node_modules/Haraka/outbound/queue.js:41:9)
2019-03-04T15:12:35.660Z [CRIT] [-] [core] at HMailItem.double_bounce (/usr/lib/node_modules/Haraka/outbound/hmail.js:1254:14)
2019-03-04T15:12:35.660Z [CRIT] [-] [core] at /usr/lib/node_modules/Haraka/outbound/hmail.js:1238:29
2019-03-04T15:12:35.660Z [CRIT] [-] [core] at ReadStream. (/usr/lib/node_modules/Haraka/outbound/hmail.js:941:17)
2019-03-04T15:12:35.661Z [CRIT] [-] [core] at emitOne (events.js:96:13)
2019-03-04T15:12:35.661Z [CRIT] [-] [core] at ReadStream.emit (events.js:188:7)
2019-03-04T15:12:35.661Z [CRIT] [-] [core] at fs.js:1956:12
2019-03-04T15:12:35.661Z [CRIT] [-] [core] at FSReqWrap.oncomplete (fs.js:123:15)
2019-03-04T15:12:35.663Z [NOTICE] [-] [core] Shutting down

[shurli]

Actually I am testing if the following fix works?

[baudehlo]

Let us know in a few days how it goes.

[analogic]

It might be similar bug as #2597

[shurli]

Works perfect for me. No more crashes since that.
Tested with pool code enabled and disabled.
As I'm not so familiar with PRs yet, is anyone able to commit the screenshot- posted changes in client_pool.js to master ?

[msimerson]

PR created.