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

[Eirik Rye]

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).
> 


-- 
Eirik