#60 Gmail IMAP timeouts

[Jonny]

I'm trying to use mbsync with gmail. After configuration, the first time I run mbsync -a, all downloads smoothly. The second time, however, I get:

Socket error on imap.googlemail.com (172.253.120.16:993): timeout.

This error persists; the only way to clear it is to delete the sync state; after this, downloads run fine but of course download the entire inbox again.

As I understand it, the DNS for this hostname changes regularly; at the time I got this error I ran dig imap.googlemail.com I got a different IP address. I'm led to suspect that the sync state caches the IP address? I'm not sure what else could cause this.

[Oswald Buddenhagen]

the sync state does positively have nothing to do with networking.

please add -Dn to the mbsync command line, and attach the log (or send it privately if you consider it too sensitive).

[Jonny]

Interesting. Here's the log:

❯ mbsync -Dn gmail-inbox
Reading configuration file /home/jonny/.mbsyncrc
Channel gmail-inbox
Opening master store gmail-remote...
Resolving imap.googlemail.com... ok
Connecting to imap.googlemail.com (64.233.166.16:993)... 
Opening slave store gmail-local...
Connection is now encrypted
* OK Gimap ready for requests from XX.XX.XX.XX f18mb532327170wrc
>>> 1 CAPABILITY
* CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 XYZZY SASL-IR AUTH=XOAUTH2 AUTH=PLAIN AUTH=PLAIN-CLIENTTOKEN AUTH=OAUTHBEARER AUTH=XOAUTH
1 OK Thats all she wrote! f18mb532327170wrc
Logging in...
gpg: WARNING: server 'gpg-agent' is older than us (2.2.24 < 2.2.25)
>>> 2 LOGIN <user> <pass>
* CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH UTF8=ACCEPT LIST-EXTENDED LIST-STATUS LITERAL- SPECIAL-USE APPENDLIMIT=35651584
2 OK XXXX@YYYYY authenticated (Success)
>>> 3 COMPRESS DEFLATE
3 OK Success
>>> 4 NAMESPACE
* NAMESPACE (("" "/")) NIL NIL
4 OK Success
Opening master box INBOX...
>>> 5 SELECT "INBOX"
Opening slave box INBOX...
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen $Forwarded $MDNSent $NotPhishing $Phishing Junk NonJunk)
* OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $Forwarded $MDNSent $NotPhishing $Phishing Junk NonJunk \*)] Flags permitted.
* OK [UIDVALIDITY 2] UIDs valid.
* 9855 EXISTS
* 0 RECENT
* OK [UIDNEXT 96275] Predicted next UID.
* OK [HIGHESTMODSEQ 11916823]
5 OK [READ-WRITE] INBOX selected. (Success)
Loading master...
>>> 6 UID FETCH 1:95993 (UID FLAGS)
Loading slave...
slave: 32316 messages, 8363 recent
Warning: lost track of 2473 pulled message(s)
Socket error on imap.googlemail.com (64.233.166.16:993): timeout.

The timeout line happened soon after the 'warning' line above it.

For reference, my config:

IMAPAccount gmail
  Host imap.googlemail.com
  Port 993
  User XXXXXXXXXXX
  PassCmd "pass XXXXXXXXX"
  AuthMechs LOGIN
  SSLType IMAPS
  #SSLVersions TLSv1.2
  CertificateFile /etc/ssl/certs/ca-certificates.crt
  # to avoid hitting gmail limits, which appear to be 
  # 10 connections, 2.5G dowmload per day, 500M upload per day
  # https://bugzilla.mozilla.org/show_bug.cgi?id=805830
  # https://support.google.com/a/answer/1071518?hl=en
  #
  PipelineDepth 1

IMAPStore gmail-remote
  Account gmail

MaildirStore gmail-local
  SubFolders Verbatim
  Path ~/mail/gmail/
  Inbox ~/mail/gmail/INBOX

Channel gmail-inbox
  Master :gmail-remote:INBOX
  Slave :gmail-local:INBOX

[Oswald Buddenhagen]

this is concerning, because mbsync is not supposed to lose track of messages in maildir stores.
that the server simply stops responding is also concerning.

please attach the log with -D (not -Dn) of the initial sync, and then the first followup sync.

also, consider using a build from git master, at least for testing purposes.

[Jonny]

Here's the tail of the log with -D:

new message 28921 on slave
  -> pair(0,28921) exists
new message 97035 on master
  -> pair(97035,0) exists
new message 98806 on master
  -> pair(98806,0) exists
  -> updated flags to 8
new message 98807 on master
  -> pair(98807,0) exists
new message 98808 on master
  -> pair(98808,0) exists
new message 98809 on master
  -> pair(98809,0) exists
new message 98810 on master
  -> pair(98810,0) exists
