greenmail icon indicating copy to clipboard operation
greenmail copied to clipboard

Published 20 hours ago • verified publisher icon greenmail-mail-test

`Error processing command: End of stream Command should be '<tag> IDLE'` after updating to v1.6.5

Open ceisele-r opened this issue 3 years ago • 7 comments

After updating to greenmail v1.6.5, the following exception is logged at the end of our test executions:

commands.IdleCommand| Error processing command: End of stream Command should be '<tag> IDLE'
com.icegreen.greenmail.imap.ProtocolException: End of stream
	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
	at com.icegreen.greenmail.imap.commands.IdleCommand.waitForClientDone(IdleCommand.java:46)
	at com.icegreen.greenmail.imap.commands.IdleCommand.doProcess(IdleCommand.java:35)
	at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
	at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:53)
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
	at java.lang.Thread.run(Thread.java:748)

commands.IdleCommand| Error processing command: End of stream Command should be '<tag> IDLE'
com.icegreen.greenmail.imap.ProtocolException: End of stream
	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
	at com.icegreen.greenmail.imap.commands.IdleCommand.waitForClientDone(IdleCommand.java:46)
	at com.icegreen.greenmail.imap.commands.IdleCommand.doProcess(IdleCommand.java:35)
	at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
	at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:53)
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
	at java.lang.Thread.run(Thread.java:748)
Exception in thread "imap:ourtestdomain.com:3143<-/127.0.0.1:33310" java.lang.IllegalStateException: Can not handle IMAP connection
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:66)
	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.icegreen.greenmail.imap.ProtocolException: End of stream
	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
	at com.icegreen.greenmail.imap.ImapRequestLineReader.consumeLine(ImapRequestLineReader.java:176)
	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:57)
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
	... 2 more
Exception in thread "imap:ourtestdomain.com:3143<-/127.0.0.1:33288" java.lang.IllegalStateException: Can not handle IMAP connection
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:66)
	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.icegreen.greenmail.imap.ProtocolException: End of stream
	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
	at com.icegreen.greenmail.imap.ImapRequestLineReader.consumeLine(ImapRequestLineReader.java:176)
	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:57)
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
	... 2 more

This probably happens during something being shut down (probably the connection by imap).

If you need more information, please let me know.

ceisele-r avatar Aug 19 '21 08:08 ceisele-r

