Haraka: Error: Callback was already called

I’m getting this crash about once or twice a week on average. I can’t quite put together what the problem may be. During the times of failure, it appears the server is processing several mails simultaneously, so that makes it more difficult to pin down (or is a clue). However, in all of the cases just before the crash, there does appear to be a socket or delivery failure of various causes (time out, hang up, grey-listing delay, etc), so perhaps that is a clue. It is always in Outbound delivery. I’ll show a less busy log snippet as an example:

[11:10:43] [ERROR] [-] [outbound] Ongoing connection failed to 25.10.148.12:25 : Error: socket hang up
[11:10:43] [DEBUG] [-] [core] [outbound] release_client: 25.10.148.12:25 to undefined
[11:10:43] [DEBUG] [-] [core] Temp fail for: Tried all MXs
[11:10:43] [DEBUG] [-] [outbound] running deferred hooks
[11:10:43] [INFO] [-] [outbound] Temp failing 1496848206803_1496848302397_1_7660_YYOOgO_411_omega12 for 128 seconds: Tried all MXs
[11:10:43] [CRIT] [-] [core] Error: Callback was already called.
[11:10:43] [CRIT] [-] [core]     at C:\Haraka\npm\node_modules\Haraka\node_modules\async\dist\async.js:903:32
[11:10:43] [CRIT] [-] [core]     at HMailItem.hmail.next_cb (C:\Haraka\npm\node_modules\Haraka\outbound\queue.js:41:9)
[11:10:43] [CRIT] [-] [core]     at C:\Haraka\npm\node_modules\Haraka\outbound\hmail.js:1251:15
[11:10:43] [CRIT] [-] [core]     at FSReqWrap.oncomplete (fs.js:114:15)
[11:10:43] [NOTICE] [-] [core] Shutting down

In every case, the server immediately restarts and then successfully delivers whatever mail it crashed on. I’ve tried to find a technique to reproduce this error but have been unsuccessful. I’d appreciate any advice on how to track this problem down and fix it.

About this issue

Original URL
State: closed
Created 7 years ago
Comments: 42 (8 by maintainers)

Most upvoted comments

Email and being bored in a taxi helps hana

On 3 Feb 2018 18:29, “Sergei Sleptsov” notifications@github.com wrote:

@KingNoosh https://github.com/kingnoosh wow, thanks for such fast response!

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1954#issuecomment-362837665, or mute the thread https://github.com/notifications/unsubscribe-auth/AJbg3myfykYjhaltUm3ircr5RN9Z_f8Iks5tRJd_gaJpZM4NzWqd .

KingNoosh on Feb 3, 2018

I should’ve fixed this which’ll be available in the next release

On 3 Feb 2018 18:24, “Sergei Sleptsov” notifications@github.com wrote:

Hey! Any news about this bug? Because I have the same issue too. Thanks!

mail_1 | 2018-02-03T10:04:37.982Z [ERROR] [96F29586-8550-4261-AEFC-BB78E4AF2218.1.1] [outbound] Double bounce: Error populating bounce message: Error: ENOENT: no such file or directory, open ‘/opt/app/haraka/queue/ 1517652277349_1517652277349_0_23_AuXJ7X_326_679867d0584b’ mail_1 | 2018-02-03T10:04:37.983Z [CRIT] [-] [core] Error: Callback was already called. mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at /usr/local/lib/node_modules/Haraka/node_modules/async/dist/async.js:903:32 mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at HMailItem.hmail.next_cb (/usr/local/lib/node_modules/ Haraka/outbound/queue.js:40:9) mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at HMailItem.events.EventEmitter.HMailItem.double_bounce (/usr/local/lib/node_modules/Haraka/outbound/hmail.js:1191:10) mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at /usr/local/lib/node_modules/Haraka/outbound/hmail.js:1175:25 mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at ReadStream. (/usr/local/lib/node_modules/Haraka/outbound/hmail.js:943:13) mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at emitOne (events.js:116:13) mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at ReadStream.emit (events.js:211:7) mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at fs.js:1987:12 mail_1 | 2018-02-03T10:04:37.984Z [CRIT] [-] [core] at FSReqWrap.oncomplete (fs.js:135:15) mail_1 | error: uncaughtException: Callback was already called. date=Sat Feb 03 2018 10:04:37 GMT+0000 (UTC), pid=23, uid=0, gid=0, cwd=/opt/app, execPath=/usr/local/bin/node, version=v8.9.1, argv=[/usr/local/bin/node, /usr/local/lib/node_modules/Haraka/haraka.js, -c, haraka], rss=115953664, heapTotal=80179200, heapUsed=39829864, external=23671145, loadavg=[0.68994140625, 0.86669921875, 0.55712890625], uptime=1966064 mail_1 | Error: Callback was already called. mail_1 | at /usr/local/lib/node_modules/Haraka/node_modules/async/ dist/async.js:903:32 mail_1 | at HMailItem.hmail.next_cb (/usr/local/lib/node_modules/ Haraka/outbound/queue.js:40:9) mail_1 | at HMailItem.events.EventEmitter.HMailItem.double_bounce (/usr/local/lib/node_modules/Haraka/outbound/hmail.js:1191:10) mail_1 | at /usr/local/lib/node_modules/Haraka/outbound/hmail.js:1175:25 mail_1 | at ReadStream. (/usr/local/lib/node_modules/ Haraka/outbound/hmail.js:943:13) mail_1 | at emitOne (events.js:116:13) mail_1 | at ReadStream.emit (events.js:211:7) mail_1 | at fs.js:1987:12 mail_1 | at FSReqWrap.oncomplete (fs.js:135:15) mail_1 | 2018-02-03T10:04:37.988Z [NOTICE] [-] [core] Shutting down

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/haraka/Haraka/issues/1954#issuecomment-362837184, or mute the thread https://github.com/notifications/unsubscribe-auth/AJbg3s7h9lZkTI1CmoTOT8voqPfvPDHbks5tRJZPgaJpZM4NzWqd .

KingNoosh on Feb 3, 2018

Some extra eyes would be much appreciated. My job has been extraordinarily demanding lately (with excessive travel and unrealistic overtime) and I have had almost no time to properly debug this since it started for me. I can add some minor additional info. I see 3 distinct ways to get this error:

My previous post where the Haraka connect_timeout is equal to the receiving server’s SMTP greeting delay (and the domain has 2 or more A records). This is very repeatable and the timing is always off.
When sending an e-mail to multiple recipients all at different domains and at least 1 of the domains causes a legitimate temp fail (like grey-listing). This happens a lot to me but not every time. The logs for this one are messy because too much happens concurrently.
Sometimes Haraka will complete the sending of an e-mail successfully, but it doesn’t realize it. It will run the delivered hooks, issue the QUIT command, and delete the email file. Then, after the timeout period of “attempting” to connect to the original IP (which it did successfully), it will attempt to send the e-mail to additional A records. During the DATA phase, it will generate the error “Reading from the data stream failed: Error: ENOENT: no such file or directory” because the file really isn’t there. After it exhausts the A records it will do a temp fail and call the callback that was originally already called. I can’t purposely repeat this but see it often.

I don’t have many continuous hours of free time, but I’d like to help where I can.

superman20 on Sep 27, 2017