new message 98811 on master
  -> pair(98811,0) exists
new message 98812 on master
  -> pair(98812,0) exists
new message 98813 on master
  -> pair(98813,0) exists
new message 98815 on master
  -> pair(98815,0) created
  -> updated flags to 8
synchronizing flags
propagating new messages
M: Called get_uidnext, ret=98816
M: Called get_memory_usage, ret=0
pushing message 2961, TUID +oVx0IZgON3y
S: [ 7] Enter fetch_msg, uid=2961, want_flags=no, want_date=no
S: [ 7] Callback enter fetch_msg, flags=S, date=0, size=18744121
S: Called get_caps, ret=0
M: Called get_caps, ret=0x3
M: [ 8] Enter store_msg, flags=S, date=0, size=18987609, to_trash=no
M: >>> 8 APPEND "INBOX" (\Seen) {18987609}
M: [ 8] Leave store_msg
S: [ 7] Callback leave fetch_msg
S: [ 7] Leave fetch_msg
M: Called get_memory_usage, ret=18987609
S: Called get_uidnext, ret=0
S: Called get_memory_usage, ret=0
pulling message 97035, TUID dUYzYeAZ3Ij6
M: [ 9] Enter fetch_msg, uid=97035, want_flags=no, want_date=no
M: [ 9] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98806, TUID bdml2S9XPtrO
M: [ 10] Enter fetch_msg, uid=98806, want_flags=no, want_date=no
M: [ 10] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98807, TUID mpjJfPsAf1/S
M: [ 11] Enter fetch_msg, uid=98807, want_flags=no, want_date=no
M: [ 11] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98808, TUID VVQvTGMi5tvY
M: [ 12] Enter fetch_msg, uid=98808, want_flags=no, want_date=no
M: [ 12] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98809, TUID bwVdO53phY8D
M: [ 13] Enter fetch_msg, uid=98809, want_flags=no, want_date=no
M: [ 13] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98810, TUID EHtHbbCK/Pkv
M: [ 14] Enter fetch_msg, uid=98810, want_flags=no, want_date=no
M: [ 14] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98811, TUID oqzZuKCALLoK
M: [ 15] Enter fetch_msg, uid=98811, want_flags=no, want_date=no
M: [ 15] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98812, TUID xh4iaYtgoOLJ
M: [ 16] Enter fetch_msg, uid=98812, want_flags=no, want_date=no
M: [ 16] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98813, TUID hZlAsf8rmvEH
M: [ 17] Enter fetch_msg, uid=98813, want_flags=no, want_date=no
M: [ 17] Leave fetch_msg
S: Called get_memory_usage, ret=0
pulling message 98815, TUID kzCVe+s3CX7V
M: [ 18] Enter fetch_msg, uid=98815, want_flags=no, want_date=no
M: [ 18] Leave fetch_msg
M: [ 5] Callback leave load_box
M: + go ahead
Socket error on imap.googlemail.com (74.125.133.16:993): timeout.
M: Callback enter bad store
M: Enter cancel_store
M: [ 8] Callback enter store_msg, sts=4, uid=0
M: [ 8] Callback leave store_msg
M: [ 9] Callback enter fetch_msg, flags=, date=0, size=0
M: [ 9] Callback leave fetch_msg
M: [ 10] Callback enter fetch_msg, flags=S, date=0, size=775434295
M: [ 10] Callback leave fetch_msg
M: [ 11] Callback enter fetch_msg, flags=, date=0, size=775041079
M: [ 11] Callback leave fetch_msg
M: [ 12] Callback enter fetch_msg, flags=, date=0, size=0
M: [ 12] Callback leave fetch_msg
M: [ 13] Callback enter fetch_msg, flags=, date=0, size=775041079
M: [ 13] Callback leave fetch_msg
M: [ 14] Callback enter fetch_msg, flags=, date=0, size=0
M: [ 14] Callback leave fetch_msg
M: [ 15] Callback enter fetch_msg, flags=, date=0, size=33
M: [ 15] Callback leave fetch_msg
M: [ 16] Callback enter fetch_msg, flags=, date=0, size=0
M: [ 16] Callback leave fetch_msg
M: [ 17] Callback enter fetch_msg, flags=, date=0, size=360923280
M: [ 17] Callback leave fetch_msg
M: [ 18] Callback enter fetch_msg, flags=S, date=0, size=0
M: [ 18] Callback leave fetch_msg
M: Leave cancel_store
S: [ 19] Enter cancel_cmds
S: [ 19] Callback enter cancel_cmds
S: [ 20] Enter cancel_cmds
S: [ 20] Callback enter cancel_cmds
S: Enter free_store
S: Leave free_store
S: [ 20] Callback leave cancel_cmds
S: [ 20] Leave cancel_cmds
S: [ 19] Callback leave cancel_cmds
S: [ 19] Leave cancel_cmds
M: Callback leave bad store

