UnhandledPromiseRejectionWarning in IMAP handler

[Touffy]

Hi,

I randomly get this error when the connection has been open for about one to six hours (outlook.office.com IMAP server). It does trigger client.onerror but can't be caught by a catch on the client's methods.

Running on heroku with node ^10.

Haven't been able to reproduce it at will (it just happens on its own after some time, at which point I create a new client and reconnect and it works fine until it happens again, etc).

(node:20) UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18
    at ParserInstance.getElement (/app/node_modules/emailjs-imap-handler/dist/parser.js:152:17)
    at ParserInstance.getCommand (/app/node_modules/emailjs-imap-handler/dist/parser.js:112:29)
    at exports.default (/app/node_modules/emailjs-imap-handler/dist/parser.js:17:29)
    at Imap._parseIncomingCommands (/app/node_modules/emailjs-imap-client/dist/imap.js:577:51)
    at Imap._onData (/app/node_modules/emailjs-imap-client/dist/imap.js:428:10)
    at TCPSocket.socket.ondata.evt (/app/node_modules/emailjs-imap-client/dist/imap.js:160:16)
    at TCPSocket._emit (/app/node_modules/emailjs-tcp-socket/dist/node-socket.js:103:31)
    at TLSSocket.<anonymous> (/app/node_modules/emailjs-tcp-socket/dist/node-socket.js:69:23)
    at TLSSocket.emit (events.js:182:13)
    at addChunk (_stream_readable.js:283:12)

[felixhammerl]

That's weird. I haven't used the lib to keep instances alive for a longer period. Do you happen to know what it is your imap server is sending? Could you set the log level to be verbose and see the incoming command?

[Touffy]

I'm a bit scared to flood our logging system if I turn on debug logging 😓
but I'll try it on my local machine after removing the side-effects and show you the results.

In the meantime, I checked the logs again and we actually have two different, alternating errors. Here is the first line of each so you can see the random intervals (datetimes are shown in UTC+2):

Sep 15 03:48:11 UnhandledPromiseRejectionWarning: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
Sep 15 04:28:00 UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18
Sep 15 20:53:55 UnhandledPromiseRejectionWarning: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
Sep 15 21:16:25 UnhandledPromiseRejectionWarning: Error [ERR_STREAM_WRITE_AFTER_END]: write after end
Sep 16 12:12:42 UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18
Sep 16 13:12:56 UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18

the stack trace for the other ("write after end") error always looks like this:

at writeAfterEnd (_stream_writable.js:243:12)
at TLSSocket.Writable.write (_stream_writable.js:291:5)
at TCPSocket.send (/app/node_modules/emailjs-tcp-socket/dist/node-socket.js:129:20)
at Imap.send (/app/node_modules/emailjs-imap-client/dist/imap.js:370:19)
at Timeout._idleTimeout.setTimeout (/app/node_modules/emailjs-imap-client/dist/client.js:780:21)
at ontimeout (timers.js:425:11)
at tryOnTimeout (timers.js:289:5)
at listOnTimeout (timers.js:252:5)
at Timer.processTimers (timers.js:212:10)

[Touffy]

Oh, one more thing I can tell you without the debug logs showing one of those errors: the only thing happening on the IMAP client-side is idling (after setting onupdate). This sequence just keeps repeating with increasing numbers:

[15:45:13.667Z][...][outlook.office365.com] Idle terminated
[15:45:13.723Z][...][outlook.office365.com] S: W25 OK IDLE completed.
[15:45:14.728Z][...][outlook.office365.com] Client started idling
[15:45:14.728Z][...][outlook.office365.com] Entering idle with IDLE
[15:45:14.729Z][...][outlook.office365.com] C: W26 IDLE

