Crash with davmail, due to non standard server's response formatting (space)

[palb91]

For work, I have to use o365. So my setup is a mix of davmail (o365 bridge) and msmtp, with a regular sync. I tried to setup goimapnotify, which had a strange bug, and finally fall upon mirador.

However, I cannot use it right now, because of a strange behavior, and I think it is in the parsing of the server's responses (here davmail).

Expected behavior

Easy, it should not crash… interesting stuff below

Current behavior

Same behavior when built from git or from a release, so here is the output of the debug build:

stacktrace when running $ mirador watch --trace

| 2025-03-23T10:44:24.936191Z  INFO execute: process::command: run shell command cmd="bw get password Microsoft"
| 2025-03-23T10:44:24.936248Z DEBUG execute: process::command: inherit stdin from parent
| 2025-03-23T10:44:24.936274Z DEBUG execute: process::command: stdout piped
| 2025-03-23T10:44:24.936287Z DEBUG execute: process::command: stderr piped
| Watching folder INBOX, press CTRL+C to exit…
| 2025-03-23T10:44:27.179152Z DEBUG execute: process::command: shell command gracefully exited code=0
| 2025-03-23T10:44:27.179301Z DEBUG execute: email::imap: building 1 IMAP clients
| 2025-03-23T10:44:27.182121Z TRACE client::build: imap_client::stream: more input needed
| 2025-03-23T10:44:27.216101Z TRACE client::build: imap_client::stream: read 112/1024 bytes
| 2025-03-23T10:44:27.216429Z DEBUG client::build: email::imap: using password authentication
| 2025-03-23T10:44:27.216480Z DEBUG client::build: email::imap: supported auth mechanisms mechanisms=[Login]
| 2025-03-23T10:44:27.216512Z DEBUG client::build: email::imap: trying auth mechanism… mechanism=Login
| 2025-03-23T10:44:27.216543Z DEBUG client::build: email::imap: trying login…
| 2025-03-23T10:44:27.216596Z TRACE client::build: imap_client::tasks: enqueue task command=Command { tag: Tag("0.0"), body: Login { username: Atom(AtomExt("[USER REDACTED")), password: Atom(AtomExt("[PASS REDACTED")) } }
| 2025-03-23T10:44:27.216750Z TRACE client::build: imap_client::stream: wrote 46/46 bytes
| 2025-03-23T10:44:27.264643Z TRACE client::build: imap_client::stream: read 22/1024 bytes
| 2025-03-23T10:44:27.264858Z TRACE client::build: imap_client::tasks: enqueue task command=Command { tag: Tag("0.1"), body: Capability }
| 2025-03-23T10:44:27.264974Z TRACE client::build: imap_client::stream: wrote 16/16 bytes
| 2025-03-23T10:44:27.265179Z TRACE client::build: imap_client::stream: read 65/1024 bytes
| 2025-03-23T10:44:27.265366Z TRACE client::build: imap_client::stream: more input needed
| 2025-03-23T10:44:27.305565Z TRACE client::build: imap_client::stream: read 29/1024 bytes
| 2025-03-23T10:44:27.305778Z DEBUG client::build: email::imap: login succeeded!
| 2025-03-23T10:44:27.306180Z  INFO execute: email::email::envelope::watch::imap: watching imap folder INBOX for envelope changes
| 2025-03-23T10:44:27.306265Z DEBUG execute: email::imap: client 1/1 is free, locking it
| 2025-03-23T10:44:27.306372Z DEBUG execute: email::email::envelope::watch::imap: utf7 encoded folder: INBOX
| 2025-03-23T10:44:27.306601Z TRACE execute:examine_mailbox{client=1}: imap_client::tasks: enqueue task command=Command { tag: Tag("0.2"), body: Examine { mailbox: Inbox } }
| 2025-03-23T10:44:27.306795Z TRACE execute:examine_mailbox{client=1}: imap_client::stream: wrote 19/19 bytes
| 2025-03-23T10:44:27.680308Z TRACE execute:examine_mailbox{client=1}: imap_client::stream: read 2/1024 bytes
| 2025-03-23T10:44:27.680450Z TRACE execute:examine_mailbox{client=1}: imap_client::stream: more input needed
| 2025-03-23T10:44:27.720541Z TRACE execute:examine_mailbox{client=1}: imap_client::stream: read 260/1024 bytes
| Error:
|    0: cannot examine IMAP mailbox
|    1: stream error
|    2: flow error
|    3: Received malformed message
|
| Location:
|    /app/src/account/command/watch.rs:65
|
|   ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ SPANTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
|
|    0: mirador::account::command::watch::execute
|       at src/account/command/watch.rs:35
|
|   ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
|                                 ⋮ 5 frames hidden ⋮
|    6:  as core::ops::try_trait::FromResidual>>::from_residual::h6a1f717715fb56ee
|       at /usr/src/debug/rust/rustc-1.85.1-src/library/core/src/result.rs:2014
|    7: mirador::account::command::watch::WatchCommand::execute::{{closure}}::{{closure}}::{{closure}}::hb5d060709e408a5f
|       at /app/src/account/command/watch.rs:65
|    8: mirador::account::command::watch::WatchCommand::execute::{{closure}}::{{closure}}::{{closure}}::hde647b2ac01e96c1
|       at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/macros/select.rs:557
|    9:  as core::future::future::Future>::poll::hcdd6d0c1264d14a6
|       at /usr/src/debug/rust/rustc-1.85.1-src/library/core/src/future/poll_fn.rs:151
|   10: mirador::account::command::watch::WatchCommand::execute::{{closure}}::{{closure}}::he4bf6325b1081ec1
|       at /app/src/account/command/watch.rs:81
|   11:  as core::future::future::Future>::poll::hbf4847163f679ddf
|       at /home/user/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:321
|   12: mirador::account::command::watch::WatchCommand::execute::{{closure}}::hca43857a0981e016
|       at /app/src/account/command/watch.rs:35
|   13: mirador::cli::MiradorCommand::execute::{{closure}}::hc0d59cc3cfb7e1c9
|       at /app/src/cli.rs:88
|   14: mirador::main::{{closure}}::hb01a516794aa2025
|       at /app/src/main.rs:21
|   15: tokio::runtime::park::CachedParkThread::block_on::{{closure}}::hd257543a0dd841cd
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/park.rs:284
|   16: tokio::runtime::coop::with_budget::h45be346b68de905e
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/coop.rs:107
|   17: tokio::runtime::coop::budget::hfecd4012b7be0093
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/coop.rs:73
|   18: tokio::runtime::park::CachedParkThread::block_on::hf5fc34b7db8564c1
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/park.rs:284
|   19: tokio::runtime::context::blocking::BlockingRegionGuard::block_on::hef923c6441d6275d
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/context/blocking.rs:66
|   20: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}::h298877a4605216fd
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/scheduler/multi_thread/mod.rs:87
|   21: tokio::runtime::context::runtime::enter_runtime::h12ca9aec09d072e5
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/context/runtime.rs:65
|   22: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::hecdcc28573bf2a06
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/scheduler/multi_thread/mod.rs:86
|   23: tokio::runtime::runtime::Runtime::block_on_inner::h1f3e13eacf23fe48
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/runtime.rs:370
|   24: tokio::runtime::runtime::Runtime::block_on::h479018ead7dbb069
|       at /home/pat/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/runtime.rs:342
|   25: mirador::main::h5ec3d4b1bd5f9ab3
|       at /app/src/main.rs:23
|   26: core::ops::function::FnOnce::call_once::hc50708d01cb145b3
|       at /usr/src/debug/rust/rustc-1.85.1-src/library/core/src/ops/function.rs:250
|   27: std::sys::backtrace::__rust_begin_short_backtrace::h204b7defe399440a
|       at /usr/src/debug/rust/rustc-1.85.1-src/library/std/src/sys/backtrace.rs:152
|                                 ⋮ 6 frames hidden ⋮

