thr3ads.net - dovecot - Dovecot v2.3.8 released [Oct 2019]

If this information is useful, please help other people find it:
Share via:

Tom Sommer

2019-Oct-18 11:43 UTC

Dovecot v2.3.8 released

On 2019-10-18 13:25, Tom Sommer via dovecot wrote:
> I am seeing a lot of errors since the upgrade, on multiple client 
> accounts:
> 
> Info: Connection closed: read(size=7902) failed: Connection reset by
> peer (UID FETCH running for 0.242 + waiting input/output for 108.816
> secs, 60 B in + 24780576+8192 B out, state=wait-output)
> 
> Using NFS storage (not running with the mail_nfs_index or 
> mail_nfs_storage)
> 
> Was something changed in terms of IO/Idle timeouts?
We are also seeing different I/O patterns since the upgrade, more I/O is 
being used than normal.

This is mail_debug from one of the accounts in question:

Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: Mailbox opened because: SELECT
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17854: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17854: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17855: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17855: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17856: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17856: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17857: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17857: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17858: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17858: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17859: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17859: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17860: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17860: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17861: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17861: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17862: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17862: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17863: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17863: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17864: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17864: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17865: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17865: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17866: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17866: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17867: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17867: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17868: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17868: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17869: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17869: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17870: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17870: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17871: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17871: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17872: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17872: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17873: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17873: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17874: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17874: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17875: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17875: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17876: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17876: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17877: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17877: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17878: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17878: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17879: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17879: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17880: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17880: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17881: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17881: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17882: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17882: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17883: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17883: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17884: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17884: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17885: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17885: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17886: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17886: Opened mail because: full mail
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17887: Opened mail because: prefetch
Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17887: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17888: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17888: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17889: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17889: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17890: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17890: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17891: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17891: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17892: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17892: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17893: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17893: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17894: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17894: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17895: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17895: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17896: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17896: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17897: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17897: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17898: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17898: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17899: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17899: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17900: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17900: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17901: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17901: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17902: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17902: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17903: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17903: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17904: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17904: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17905: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17905: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17906: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17906: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17907: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17907: Opened mail because: full mail
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17908: Opened mail because: prefetch
Oct 18 13:39:41 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17908: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17909: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17909: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17910: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17910: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17911: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17911: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17912: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17912: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17913: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17913: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17914: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17914: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17915: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17915: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17916: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17916: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17917: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17917: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17918: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17918: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17919: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17919: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17920: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17920: Opened mail because: full mail
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17921: Opened mail because: prefetch
Oct 18 13:39:43 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17921: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17922: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17922: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17923: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17923: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17924: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17924: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17925: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17925: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17926: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17926: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17927: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17927: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17928: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17928: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17929: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17929: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17930: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17930: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17931: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17931: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17932: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17932: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17933: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17933: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17934: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17934: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17935: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17935: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17936: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17936: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17937: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17937: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17938: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17938: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17939: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17939: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17940: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17940: Opened mail because: full mail
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17941: Opened mail because: prefetch
Oct 18 13:39:46 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17941: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17942: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17942: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17943: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17943: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17944: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17944: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17945: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17945: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17946: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17946: Opened mail because: full mail
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17947: Opened mail because: prefetch
Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox 
INBOX: UID 17947: Opened mail because: full mail
Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox
Junk:
Mailbox opened because: autoexpunge
Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug: Mailbox
Junk
E-mail: Mailbox opened because: autoexpunge
Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Info: Connection
closed: read(size=7902) failed: Connection reset by peer (UID FETCH 
running for 0.542 + waiting input/output for 78.357 secs, 60 B in + 
39221480+8192 B out, state=wait-output) in=290 out=39401283 deleted=0 
expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=94 
body_bytes=39210315

Timo Sirainen

2019-Oct-20 09:30 UTC

head link

Dovecot v2.3.8 released

> On 18 Oct 2019, at 13.43, Tom Sommer via dovecot <dovecot at
dovecot.org> wrote:
> 
>> I am seeing a lot of errors since the upgrade, on multiple client
accounts:
>> Info: Connection closed: read(size=7902) failed: Connection reset by
>> peer (UID FETCH running for 0.242 + waiting input/output for 108.816
>> secs, 60 B in + 24780576+8192 B out, state=wait-output)
>> Using NFS storage (not running with the mail_nfs_index or
mail_nfs_storage)
>> Was something changed in terms of IO/Idle timeouts?
> 
> We are also seeing different I/O patterns since the upgrade, more I/O is
being used than normal.
What was the previous version you were running?
> This is mail_debug from one of the accounts in question:
> 
> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox INBOX: Mailbox opened because: SELECT
> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox INBOX: UID 17854: Opened mail because: prefetch
> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox INBOX: UID 17854: Opened mail because: full mail
..> Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox INBOX: UID 17947: Opened mail because: full mail
Quite a lot of mail downloads for a single session. I wonder if the user really
had that many new mails or if they were being redownloaded for some reason?
> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox Junk: Mailbox opened because: autoexpunge
> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox Junk E-mail: Mailbox opened because: autoexpunge
> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Info:
Connection closed: read(size=7902) failed: Connection reset by peer (UID FETCH
running for 0.542 + waiting input/output for 78.357 secs, 60 B in +
39221480+8192 B out, state=wait-output) in=290 out=39401283 deleted=0 expunged=0
trashed=0 hdr_count=0 hdr_bytes=0 body_count=94 body_bytes=39210315
state=wait-output means Dovecot was waiting for client to read the data it is
sending. In v2.3.7 there was some changes related to this, but were you
previously successfully running v2.3.7? In v2.3.8 I can't really think of
such changes.