@ceisele-r Thanks for the report. Would you be able to provide a debug log (depends on how you start greenmail: standalone -Dgreenmail.verbose or embedded set logger com.icegreen.greenmail to level DEBUG). What client are you using? Could you ideally provide its IMAP-Log as well? It seems that the client terminates with an IDLE wait still open (and doesn't end it properly). We don't handle that well. I would like to reproduce with the client you are using.

apinske avatar Aug 19 '21 13:08 apinske

@apinske sorry for the late response. We are using node-imap (https://github.com/mscdex/node-imap).

I will try to gather the debug logs for greenmail, unfortunately, I don't think node-imap itself has a log.

ceisele-r avatar Sep 07 '21 07:09 ceisele-r

@apinske here is the exception part with verbose log activated and the most recent logging from greenmail before that (last imap and last smtp block):

2021-09-07T08:29:50.6428581Z 2021-09-07 08:29:50,606 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: * 1 EXISTS\r\n
2021-09-07T08:29:50.6429780Z 2021-09-07 08:29:50,606 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: * 1 RECENT\r\n
2021-09-07T08:29:50.6431054Z 2021-09-07 08:29:50,606 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: IDLE OK IDLE completed.\r\n
2021-09-07T08:29:50.6432296Z 2021-09-07 08:29:50,607 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| C: DONE\r\n
2021-09-07T08:29:50.6502169Z 2021-09-07 08:29:50,649 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG ommands.SearchTermBuilder| Creating search term for 'ALL'
2021-09-07T08:29:50.6530206Z 2021-09-07 08:29:50,649 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| C: A176 UID SEARCH ALL\r\n
2021-09-07T08:29:50.6531864Z 2021-09-07 08:29:50,649 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: * SEARCH 46\r\n
2021-09-07T08:29:50.6533171Z 2021-09-07 08:29:50,649 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: A176 OK SEARCH completed.\r\n
2021-09-07T08:29:50.6534683Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| C: A177 UID FETCH 46 (UID FLAGS INTERNALDATE BODYSTRUCTURE BODY.PEEK[])\r\n
2021-09-07T08:29:50.6536587Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG     commands.FetchCommand| Fetching body part for section specifier  and mime message (contentType=text/html; charset=utf-8
2021-09-07T08:29:50.6538509Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: * 1 FETCH (FLAGS () INTERNALDATE "07-Sep-2021 08:29:50 +0000" BODYSTRUCTURE ("TEXT" "HTML" ("charset" "utf-8") NIL NIL "quoted-pr[WRAP]
2021-09-07T08:29:50.6540142Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: intable" 9463 335 NIL NIL NIL) UID 46 BODY[] {9946}\r\n
2021-09-07T08:29:50.6541620Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Return-Path: <[email protected]>\r\n
2021-09-07T08:29:50.6543137Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Received: from 127.0.0.1 (HELO [127.0.0.1]); Tue Sep 07 08:29:50 UTC 2021\r\n
2021-09-07T08:29:50.6544571Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Content-Type: text/html; charset=utf-8\r\n
2021-09-07T08:29:50.6546227Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: From: "Test-Server" <[email protected]>\r\n
2021-09-07T08:29:50.6547750Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: To: [email protected]\r\n
2021-09-07T08:29:50.6549200Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Reply-To: [email protected]\r\n
2021-09-07T08:29:50.6550611Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Subject: Test test\r\n
2021-09-07T08:29:50.6567774Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Message-ID: <[email protected]>\r\n
2021-09-07T08:29:50.6570084Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Content-Transfer-Encoding: quoted-printable\r\n
2021-09-07T08:29:50.6571645Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: Date: Tue, 07 Sep 2021 08:29:50 +0000\r\n
2021-09-07T08:29:50.6572949Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: MIME-Version: 1.0\r\n
2021-09-07T08:29:50.6574177Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: \r\n
2021-09-07T08:29:50.6575819Z 2021-09-07 08:29:50,650 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: <html xmlns=3D"http://www.w3.org/1999/xhtml">\r\n
... (I stripped the remaining parts of the html mail contents)
2021-09-07T08:29:50.7026389Z 2021-09-07 08:29:50,652 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: </html>\r\n
2021-09-07T08:29:50.7027559Z 2021-09-07 08:29:50,652 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: )\r\n
2021-09-07T08:29:50.7029184Z 2021-09-07 08:29:50,652 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: A177 OK FETCH completed.\r\n
2021-09-07T08:29:50.7030612Z             ✔ text_xyz (191ms)
2021-09-07T08:29:50.7031822Z 2021-09-07 08:29:50,655 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| C: IDLE IDLE\r\n
2021-09-07T08:29:50.7033012Z 2021-09-07 08:29:50,655 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: + OK\r\n

...
...

2021-09-07T08:30:42.5653155Z 2021-09-07 08:30:42,564 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: MAIL FROM:<[email protected]>\r\n
2021-09-07T08:30:42.5658920Z 2021-09-07 08:30:42,565 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| S: 250 OK\r\n
2021-09-07T08:30:42.5663771Z 2021-09-07 08:30:42,566 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: RCPT TO:<[email protected]>\r\n
2021-09-07T08:30:42.5665470Z 2021-09-07 08:30:42,566 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| S: 250 OK\r\n
2021-09-07T08:30:42.6101229Z 2021-09-07 08:30:42,609 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: DATA\r\n
2021-09-07T08:30:42.6104573Z 2021-09-07 08:30:42,610 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| S: 354 Start mail input; end with <CRLF>.<CRLF>\r\n
2021-09-07T08:30:42.6111224Z 2021-09-07 08:30:42,610 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Content-Type: text/html; charset=utf-8\r\n
2021-09-07T08:30:42.6112993Z 2021-09-07 08:30:42,610 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: From: test user <[email protected]>\r\n
2021-09-07T08:30:42.6123464Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: To: [email protected]\r\n
2021-09-07T08:30:42.6147157Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Reply-To: [email protected]\r\n
2021-09-07T08:30:42.6151236Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Subject: Test test\r\n
2021-09-07T08:30:42.6153314Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Message-ID: <[email protected]>\r\n
2021-09-07T08:30:42.6155087Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Content-Transfer-Encoding: quoted-printable\r\n
2021-09-07T08:30:42.6156605Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: Date: Tue, 07 Sep 2021 08:30:42 +0000\r\n
2021-09-07T08:30:42.6157906Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: MIME-Version: 1.0\r\n
2021-09-07T08:30:42.6159138Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: \r\n
2021-09-07T08:30:42.6160500Z 2021-09-07 08:30:42,611 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: <html xmlns=3D"http://www.w3.org/1999/xhtml">\r\n
... (I stripped the remaining parts of the html mail contents)
2021-09-07T08:30:42.6503368Z 2021-09-07 08:30:42,614 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: </html>\r\n
2021-09-07T08:30:42.6504535Z 2021-09-07 08:30:42,614 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| C: .\r\n
2021-09-07T08:30:42.6505803Z 2021-09-07 08:30:42,614 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| S: * 67 EXISTS\r\n
2021-09-07T08:30:42.6506990Z 2021-09-07 08:30:42,619 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG    util.LineLoggingBuffer| S: 250 OK\r\n

...
...


2021-09-07T08:30:43.5013610Z 2021-09-07 08:30:43,497 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 WARN       commands.IdleCommand| Error processing command: End of stream Command should be '<tag> IDLE'
2021-09-07T08:30:43.5019352Z com.icegreen.greenmail.imap.ProtocolException: End of stream
2021-09-07T08:30:43.5021342Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
2021-09-07T08:30:43.5023693Z 	at com.icegreen.greenmail.imap.commands.IdleCommand.waitForClientDone(IdleCommand.java:46)
2021-09-07T08:30:43.5025952Z 	at com.icegreen.greenmail.imap.commands.IdleCommand.doProcess(IdleCommand.java:35)
2021-09-07T08:30:43.5028057Z 	at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
2021-09-07T08:30:43.5030361Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
2021-09-07T08:30:43.5032728Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:53)
2021-09-07T08:30:43.5034593Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
2021-09-07T08:30:43.5036295Z 	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
2021-09-07T08:30:43.5037595Z 	at java.lang.Thread.run(Thread.java:748)
2021-09-07T08:30:43.5038971Z 2021-09-07 08:30:43,500 imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG    util.LineLoggingBuffer| S: IDLE BAD End of stream Command should be '<tag> IDLE'\r\n
2021-09-07T08:30:43.5040587Z Exception in thread "imap:ourtestdomain.com:3143<-/127.0.0.1:52022" java.lang.IllegalStateException: Can not handle IMAP connection
2021-09-07T08:30:43.5041984Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:66)
2021-09-07T08:30:43.5043670Z 	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
2021-09-07T08:30:43.5044977Z 	at java.lang.Thread.run(Thread.java:748)
2021-09-07T08:30:43.5046001Z Caused by: com.icegreen.greenmail.imap.ProtocolException: End of stream
2021-09-07T08:30:43.5047845Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
2021-09-07T08:30:43.5050191Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.consumeLine(ImapRequestLineReader.java:176)
2021-09-07T08:30:43.5052579Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:57)
2021-09-07T08:30:43.5054422Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
2021-09-07T08:30:43.5055383Z 	... 2 more
2021-09-07T08:30:43.5064684Z 2021-09-07 08:30:43,498 smtp:ourtestdomain.com:3025<-/127.0.0.1:54274 DEBUG       smtp.SmtpConnection| Unexpected end of stream, read 0 bytes: 
2021-09-07T08:30:43.5066199Z 2021-09-07 08:30:43,497 imap:ourtestdomain.com:3143<-/127.0.0.1:52040 WARN       commands.IdleCommand| Error processing command: End of stream Command should be '<tag> IDLE'
2021-09-07T08:30:43.5067518Z com.icegreen.greenmail.imap.ProtocolException: End of stream
2021-09-07T08:30:43.5069345Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
2021-09-07T08:30:43.5071716Z 	at com.icegreen.greenmail.imap.commands.IdleCommand.waitForClientDone(IdleCommand.java:46)
2021-09-07T08:30:43.5073946Z 	at com.icegreen.greenmail.imap.commands.IdleCommand.doProcess(IdleCommand.java:35)
2021-09-07T08:30:43.5076036Z 	at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
2021-09-07T08:30:43.5078365Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
2021-09-07T08:30:43.5080757Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:53)
2021-09-07T08:30:43.5098326Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
2021-09-07T08:30:43.5100082Z 	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
2021-09-07T08:30:43.5101377Z 	at java.lang.Thread.run(Thread.java:748)
2021-09-07T08:30:43.5102759Z 2021-09-07 08:30:43,506 imap:ourtestdomain.com:3143<-/127.0.0.1:52040 DEBUG    util.LineLoggingBuffer| S: IDLE BAD End of stream Command should be '<tag> IDLE'\r\n
2021-09-07T08:30:43.5104354Z Exception in thread "imap:ourtestdomain.com:3143<-/127.0.0.1:52040" java.lang.IllegalStateException: Can not handle IMAP connection
2021-09-07T08:30:43.5105954Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:66)
2021-09-07T08:30:43.5107630Z 	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:165)
2021-09-07T08:30:43.5108961Z 	at java.lang.Thread.run(Thread.java:748)
2021-09-07T08:30:43.5109997Z Caused by: com.icegreen.greenmail.imap.ProtocolException: End of stream
2021-09-07T08:30:43.5111825Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.nextChar(ImapRequestLineReader.java:69)
2021-09-07T08:30:43.5114176Z 	at com.icegreen.greenmail.imap.ImapRequestLineReader.consumeLine(ImapRequestLineReader.java:176)
2021-09-07T08:30:43.5116534Z 	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:57)
2021-09-07T08:30:43.5118376Z 	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:62)
2021-09-07T08:30:43.5119221Z 	... 2 more