Debug steps

Because I do not know a lot about IMAP, I went the dumb way. I used netcat to gather requests from mirador, and replicated them in a netcat connected to davmail. Then I took the responses from davmail and replied them to mirador.

Results

The problem occurs when miradors requests EXAMINE INBOX, and the davmail responses is not formated as expected.

normal response:

* 22 EXISTS
 ^
 1 space

davmail response:

*  22 EXISTS
 ^^
 2 spaces

By modifying davmail response, removing the second space, mirador goes further without crashing.

Suggestion

It seems that davmail does not follow the standards, however I'm not sure what is the standard. In a quick parsing of the IMAP RCF, I read that the server SHOULD be strict about syntax, while I don't see the same rule for clients.

Now, I'm not sure if mirador (and other clients) should be less strict, or if davmail should have better responses formatting…

[soywod]

The actual lib used by mirador is strict by default, but quirks can be implemented to make rules less strict in order to better fit real world servers.

@duesee do we already have a quirk for this particular case?

[duesee]

Not yet! We could do three things:

• file an issue in https://github.com/modern-email/defects/issues
• file an issue for davmail
• provide a quirk in imap-codec (the library used by mirador)

I can maybe provide a quirk (workaround) in imap-codec today @soywod :-)

Does someone of you can tackle the rest?