The 'lost track' messages appear every time I run mbsync. Shout if you need the complete log.

I have seen posts that suggest extending receive timeouts with Gmail specifically. Sadly I didn't save the URLs but if I find more links and numbers I'll add these.

[Oswald Buddenhagen]

fwiw, upon re-inspection i see that the error in this log occurs while uploading a 18MB message. there was a bug which would cause spurious timeouts in this situation, but it's supposed to be fixed in v1.3.2. so this suggests that this is a seemingly unmotivated timeout as in the original report, even though it appears in a completely different situation. this suggests a problem with the network connection.

[Oswald Buddenhagen]

yes, i need complete logs of both the initial sync of a mailbox and the followup sync. otherwise i cannot reconstruct the chain of events.

[Pope Rigby]

I'm having the same issue, but with mailbox.org. Is it okay if I post my logs?

[Oswald Buddenhagen]

sure

[Pope Rigby]

Sorry, it now seems to be complaining about not being able to open far side boxes.

[mod: removed huge log]

[Oswald Buddenhagen]

two things:
- when you post a lot of text, make an attachment instead of pasting it inline
- when you realize that it doesn't seem to be the same issue after all, start from scratch instead of going off-topic on the existing issue

[Pope Rigby]

Sorry about that. The other issue is gone anyway. Here's the log files:

[Oswald Buddenhagen]

ok, so how you trigger this is that you delete a lot of local mails. the timeout occurs while mbsync is pushing the deletions to the far side. the flags actually get updated, but mbsync doesn't see the confirmations any more.
it would be interesting to know the timing of this. when you run with -Dn interactively, does progress suddenly just stop before the timeout occurs 20 secs later? or does the message come out of the blue while everything seems to be going nicely?

[Pope Rigby]

The former. It will be going about its business, and then it just freezes for about 20 seconds and throws the socket timeout error.

[Oswald Buddenhagen]

ok, that's a genuine timeout then. let's find out what is triggering it.
first, try sidestepping mbsync's use of openssl:

Tunnel "openssl s_client -connect imap.mailbox.org:993 -quiet -no_ign_eof"

second, try disabling compression:

DisableExtension COMPRESS

[Pope Rigby]

It's saying Unrecognized IMAP extension 'COMPRESS' with this config file:

IMAPAccount main
# Address to connect to
Host imap.mailbox.org
User email@mailbox.org
Pass SecretPassword
Tunnel "openssl s_client -connect imap.mailbox.org:993 -quiet -no_ign_eof"
DisableExtension COMPRESS
# To store the password in an encrypted file use PassCmd instead of Pass
# PassCmd "gpg2 -q --for-your-eyes-only --no-tty -d ~/.mailpass.gpg"
#
# Use SSL
SSLType IMAPS
# The following line should work. If get certificate errors, uncomment the two following lines and read the "Troubleshooting" section.
CertificateFile /etc/ssl/certs/ca-certificates.crt
#CertificateFile ~/.cert/imap.main.com.pem
#CertificateFile ~/.cert/Equifax_Secure_CA.pem

IMAPStore main-remote
Account main

MaildirStore main-local
SubFolders Verbatim
# The trailing "/" is important
Path ~/.local/share/mail/
Inbox ~/.local/share/mail/Inbox

Channel main
Far :main-remote:
Near :main-local:
Patterns *
# Automatically create missing mailboxes, both locally and on the server
Create Both
# Save the synchronization state files in the relevant directory
SyncState *

[Oswald Buddenhagen]

oh, that's because it actually needs to be the full string, COMPRESS=DEFLATE.

[Pope Rigby]

It throws a socket error:

Reading configuration file /home/cassidy/.config/isync/config
Channel main
Opening far side store main-remote...
F: [ 1] Enter connect_store
Starting tunnel 'openssl s_client -connect imap.mailbox.org:993 -quiet -no_ign_eof'... ok
F: [ 1] Leave connect_store
Opening near side store main-local...
N: [ 2] Enter connect_store
N: [ 2] Callback enter connect_store, sts=0
pattern '*' (effective '*'): Path, no INBOX
N: [ 3] Enter list_store, flags=2
N: [ 3] Callback enter list_store
  Trash
  Sent
  Junk
  Drafts
  Archive/2021
  Archive/2020
  Archive
  INBOX/Work
  INBOX/Server
  INBOX/School
  INBOX/GitLab
  INBOX/GitHub
  INBOX
