Upgrade 2.2.27 to 2.3.9.2: master(imap): net_connect_unix(imap) failed: Resource temporarily unavailable

[Aki Tuomi]

Uh. It's not actually supported to access same user concurrently from two servers even if you are using NFS. It will cause problems. You should use dovecot director or some other arrangement to make sure this does not happen.

Aki

> On 09/01/2020 16:56 Eirik Rye <rye at domeneshop.no> wrote:
> 
>  
> As a workaround for the titular issue, I have tried enabling the 
> "imap-hibernate" service on a couple of servers to reduce the number of 
> running imap processes.
> 
> Since ~50-60% of clients are in IDLE at any one time, this allows us to 
> reduce the number of running imap processes to less than half of what it 
> was.
> 
> After this I have yet to see the "net_connect_unix(imap) failed" errors 
> on these servers, however instead we are now instead seeing a few of these:
> 
>    imap([redacted])<30266><[redacted]>: Error: imap-master: Failed to 
> import client state: Mailbox INBOX: Couldn't get recently expunged UIDs 
> (uidnext=13479 highest_modseq=1716)
> 
> and
> 
>    imap([redacted])<20055><[redacted]>: Error: imap-master: Failed to 
> import client state: Mailbox INBOX: Couldn't send flag changes
>    imap([redacted])<20055><[redacted]>: NOTIFY failed in the middle of 
> FETCH reply in=0 out=0 deleted=0 expunged=0 trashed=0 hdr_count=0 
> hdr_bytes=0 body_count=0 body_bytes=0
> 
> The former I suspect may be related to our NFS-backed store and 
> simultaneous access from different, since many of the errors are 
> accompanied by other corruption related errors:
> 
>    imap([redacted])<30266><[redacted]>: Error: Mailbox INBOX: vsize-hdr 
> has invalid size: 36
> 
> This whole upgrade is part of a migration to a director-backed system, 
> because we are seeing a too large amount of corruption errors 
> (locking/indexes, etc) assumed to be caused by NFS.
> 
> Once we introduce the director cluster in front, these errors should 
> hopefully be strongly reduced. :-)
> 
> -- 
> Eirik
> 
> On 08/01/2020 15:14, Eirik Rye wrote:
> > With proctitles below.
> > 
> > Strangely, Dovecot is reporting 12679 imap-login sockets in "pre-login" 
> > state, which is about 50% more than there are active TCP connections to 
> > the server (8271, of which 7546 are in "imap-login" process according to 
> > `ss -tp`).
> > 
> > On another server, not currently experiencing this issue, the number of 
> > TCP sockets appears to more closely match the number of imap-login 
> > sockets used (either in pre-login or TLS proxing).
> > 
> > imap:~# ps -f --ppid `pidof dovecot` | egrep -v "dovecot/(imap|pop3) "
> > UID        PID  PPID  C STIME TTY          TIME CMD
> > dovenull  5262  5260  0 11:48 ?        00:00:00 dovecot/pop3-login
> > dovenull  5263  5260  2 11:48 ?        00:03:53 dovecot/imap-login [724 
> > pre-login + 113 TLS proxies]
> > dovecot   5264  5260  0 11:48 ?        00:01:15 dovecot/anvil [21 
> > connections]
> > root      5265  5260  1 11:48 ?        00:02:18 dovecot/log
> > dovenull  5266  5260  0 11:48 ?        00:00:00 dovecot/pop3-login
> > dovenull  5267  5260  0 11:48 ?        00:00:00 dovecot/pop3-login
> > dovenull  5268  5260  0 11:48 ?        00:00:00 dovecot/pop3-login
> > dovenull  5269  5260 20 11:48 ?        00:35:34 dovecot/imap-login [1073 
> > pre-login + 1199 TLS proxies]
> > dovenull  5270  5260  1 11:48 ?        00:02:25 dovecot/imap-login [615 
> > pre-login + 67 TLS proxies]
> > dovenull  5271  5260  0 11:48 ?        00:01:39 dovecot/imap-login [489 
> > pre-login + 44 TLS proxies]
> > dovenull  5272  5260 14 11:48 ?        00:24:44 dovecot/imap-login [938 
> > pre-login + 720 TLS proxies]
> > dovenull  5273  5260  6 11:48 ?        00:10:30 dovecot/imap-login [845 
> > pre-login + 242 TLS proxies]
> > dovenull  5274  5260  4 11:48 ?        00:06:54 dovecot/imap-login [817 
> > pre-login + 209 TLS proxies]
> > dovenull  5275  5260  0 11:48 ?        00:01:23 dovecot/imap-login [445 
> > pre-login + 36 TLS proxies]
> > dovenull  5276  5260 25 11:48 ?        00:43:14 dovecot/imap-login [1064 
> > pre-login + 1434 TLS proxies]
> > dovenull  5277  5260  1 11:48 ?        00:02:19 dovecot/imap-login [523 
> > pre-login + 58 TLS proxies]
> > dovenull  5278  5260  9 11:48 ?        00:16:19 dovecot/imap-login [937 
> > pre-login + 462 TLS proxies]
> > dovenull  5279  5260 19 11:48 ?        00:33:24 dovecot/imap-login [937 
> > pre-login + 823 TLS proxies]
> > dovenull  5280  5260  1 11:48 ?        00:03:04 dovecot/imap-login [655 
> > pre-login + 92 TLS proxies]
> > dovenull  5281  5260 26 11:48 ?        00:45:20 dovecot/imap-login [969 
> > pre-login + 1450 TLS proxies]
> > dovenull  5282  5260  6 11:48 ?        00:10:55 dovecot/imap-login [917 
> > pre-login + 303 TLS proxies]
> > dovenull  5283  5260  4 11:48 ?        00:08:36 dovecot/imap-login [731 
> > pre-login + 128 TLS proxies]
> > root      5284  5260  2 11:48 ?        00:03:55 dovecot/config
> > dovecot   5285  5260  1 11:48 ?        00:02:19 dovecot/stats [7968 
> > connections]
> > dovecot   5286  5260  3 11:48 ?        00:05:53 dovecot/auth [138 wait, 
> > 0 passdb, 0 userdb]
> > 528246   10322  5260  0 14:36 ?        00:00:00 [imap]
> > root     16688  5260  0 14:40 ?        00:00:00 dovecot/imap
> > imap02:~# doveadm process status | grep "^imap-login " | awk "{sum += 
> > 2500-\$3} END {print sum}"
> > 20081
> > imap:~# ps -f --ppid `pidof dovecot` | grep "dovecot/imap " | wc -l
> > 7937
> > imap:~# doveadm process status | grep "^imap " | wc -l
> > 7937
> > imap:~# ss -ntp "( sport = :143 or sport = :993 )" | grep "\"imap\"" | 
> > wc -l
> > 559
> > imap:~# ss -ntp "( sport = :143 or sport = :993 )" | grep 
> > "\"imap-login\"" | wc -l
> > 7546
> > imap:~# ss -ntp "( sport = :143 or sport = :993 )" | wc -l
> > 8271
> > 
> > On 08/01/2020 11:33, Eirik Rye wrote:
> >> On 08/01/2020 11:09, Aki Tuomi wrote:
> >>> Can you enable 'verbose_proctitle=yes' and maybe compare with ss -tp 
> >>> output?
> >>
> >> Thanks for the response!
> >>
> >> What exactly did you want to compare? `ss -tp` does not appear to show 
> >> cmdline/process title. I enabled it for one server, but will have to 
> >> wait for users to reconnect and for the issue to reappear there.
> >>
> >> In the meantime, on another server experiencing the same issue at this 
> >> moment (same configuration), but no proctitles:
> >>
> >> root at imap03:~# doveadm process status | grep "^imap " | wc -l
> >> 7564
> >> root at imap03:~# ps aux | grep "dovecot/imap$" | wc -l
> >> 7570
> >> root at imap03:~# ss -tp | grep '"imap-login"' | wc -l
> >> 8009
> >> root at imap03:~# ss -tp | grep '"imap"' | wc -l
> >> 536
> >> root at imap03:~# ss -nt "( sport = :143 or sport = :993 )" | wc -l
> >> 8739
> >> root at imap03:~# doveadm who -1 | wc -l
> >> 7581
> >>
> >> The `ss -tp` output appears normal (e.g. 8009+536 ~= 8739).
> >>
> > 
> >