[duesee]

By the way, what a great report @palb91!

[palb91]

I'll try to find time soon to report the issue to both projects (didn't know about defects, interesting resource). Before doing so, do you think davmail should fix this? Or is is still a valid response from the server?

provide a quirk in imap-codec (the library used by mirador)

Ah! I cloned mirador and grepped around the project, but found no relevant information about this particular problem: clues were just in another lib…

By the way, what a great report @palb91!

Thanks :) I invested quite a bit in detecting and understanding the bug, so I could take some extra time to write a proper bug report.

[duesee]

Before doing so, do you think davmail should fix this? Or is is still a valid response from the server?

Yes, I think DavMail should fix this. The RFC is indeed a bit strange as it clearly mentions extraneous spaces but somehow assumes that only clients can make this mistake...

Section 9 is more generic:

Note: [ABNF] rules MUST be followed strictly; in
        particular:

        (...)

        (2) In all cases, SP refers to exactly one space.  It is
        NOT permitted to substitute TAB, insert additional spaces,
        or otherwise treat SP as being equivalent to LWSP.

I invested quite a bit in detecting and understanding the bug, so I could take some extra time to write a proper bug report.

That would be awesome :-) By the way... what helped me a few times already is to use the parse_* examples in imap-codec to pinpoint more complicated issues. Maybe it could be helpful to you in the future :-)

I didn"t manage to provide the quirk in imap-codec today but will do a second attempt tomorrow!

[palb91]

Well… I made a mistake during my investigation, the output was 522, and I (manually) wrote 22 in the bug reports. And this change everything!

• IMAP Select unexpected response mguessan/davmail#343;
• selecting "INBOX" -> response is violating imap protocol mguessan/davmail#122.

It's on purpose, mguessan does not follow the RFC when a box has more than 500 messages, cf. this comment in #122:

The additional space is related to a workaround to avoid client timeouts with large folders.

I'm not sure why not following the RFC is the solution he choose, but there is a workaround in davmail (set davmail.enableKeepAlive=false) which works. However I don't know if there could be some downside to this setting.

Given the comments, the reason behind the additional space and the workaround, I'm pretty sure he won't fix this.

... is to use the parse_* examples in imap-codec to pinpoint more complicated issues.

I'll keep it in mind, thanks.

I didn"t manage to provide the quirk in imap-codec today but will do a second attempt tomorrow!

No rush, and now, with these new details, I don't know if this is still relevant to fix. Maybe a note somewhere about this could be enough.

[duesee]

Oh wow, that was... unexpected :-) I asked @mguessan for a clarification. Maybe we can resolve this in a better way.

[mguessan]

davmail.enableKeepAlive=false is the way to go in your case.

Just a bit of context: select command is usually fast on IMAP servers so there is not mechanism in IMAP to keep the connection alive. As DavMail has to get message list to answer this sometimes ends up in a timeout on IMAP client side. In order to avoid this I had to find a way to keep the connection alive - send something - without breaking - most - IMAP client parsing.

By disabling keep alive in DavMail you just make it compliant to IMAP RFC, just make sure the read timeout is high enough to avoid errors with large folders.

[palb91]

Hi @mguessan,

Thanks for reaching us, and for the clarification. You cleared up a small doubt that would have stayed in my mind for a long time.

just make sure the read timeout is high enough to avoid errors with large folders.

I did not have the problem but I'll keep that in mind.

[duesee]

Thanks for the answer @mguessan! I still don't understand the "one vs two spaces trick", though :-(

How does * n EXISTS (with two spaces) prevents a timeout that * n EXISTS (with one space) can't?

I'm asking because lax clients (accepting e.g. multiple spaces) will interpret both response variants in exact the same way. So... I'm kind of missing how it triggers different behavior.