elizagamedev / mujmap

Bridge for synchronizing email and tags between JMAP and notmuch
GNU General Public License v3.0
63 stars 11 forks source link

mujmap sync => Error encountered in the status line: timed out reading response #37

Open teto opened 2 years ago

teto commented 2 years ago

My initial sync worked well, I now tried to change tags and reran mujmap sync and I hit: Error encountered in the status line: timed out reading response I wonder if its due to the size of the request, I've got sthg like 11000mails and I get in the log a seemingly long request with lines of

"keywords/$answered": Null, "keywords/$forwarded": Null, "keywords/$draft": Null, "keywords/$phishing": Null, "keywords/$seen": Bool(true), "keywords/$flagged": Null, "mailboxIds": Object({"86a2d9f5-c010-45a0-82ac-67c2e55da6d3": Bool(true), "a0b0232f-b611-4eaf-b185-6ed047a97c96": Bool(true), "e33b24e7-4faf-46e9-83fd-d3c97ce02868": Bool(true)})}, Id("Maa48c356ce4142cfb28d5c97"): {"keywords/$forwarded": Null, "keywords/$answered": Null, "keywords/$phishing": Null, "mailboxIds": Object({"24e4de2e-a4e2-4cd9-822e-08efbf5efab9": Bool(true), "a0b0232f-b611-4eaf-b185-6ed047a97c96": Bool(true)}), "keywords/$flagged": Null, "keywords/$seen": Bool(true), "

This is the end of the log

24e4de2e-a4e2-4cd9-822e-08efbf5efab9": Bool(true), "a0b0232f-b611-4eaf-b185-6ed047a97c96": Bool(true)}), "keywords/$forwarded": Null, "keywords/$seen": Bool(true), "keywords/$draft": Null, "keywords/$answered": Null, "keywords/$phishing": Null, "keywords/$flagged": Null}, Id("M672a30cce2ed0a77ea870958"): {"keywords/$phishing": Null, "mailboxIds": Object({"24e4de2e-a4e2-4cd9-822e-08efbf5efab9": Bool(true), "a0b0232f-b611-4eaf-b185-6ed047a97c96": Bool(true)}), "keywords/$seen": Bool(true), "keywords/$flagged": Null, "keywords/$answered": Null, "keywords/$forwarded": Null, "keywords/$draft": Null}}
[2022-07-02T20:11:32Z DEBUG ureq::stream] connecting to jmap.fastmail.com:443 at 66.111.4.141:443
[2022-07-02T20:11:32Z DEBUG rustls::client::hs] Resuming session
[2022-07-02T20:11:32Z DEBUG rustls::client::hs] Using ciphersuite Tls13(Tls13CipherSuite { suite: TLS13_AES_256_GCM_SHA384, bulk: Aes256Gcm })
[2022-07-02T20:11:32Z DEBUG rustls::client::tls13] Resuming using PSK
[2022-07-02T20:11:32Z DEBUG rustls::client::tls13] TLS1.3 encrypted extensions: [ServerNameAck]
[2022-07-02T20:11:32Z DEBUG rustls::client::hs] ALPN protocol is None
[2022-07-02T20:11:32Z DEBUG ureq::stream] created stream: TcpStream { addr: 192.168.1.13:36722, peer: 66.111.4.141:443, fd: 9 }
[2022-07-02T20:11:32Z DEBUG ureq::unit] sending request POST https://jmap.fastmail.com/api/
[2022-07-02T20:11:32Z DEBUG ureq::unit] writing prelude: POST /api/ HTTP/1.1
    Host: jmap.fastmail.com
    User-Agent: ureq/2.4.0
    Accept: */*
    Authorization: ***
    Content-Type: application/json
    accept-encoding: gzip
    Content-Length: 1288766
[2022-07-02T20:11:33Z DEBUG rustls::client::tls13] Ticket saved
[2022-07-02T20:11:37Z DEBUG ureq::stream] dropping stream: TcpStream { addr: 192.168.1.13:36722, peer: 66.111.4.141:443, fd: 9 }
error: Could not sync mail: Could not push changes to JMAP server: Could not complete API request: https://jmap.fastmail.com/api/: Network Error: Network Error: Error encountered in a header: timed out reading response

the funny thing is that the tag I changed was successfully sent to fastmail as I can now see it in the UI, which is fantastic , it means mujmap has been solving my single biggest issue in my setup so thanks for that. Let me know how I can help (testing etc)

elizagamedev commented 2 years ago

Yeah, I'm guessing it's because massive tag changes like that result in massive requests. To solve this, we should add a new config option to optionally hard-cap the number of messages to update in a request for flaky servers or connections.

teto commented 2 years ago

It passed for the first time now:

➜ mujmap sync
Retrieving metadata... (9945 possibly changed)
Downloading new mail...
█████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████████ 11/11
Applying changes to notmuch database... (11 new, 9945 changed, 0 destroyed)
Applying changes to JMAP server... (10419 changed)
~/maildir/fastmail took 25s 
➜ mujmap sync
Retrieving metadata... (10420 possibly changed)
Applying changes to notmuch database... (0 new, 10420 changed, 0 destroyed)
Applying changes to JMAP server... (509 changed)

The funny thing is that the server times out instantaneously, it's not like it tries to process my request, the timeout on fastmail side must be low. I dont know if this should be configurable (at least userfacing) but the ability to split a big request into several small ones would be nice. Maybe even the server could return a hint about the size of the request.

elizagamedev commented 2 years ago

The server does return a hint about the request size, and we do respect it, but it doesn't seem like it can be fully trusted given the behavior you're encountering 😔

georgyo commented 1 year ago

Also running into this problem, while trying to sync 14k changes do to changing a tag.

Not the most elegant of solutions, but as a band-aid, this worked for me.

diff --git a/src/remote.rs b/src/remote.rs
index 7829255..74abac1 100644
--- a/src/remote.rs
+++ b/src/remote.rs
@@ -994,7 +994,7 @@ impl Remote {
         // Send it off into cyberspace~
         const SET_METHOD_ID: &str = "0";

-        let chunk_size = self.session.capabilities.core.max_objects_in_set as usize;
+        let chunk_size = 50 as usize;

         for chunk in &updates.into_iter().chunks(chunk_size) {
             let account_id = &self.session.primary_accounts.mail;
vbmithr commented 1 year ago

Same issue here, does not work well on massive changes.