timeout due to debug output

[Uwe Kleine-K. <uwe...@kl...>]

Hello,

running mbsync 1.4.4-5 (as provided by Debian) I sometimes run into 
timeout issues. After some debugging I think I understood the issue. The 
relevant logging looks from mbsync -V -DDMns as follows (with line 
numbers, timestamp and some debugging added over 1.4.4, I hope it's 
self-explanatory):


      1  10:07:09 O: event_wait:801
      2  10:07:09 O: event_wait:814
      3  10:07:09 O: event_wait:828: fd=4
      4  10:07:09 O: socket_fd_cb:1083: conn="tunnel 'ssh -W slowmap:143 
login.ptx'"
      5  10:07:09 O: socket_fd_cb:1109: shift timeout for "tunnel 'ssh 
-W slowmap:143 login.ptx'"
      6  10:07:09 O: F: * FLAGS (\Answered \Flagged \Deleted \Seen 
\Draft unknown-0)
      7  10:07:09 O: F: * OK [PERMANENTFLAGS (\Answered \Flagged 
\Deleted \Seen \Draft unknown-0 \*)] Flags permitted.
      8  10:07:09 O: F: * 75642 EXISTS
      9  10:07:09 O: F: * 0 RECENT
     10  10:07:09 O: F: * OK [UNSEEN 2] First unseen.
     11  10:07:09 O: F: * OK [UIDVALIDITY 1590482668] UIDs valid
     12  10:07:09 O: F: * OK [UIDNEXT 75756] Predicted next UID
     13  10:07:09 O: F: 7 OK [READ-WRITE] Select completed (1.202 + 
0.000 + 1.201 secs).
     14  10:07:09 O: socket_expect_activity:809: conn="tunnel 'ssh -W 
slowmap:143 login.ptx'", expect=0
     15  10:07:09 O: socket_expect_activity:811
     16  10:07:09 O: F: [ 5] Callback enter open_box, sts=0, 
uidvalidity=1590482668
     17  10:07:09 O: F: Enter prepare_load_box, opts=0xc7
     18  10:07:09 O: F: Leave prepare_load_box, ret=0xc7
     19  10:07:09 O: N: Enter prepare_load_box, opts=0xc7
     20  10:07:09 O: N: Leave prepare_load_box, ret=0xc7
     21  10:07:09 O: Loading far side box...
     22  10:07:09 O: F: [ 7] Enter load_box, [1,inf] (find >= 0, paired 
<= 4294967295, new > 75726)
     23  10:07:09 O: F: >>> 8 UID FETCH 1:75755 (UID FLAGS)^M
     24  10:07:09 O: socket_expect_activity:809: conn="tunnel 'ssh -W 
slowmap:143 login.ptx'", expect=1
     25  10:07:09 O: socket_expect_activity:811
     26  10:07:09 O: F: [ 7] Leave load_box
     27  10:07:09 O: Loading near side box...
     28  10:07:09 O: N: [ 8] Enter load_box, [1,inf] (find >= 0, paired 
<= 4294967295, new > 75659)
     29  10:07:09 O: N: [ 8] Callback enter load_box, sts=0, 
total=75635, recent=0
     30  10:07:09 O:   uid=1     flags=S    size=0      tuid=?
     31  10:07:09 O:   uid=2     flags=     size=0      tuid=?
     32  ...
     33  10:09:02 O:   uid=75658 flags=     size=0      tuid=?
     34  10:09:02 O:   uid=75659 flags=     size=0      tuid=?
     35  10:09:02 O: near side: 75635 messages, 0 recent
     36  10:09:02 O: matching messages on near side against sync records
     37  10:09:02 O: N: [ 8] Callback leave load_box
     38  10:09:02 O: N: [ 8] Leave load_box
     39  10:09:02 O: F: [ 5] Callback leave open_box
     40  10:09:02 O: event_wait:801
     41  10:09:02 O: event_wait:801
     42  10:09:02 O: event_wait:801
     43  10:09:02 O: F: Callback enter bad store
     44  10:09:02 O: F: Enter cancel_store
     45  10:09:02 O: socket_expect_activity:809: conn="(null)", expect=0

My interpretation is that some reply is expected from the far side (line 
24) so a timeout (default value 20s) is setup. Then mbsync proceeds to 
load the local box. With the given debugging and mailbox size this takes 
longer than 20s and then the timeout timer triggers before the 
connection is checked for input the next time.

Does this sound about right?

I'll increase the timeout (maybe to 0) locally, but a proper fix would 
be very welcome.

Best regards
Uwe