Let me know if you need more - as the log is pretty huge, I tried to extract only the last parts.

ceisele-r avatar Sep 07 '21 08:09 ceisele-r

@ceisele-r Sorry for the late reply. Were you updating to 1.6.5 from 1.6.4 or a version before that, i.e. were you using IMAP IDLE (introduced in 1.6.4) successfully before? It seems that node-imap (which version are you using, btw?) uses polling if IDLE is not supported.

Unfortunately, I still have no idea, what could be the problem. Is there no line after 2021-09-07T08:30:42.6506990Z that says something like imap:ourtestdomain.com:3143<-/127.0.0.1:52022 DEBUG util.LineLoggingBuffer| S: * 1 EXISTS\r\n? It seems the client libs dropped the TCP connection.

Does it only ever work for the first mail, and then the error occurs for the second one? Or is ist after a certain amount of time?

Could you attach the missing log between 2021-09-07T08:30:42.6506990Z and 2021-09-07T08:30:43.5013610Z?

apinske avatar Oct 07 '21 10:10 apinske

@apinske no worries. We updated from greenmail 1.6.2 to 1.6.5 as with the versions in between, as far as I remember, we could not update because of other issues. Before the update, we did not notice these error logs (which makes sense if the issue lies somewhere in the IMAP IDLE "range" that was not available in 1.6.2).

We are using node-imap (npm package imap https://www.npmjs.com/package/imap) v0.8.19 which is the latest (even though it's already several years old).

Unfortunately, the log from my original message was deleted meanwhile so I have to create a new log with debug logging enabled. I will do that and post check if there's such a line as you mentioned in there.

Does it only ever work for the first mail, and then the error occurs for the second one? Or is ist after a certain amount of time?

Unfortunately, I don't know. The error occurs while/after executing several hundred unittests. I will try if I can isolate it somehow.

ceisele-r avatar Oct 11 '21 15:10 ceisele-r

@apinske I received an email regarding a new comment by you ("you might have reproduced the problem") but it seems this comment is missing in this thread here on GH. Did you delete it again?

I just want to clarify whether you could reproduce this issue or whether I can still help trace it by producing the logs.

ceisele-r avatar Oct 12 '21 09:10 ceisele-r

Two years late, but I encountered a similar situation, and the problem was the result of failing to close my Folder and Session before stopping the ExecutorService. I believe the server end would read the IDLE command from the watcher, then attempt to reply on the then-closed socket.

To reproduce, just have an IdleManager on some store, then close the ExecutorService, but not any other JavaMail constructs.

krashanoff avatar May 30 '23 00:05 krashanoff