During the time range in which the most recent errors occurred (this week-end), no new email was sent to the mailbox. This code was triggered a few times (5 seconds after the errors occurred as we reconnect, and after heroku's daily reboot):

client.search('INBOX', {unseen: true, not: {from: 'foo'}}, {byUid: true})

We never called listMessages or anything else because we only do that when the search above returns messages. So, unless I'm missing something, this is all happening while just idling.

[Touffy]

Yet another kind of uncaught error popped up while the IMAP client was idling:

UnhandledPromiseRejectionWarning: Error:  Socket timed out! 
    at Timeout._socketTimeoutTimer.setTimeout (/app/node_modules/emailjs-imap-client/dist/imap.js:365:63) 
    at ontimeout (timers.js:425:11) 
    at tryOnTimeout (timers.js:289:5) 
    at listOnTimeout (timers.js:252:5) 
    at Timer.processTimers (timers.js:212:10) 

It's not entirely surprising that some network errors may occur after hours of keeping a connection alive, and it's easy enough to reconnect. The only problem I have here is the uncaught bit. Someday this will make Node.js just crash.

[SunriseFox]

Yet another kind of uncaught error popped up while the IMAP client was idling:

UnhandledPromiseRejectionWarning: Error:  Socket timed out! 
    at Timeout._socketTimeoutTimer.setTimeout (/app/node_modules/emailjs-imap-client/dist/imap.js:365:63) 
    at ontimeout (timers.js:425:11) 
    at tryOnTimeout (timers.js:289:5) 
    at listOnTimeout (timers.js:252:5) 
    at Timer.processTimers (timers.js:212:10) 

It's not entirely surprising that some network errors may occur after hours of keeping a connection alive, and it's easy enough to reconnect. The only problem I have here is the uncaught bit. Someday this will make Node.js just crash.

See #195 ... I think it is the problem.

[cormip]

Also seeing the UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18 error. It's definitely occuring while the IMAP client is simply idling (not retrieving a message). The host I'm connected to is imap-mail.outlook.com:

2018-12-14 01:16:55-05:00(node:7) UnhandledPromiseRejectionWarning: Error: Unexpected char at position 18
2018-12-14 01:16:55-05:00 at ParserInstance.getElement (/app/bundle/programs/server/npm/node_modules/emailjs-imap-handler/dist/parser.js:152:17)
2018-12-14 01:16:55-05:00 at ParserInstance.getCommand (/app/bundle/programs/server/npm/node_modules/emailjs-imap-handler/dist/parser.js:112:29)
2018-12-14 01:16:55-05:00 at exports.default (/app/bundle/programs/server/npm/node_modules/emailjs-imap-handler/dist/parser.js:17:29)
2018-12-14 01:16:55-05:00 at Imap._parseIncomingCommands (/app/bundle/programs/server/npm/node_modules/emailjs-imap-client/dist/imap.js:577:51)
2018-12-14 01:16:55-05:00 at Imap._onData (/app/bundle/programs/server/npm/node_modules/emailjs-imap-client/dist/imap.js:428:10)
2018-12-14 01:16:55-05:00 at TCPSocket.socket.ondata.evt (/app/bundle/programs/server/npm/node_modules/emailjs-imap-client/dist/imap.js:160:16)
2018-12-14 01:16:55-05:00 at TCPSocket._emit (/app/bundle/programs/server/npm/node_modules/emailjs-tcp-socket/dist/node-socket.js:103:31)
2018-12-14 01:16:55-05:00 at TLSSocket.<anonymous> (/app/bundle/programs/server/npm/node_modules/emailjs-tcp-socket/dist/node-socket.js:69:23)
2018-12-14 01:16:55-05:00 at emitOne (events.js:116:13)
2018-12-14 01:16:55-05:00 at TLSSocket.emit (events.js:211:7)
2018-12-14 01:16:55-05:00 at addChunk (_stream_readable.js:263:12)
2018-12-14 01:16:55-05:00 at readableAddChunk (_stream_readable.js:250:11)
2018-12-14 01:16:55-05:00 at TLSSocket.Readable.push (_stream_readable.js:208:10)
2018-12-14 01:16:55-05:00 at TLSWrap.onread (net.js:597:20)
2018-12-14 01:16:55-05:00(node:7) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 158)