Tom Sommer

2019-Oct-20 09:37 UTC

head link

Dovecot v2.3.8 released

On 2019-10-20 11:30, Timo Sirainen via dovecot wrote:>> On 18 Oct 2019, at 13.43, Tom Sommer via dovecot <dovecot at
dovecot.org>
>> wrote:
>> 
>>> I am seeing a lot of errors since the upgrade, on multiple client 
>>> accounts:
>>> Info: Connection closed: read(size=7902) failed: Connection reset
by
>>> peer (UID FETCH running for 0.242 + waiting input/output for
108.816
>>> secs, 60 B in + 24780576+8192 B out, state=wait-output)
>>> Using NFS storage (not running with the mail_nfs_index or 
>>> mail_nfs_storage)
>>> Was something changed in terms of IO/Idle timeouts?
>> 
>> We are also seeing different I/O patterns since the upgrade, more I/O 
>> is being used than normal.
> 
> What was the previous version you were running?
2.3.7.2
>> This is mail_debug from one of the accounts in question:
>> 
>> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> INBOX: Mailbox opened because: SELECT
>> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> INBOX: UID 17854: Opened mail because: prefetch
>> Oct 18 13:39:37 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> INBOX: UID 17854: Opened mail because: full mail
> ..
>> Oct 18 13:39:48 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> INBOX: UID 17947: Opened mail because: full mail
> 
> Quite a lot of mail downloads for a single session. I wonder if the
> user really had that many new mails or if they were being redownloaded
> for some reason?
They might redownload because of UID FETCH failing?
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> Junk: Mailbox opened because: autoexpunge
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> Junk E-mail: Mailbox opened because: autoexpunge
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Info:
Connection
>> closed: read(size=7902) failed: Connection reset by peer (UID FETCH 
>> running for 0.542 + waiting input/output for 78.357 secs, 60 B in + 
>> 39221480+8192 B out, state=wait-output) in=290 out=39401283 deleted=0 
>> expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=94 
>> body_bytes=39210315
> 
> state=wait-output means Dovecot was waiting for client to read the
> data it is sending. In v2.3.7 there was some changes related to this,
> but were you previously successfully running v2.3.7? In v2.3.8 I can't
> really think of such changes.
Yes, we were successfully running 2.3.7.2 before, the issue started just 
after the upgrade

It can't be related to changes in the indexes? Increasing I/O

There were no input/output errors in the logs prior to 2.3.8

---
Tom

Tom Sommer

2019-Oct-20 14:49 UTC

head link

Dovecot v2.3.8 released

On 2019-10-20 11:30, Timo Sirainen via dovecot wrote:>> On 18 Oct 2019, at 13.43, Tom Sommer via dovecot <dovecot at
dovecot.org>
>> wrote:
> Quite a lot of mail downloads for a single session. I wonder if the
> user really had that many new mails or if they were being redownloaded
> for some reason?
> 
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> Junk: Mailbox opened because: autoexpunge
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Debug:
Mailbox
>> Junk E-mail: Mailbox opened because: autoexpunge
>> Oct 18 13:40:56 imap(XXXX)<7552><ebbmyS2VPPFOxv4t>: Info:
Connection
>> closed: read(size=7902) failed: Connection reset by peer (UID FETCH 
>> running for 0.542 + waiting input/output for 78.357 secs, 60 B in + 
>> 39221480+8192 B out, state=wait-output) in=290 out=39401283 deleted=0 
>> expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=94 
>> body_bytes=39210315
> 
> state=wait-output means Dovecot was waiting for client to read the
> data it is sending.
This made me think it might be a connection (TCP/IP) thing.

My Director is running with 3 listen-IPs, I removed two of them and this 
appeared to have made the errors stop.

Unsure if anything was changed in this regard between 2.3.7.2 and 2.3.8.

---
Tom

Possibly Parallel Threads

Search for more reasonably related threads

dovecot - Oct 2019 - Dovecot v2.3.8 released

Dovecot v2.3.8 released

Dovecot v2.3.8 released

Dovecot v2.3.8 released

Dovecot v2.3.8 released

Possibly Parallel Threads