[bug]: Stalwart server sends "BYE Server shutting down." immediately after `Starting IDLE` #280

link2xt · 2024-03-04T14:15:12Z

What happened?

Delta Chat users report that Delta Chat is constantly failing to keep IDLE connection for DeltaChat folder.
In Delta Chat logs it looks like this:

2024-03-04T13:34:40.413Z	core/event            	INFO	""	21	"src/imap.rs:463: Dropping an IMAP connection."
2024-03-04T13:34:40.414Z	core/event            	WARNING	""	21	"src/scheduler.rs:644: idle: INBOX: IMAP IDLE failed: connection lost"
2024-03-04T13:34:40.415Z	core/event            	INFO	""	21	"src/imap.rs:321: Connecting to IMAP server"
2024-03-04T13:34:40.416Z	core/event            	INFO	""	21	"src/net.rs:71: Resolved XXX:993 into [XXX]:993."
2024-03-04T13:34:40.417Z	core/event            	INFO	""	21	"src/net.rs:71: Resolved XXX:993 into XXX:993."
2024-03-04T13:34:40.730Z	core/event            	INFO	""	21	"src/imap.rs:391: Logging into IMAP server with LOGIN"
2024-03-04T13:34:41.014Z	core/event            	INFO	""	21	"src/imap.rs:408: Successfully logged into IMAP server"
2024-03-04T13:34:41.106Z	core/event            	INFO	""	21	"src/imap.rs:733: No new emails in folder \"INBOX\"."
2024-03-04T13:34:41.202Z	core/event            	INFO	""	21	"src/scheduler.rs:629: IMAP session supports IDLE, using it."
2024-03-04T13:34:41.203Z	core/event            	INFO	""	21	"src/imap.rs:1833: got unsolicited response Other(ResponseData { raw: 4096, response: Data { status: Ok, code: Some(HighestModSeq(162051081336000515)), information: Some(\"Highest Modseq\") } })"
2024-03-04T13:34:41.291Z	core/event            	INFO	""	21	"src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state"
2024-03-04T13:34:41.292Z	core/event            	INFO	""	21	"src/imap/idle.rs:72: DeltaChat: Idle has NewData ResponseData { raw: 4096, response: Data { status: Bye, code: None, information: Some(\"Server shutting down.\") } }"
2024-03-04T13:34:41.292Z	core/event            	INFO	""	21	"src/imap.rs:463: Dropping an IMAP connection."