N: [ 3] Callback leave list_store
N: [ 3] Leave list_store
N: [ 2] Callback leave connect_store
N: [ 2] Leave connect_store
depth=2 C = CH, O = SwissSign AG, CN = SwissSign Gold CA - G2
verify return:1
depth=1 C = CH, O = SwissSign AG, CN = SwissSign Server Gold CA 2014 - G22
verify return:1
depth=0 C = DE, ST = Berlin, L = Berlin, O = Heinlein Support GmbH, OU = MBO, CN = *.mailbox.org
verify return:1
Socket error: secure connect to tunnel 'openssl s_client -connect imap.mailbox.org:993 -quiet -no_ign_eof': error:1408F10B:SSL routines:ssl3_get_record:wrong version number
DONE
F: [ 1] Callback enter connect_store, sts=3
F: [ 4] Enter cancel_cmds
F: [ 4] Callback enter cancel_cmds
F: Enter free_store
F: Leave free_store
F: [ 4] Callback leave cancel_cmds
F: [ 4] Leave cancel_cmds
N: [ 5] Enter cancel_cmds
N: [ 5] Callback enter cancel_cmds
N: Enter free_store
N: Leave free_store
N: [ 5] Callback leave cancel_cmds
N: [ 5] Leave cancel_cmds
F: [ 1] Callback leave connect_store

[Oswald Buddenhagen]

works for me. what doesopenssl version say? maybe you have a stray outdated copy lying around? check ldd on mbsync and openssl,.

[Pope Rigby]

works for me. what doesopenssl version say?

OpenSSL 1.1.1k 25 Mar 2021

maybe you have a stray outdated copy lying around? check ldd on mbsync and openssl,.

I'm not familiar with that, but it doesn't look like I do. Here's the output:

~ $ ldd /usr/bin/mbsync
    linux-vdso.so.1 (0x00007ffc8afdb000
    libdb-5.3.so => /usr/lib/libdb-5.3.so (0x00007fc9001b2000)
    libssl.so.1.1 => /usr/lib/libssl.so.1.1 (0x00007fc900121000)
    libcrypto.so.1.1 => /usr/lib/libcrypto.so.1.1 (0x00007fc8ffe43000)
    libsasl2.so.3 => /usr/lib/libsasl2.so.3 (0x00007fc8ffe25000)
    libz.so.1 => /usr/lib/libz.so.1 (0x00007fc8ffe0b000)
    libc.so.6 => /usr/lib/libc.so.6 (0x00007fc8ffc3e000)
    libpthread.so.0 => /usr/lib/libpthread.so.0 (0x00007fc8ffc1b000)
    libdl.so.2 => /usr/lib/libdl.so.2 (0x00007fc8ffc14000)
    /lib64/ld-linux-x86-64.so.2 => /usr/lib64/ld-linux-x86-64.so.2 (0x00007fc9003d2000)
~ $ ldd /usr/bin/openssl
    linux-vdso.so.1 (0x00007ffe6f5bd000)
    libssl.so.1.1 => /usr/lib/libssl.so.1.1 (0x00007fcb9ec02000)
    libcrypto.so.1.1 => /usr/lib/libcrypto.so.1.1 (0x00007fcb9e924000)
    libpthread.so.0 => /usr/lib/libpthread.so.0 (0x00007fcb9e903000)
    libc.so.6 => /usr/lib/libc.so.6 (0x00007fcb9e736000)
    libdl.so.2 => /usr/lib/libdl.so.2 (0x00007fcb9e72f000)
    /lib64/ld-linux-x86-64.so.2 => /usr/lib64/ld-linux-x86-64.so.2 (0x00007fcb9ed78000)

[Oswald Buddenhagen]

err, i should pay more attention to the error messages. you need to disable ssl in mbsyncrc, otherwise it tries to talk to the tunnel via ssl.

[Pope Rigby]

That actually seems to work. Here's the log:

[Oswald Buddenhagen]

the only thing the log helps is to tell me that you applied both workarounds, which isn't a useful first step - you need to try one of the suggested workarounds at a time and see which one(s) change(s) something, or if really both are needed.

the next step would be sniffing the network connections with wireshark to see where communication breaks down, and compare it with a healthy log - in case there is a clue before the actual breakdown.

[Pope Rigby]

Oops, sorry about that. I'm really confused now, though. I tried with and without SSL and compression, and those both worked just fine. Why is it working now?

[Oswald Buddenhagen]

Why is it working now?

yeah, exactly. ;)

there are several plausible theses:
- something is broken in mbsync's stacking of ssl and compression
- the same, but on the server side, and the openssl command's mildly different behavior is sufficient to sidestep the issue
- the server or network route is broken in a completely unrelated way, and just slightly changing the client behavior in whichever way is enough to sidestep the problem.

to be clear, identifying the root cause would be hard, so unless you're in for quite the learning experience, i'd recommend to just let it be and live with either workaround (disabling compression seems cleaner).