On the server side:


 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0001 LOGIN \"alice@example.org\" \"iXuCTU42hUuNWC9mwwZ4cCzP54d4Sa9UhN\"\r\n" size=69
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="A0001 OK [CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE SASL-IR LITERAL+ ID UTF8=ACCEPT IDLE NAMESPACE CHILDREN MULTIAPPEND BINARY UNSELECT ACL UIDPLUS ESEARCH WITHIN SEARCHRES SORT THREAD=REFERENCES LIST-EXTENDED ESORT SORT=DISPLAY SPECIAL-USE CREATE-SPECIAL-USE MOVE CONDSTORE QRESYNC UNAUTHENTICATE STATUS=SIZE OBJECTID PREVIEW] Authentication successful\r\n" size=351
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0001 LOGIN \"alice@example.org\" \"iXuCTU42hUuNWC9mwwZ4cCzP54d4Sa9UhN\"\r\n" size=69
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="A0001 OK [CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE SASL-IR LITERAL+ ID UTF8=ACCEPT IDLE NAMESPACE CHILDREN MULTIAPPEND BINARY UNSELECT ACL UIDPLUS ESEARCH WITHIN SEARCHRES SORT THREAD=REFERENCES LIST-EXTENDED ESORT SORT=DISPLAY SPECIAL-USE CREATE-SPECIAL-USE MOVE CONDSTORE QRESYNC UNAUTHENTICATE STATUS=SIZE OBJECTID PREVIEW] Authentication successful\r\n" size=351
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0002 CAPABILITY\r\n" size=18
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE SASL-IR LITERAL+ ID UTF8=ACCEPT IDLE NAMESPACE CHILDREN MULTIAPPEND BINARY UNSELECT ACL UIDPLUS ESEARCH WITHIN SEARCHRES SORT THREAD=REFERENCES LIST-EXTENDED ESORT SORT=DISPLAY SPECIAL-USE CREATE-SPECIAL-USE MOVE CONDSTORE QRESYNC UNAUTHENTICATE STATUS=SIZE OBJECTID PREVIEW\r\nA0002 OK CAPABILITY completed\r\n" size=347
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0002 CAPABILITY\r\n" size=18
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="* CAPABILITY IMAP4rev2 IMAP4rev1 ENABLE SASL-IR LITERAL+ ID UTF8=ACCEPT IDLE NAMESPACE CHILDREN MULTIAPPEND BINARY UNSELECT ACL UIDPLUS ESEARCH WITHIN SEARCHRES SORT THREAD=REFERENCES LIST-EXTENDED ESORT SORT=DISPLAY SPECIAL-USE CREATE-SPECIAL-USE MOVE CONDSTORE QRESYNC UNAUTHENTICATE STATUS=SIZE OBJECTID PREVIEW\r\nA0002 OK CAPABILITY completed\r\n" size=347
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0003 ID (\"name\" \"Delta Chat\")\r\n" size=32
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* ID (\"name\" \"Stalwart IMAP\" \"version\" \"0.6.0\" \"vendor\" \"Stalwart Labs Ltd.\" \"support-url\" \"https://stalw.art/imap\")\r\nA0003 OK ID completed\r\n" size=141
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0003 ID (\"name\" \"Delta Chat\")\r\n" size=32
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="* ID (\"name\" \"Stalwart IMAP\" \"version\" \"0.6.0\" \"vendor\" \"Stalwart Labs Ltd.\" \"support-url\" \"https://stalw.art/imap\")\r\nA0003 OK ID completed\r\n" size=141
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0004 SELECT \"DeltaChat\" (CONDSTORE)\r\n" size=38
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* 10 EXISTS\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* 0 RECENT\r\n* OK [PERMANENTFLAGS (\\Deleted \\Seen \\Answered \\Flagged \\Draft \\*)] All allowed\r\n* OK [UIDVALIDITY 1075527367] UIDs valid\r\n* OK [UIDNEXT 11] Next predicted UID\r\n* OK [HIGHESTMODSEQ 162051081336000515] Highest Modseq\r\n* OK [MAILBOXID (iaaaaaf)] Unique Mailbox ID\r\nA0004 OK [READ-WRITE] SELECT completed\r\n" size=380
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0004 SELECT \"INBOX\" (CONDSTORE)\r\n" size=34
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="* 1 EXISTS\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* 0 RECENT\r\n* OK [PERMANENTFLAGS (\\Deleted \\Seen \\Answered \\Flagged \\Draft \\*)] All allowed\r\n* OK [UIDVALIDITY 2923391969] UIDs valid\r\n* OK [UIDNEXT 11] Next predicted UID\r\n* OK [HIGHESTMODSEQ 162051081336000515] Highest Modseq\r\n* OK [MAILBOXID (iaaaaaa)] Unique Mailbox ID\r\nA0004 OK [READ-WRITE] SELECT completed\r\n" size=379
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0005 UID FETCH 1:* (FLAGS) (CHANGEDSINCE 162048114260185094)\r\n" size=63
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* OK [HIGHESTMODSEQ 162051081336000515] Highest Modseq\r\n" size=56
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="A0005 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0005 UID FETCH 1:* (FLAGS) (CHANGEDSINCE 162051081336000515)\r\n" size=63
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="* OK [HIGHESTMODSEQ 162051081336000515] Highest Modseq\r\n" size=56
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="A0005 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0006 UID FETCH 11:* (UID INTERNALDATE RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])\r\n" size=188
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* 10 FETCH (UID 10 INTERNALDATE \"04-Mar-2024 11:08:33 +0000\" RFC822.SIZE 2551 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {97}\r\nFrom: <alice@example.org>\r\nMessage-ID: <Mr.bviKCHVc9Bl.vwiwXrb2wrW@example.org>\r\nChat-Version: 1.0\r\n\r\n)\r\n" size=314
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="A0006 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0006 UID FETCH 11:* (UID INTERNALDATE RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])\r\n" size=188
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="* 1 FETCH (UID 10 INTERNALDATE \"04-Mar-2024 11:32:56 +0000\" RFC822.SIZE 2567 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {97}\r\nFrom: <alice@example.org>\r\nMessage-ID: <Mr.QTYGv3Pcz-L.Rf4_OoCW6EO@example.org>\r\nChat-Version: 1.0\r\n\r\n)\r\n" size=313
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="A0006 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0007 UID FETCH 1:* (FLAGS) (CHANGEDSINCE 162048114260185094)\r\n" size=63
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="A0007 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0007 UID FETCH 1:* (FLAGS) (CHANGEDSINCE 162051081336000515)\r\n" size=63
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="A0007 OK UID FETCH completed\r\n" size=30
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::client: event="read" data="A0008 IDLE\r\n" size=12
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="+ Idling, send 'DONE' to stop.\r\n" size=32
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::op::idle: Starting IDLE. event="stat" context="idle"
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::client: event="read" data="A0008 IDLE\r\n" size=12
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::core::session: event="write" data="+ Idling, send 'DONE' to stop.\r\n" size=32
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35690}: imap::op::idle: Starting IDLE. event="stat" context="idle"
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: event="write" data="* BYE Server shutting down.\r\n" size=29
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::op::idle: IDLE channel closed.
 session{instance="imaptls" protocol=Imap remote.ip="XXX-REMOTE-IPv6-XXX" remote.port=35680}: imap::core::session: Disconnecting client. event="disconnect"

Note that there are two remote connections, one on port 35680 and one on port 35690. 35690 is an INBOX connection and it works fine, but 36580 (DeltaChat folder connection) gets BYE.

There is a similar problem visible with Thunderbird in logs posted at
#234 (comment)

How can we reproduce the problem?

Connect Delta Chat with default configuration to new stalwart server.

Version

v0.6.x

What database are you using?

RocksDB

What blob storage are you using?

RocksDB

Where is your directory located?

Internal

What operating system are you using?

Docker latest

Code of Conduct

I agree to follow this project's Code of Conduct

The text was updated successfully, but these errors were encountered:

link2xt · 2024-03-04T14:23:54Z

Similar output from deltachat-repl with IMAP tracing enabled:

 2024-03-04T14:20:05.852Z INFO  deltachat_repl          > Received ConnectivityChanged
 2024-03-04T14:20:05.852Z INFO  deltachat_repl          > Received ImapInboxIdle
 2024-03-04T14:20:05.852Z TRACE async_imap::imap_stream > decode: input: Ok("")
 2024-03-04T14:20:05.852Z INFO  deltachat_repl          > src/scheduler.rs:647: IMAP session supports IDLE, using it.
 2024-03-04T14:20:05.852Z TRACE async_imap::imap_stream > decode: incomplete data, need minimum 1 bytes
 2024-03-04T14:20:05.852Z INFO  deltachat_repl          > src/imap.rs:1633: "INBOX": got unsolicited response Other(ResponseData { raw: 4096, response: Data { status: Ok, code: Some(HighestModSeq(162051081336000515)), information: Some("Highest Modseq") } })
 2024-03-04T14:20:05.944Z TRACE async_imap::imap_stream > decode: input: Ok("+ Idling, send 'DONE' to stop.\r\n")
 2024-03-04T14:20:05.944Z TRACE async_imap::imap_stream > decode: input: Ok("")
 2024-03-04T14:20:05.944Z TRACE async_imap::imap_stream > decode: incomplete data, need minimum 1 bytes
 2024-03-04T14:20:05.945Z INFO  deltachat_repl          > src/imap/idle.rs:60: INBOX: Idle entering wait-on-remote state
 2024-03-04T14:20:05.945Z TRACE async_imap::imap_stream > decode: input: Ok("* BYE Server shutting down.\r\n")
 2024-03-04T14:20:05.945Z TRACE async_imap::imap_stream > encode: input: None, Ok("DONE")
 2024-03-04T14:20:05.945Z TRACE async_imap::imap_stream > decode: input: Ok("")
 2024-03-04T14:20:05.945Z TRACE async_imap::imap_stream > decode: incomplete data, need minimum 1 bytes
 2024-03-04T14:20:05.948Z INFO  deltachat_repl          > src/imap/idle.rs:72: DeltaChat: Idle has NewData ResponseData { raw: 4096, response: Data { status: Bye, code: None, information: Some("Server shutting down.") } }
 2024-03-04T14:20:05.948Z WARN  deltachat_repl          > src/scheduler.rs:698: Failed fetch_idle: idle: DeltaChat: IMAP IDLE failed: connection lost
 2024-03-04T14:20:05.948Z WARN  deltachat_repl          > src/imap.rs:295: IMAP got rate limited, waiting for 0h 0m 56s until can connect
 2024-03-04T14:20:40.232Z TRACE async_imap::imap_stream > decode: input: Ok("* BYE Server shutting down.\r\n")
 2024-03-04T14:20:40.233Z TRACE async_imap::imap_stream > encode: input: None, Ok("DONE")
 2024-03-04T14:20:40.233Z TRACE async_imap::imap_stream > decode: input: Ok("")
 2024-03-04T14:20:40.233Z TRACE async_imap::imap_stream > decode: incomplete data, need minimum 1 bytes
 2024-03-04T14:20:40.234Z INFO  deltachat_repl          > src/imap/idle.rs:72: INBOX: Idle has NewData ResponseData { raw: 4096, response: Data { status: Bye, code: None, information: Some("Server shutting down.") } }
 2024-03-04T14:20:40.234Z WARN  deltachat_repl          > src/scheduler.rs:410: Failed fetch_idle: idle: INBOX: IMAP IDLE failed: connection lost
 2024-03-04T14:20:40.234Z WARN  deltachat_repl          > src/imap.rs:295: IMAP got rate limited, waiting for 0h 0m 22s until can connect

In any case, sending * BYE Server shutting down. immediately after + Idling, send 'DONE' to stop. looks like a bug on the server side.

stappersg · 2024-03-04T21:31:22Z

A few days ago there was stalwartlabs/imap-server#14
Now has this issue a link to that issue.

link2xt · 2024-03-04T21:42:48Z

This bugreport should also be moved to imap-server repo probably.

EDIT: actually not, the code responsible for this BYE is inside the mail-server repo:

mail-server/crates/imap/src/op/idle.rs

Lines 134 to 136 in ff279b3

    
           self.write_bytes(&b"* BYE Server shutting down.\r\n"[..]).await.ok(); 
        
           tracing::debug!(parent: &self.span, "IDLE channel closed."); 
        
           return Err(());

nomadturk · 2024-03-05T08:59:06Z

@link2xt

That's already fixed: 414a143...d94a6a2

mdecimus · 2024-03-05T11:26:14Z

Thanks for the report @link2xt

This was just fixed, it happened with concurrent IDLE commands. The second IDLE command was disconnecting the first one.

This fix will be included in v0.7.0, do not upgrade yet as the database schemas are incompatible.

link2xt added the bug Something isn't working label Mar 4, 2024

link2xt changed the title ~~[bug]: Stalwart server sends "BYE Server shutting down." immediately after IDLE~~ [bug]: Stalwart server sends "BYE Server shutting down." immediately after Starting IDLE Mar 4, 2024

mdecimus added a commit that referenced this issue Mar 5, 2024

Fix: second IDLE connections disconnects the first one (#280)

9a5c779

mdecimus closed this as completed in 9bfdfb5 Mar 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug]: Stalwart server sends "BYE Server shutting down." immediately after `Starting IDLE` #280

[bug]: Stalwart server sends "BYE Server shutting down." immediately after `Starting IDLE` #280

link2xt commented Mar 4, 2024 •

edited

link2xt commented Mar 4, 2024

stappersg commented Mar 4, 2024

link2xt commented Mar 4, 2024 •

edited

nomadturk commented Mar 5, 2024

mdecimus commented Mar 5, 2024

[bug]: Stalwart server sends "BYE Server shutting down." immediately after Starting IDLE #280

[bug]: Stalwart server sends "BYE Server shutting down." immediately after Starting IDLE #280

Comments

link2xt commented Mar 4, 2024 • edited

What happened?

How can we reproduce the problem?

Version

What database are you using?

What blob storage are you using?

Where is your directory located?

What operating system are you using?

Code of Conduct

link2xt commented Mar 4, 2024

stappersg commented Mar 4, 2024

link2xt commented Mar 4, 2024 • edited

nomadturk commented Mar 5, 2024

mdecimus commented Mar 5, 2024

[bug]: Stalwart server sends "BYE Server shutting down." immediately after `Starting IDLE` #280

[bug]: Stalwart server sends "BYE Server shutting down." immediately after `Starting IDLE` #280

link2xt commented Mar 4, 2024 •

edited

link2xt commented Mar 4, 2024 •

edited