dovecot/config processes one more time - which are safe to kill?

Thu Mar 14 16:59:45 EET 2019

On 14/01/2019 01:43, Timo Sirainen wrote:
> On 13 Dec 2018, at 11.18, Arkadiusz Miśkiewicz <arekm at maven.pl> wrote:
>>
>>
>> Hello.
>>
>> The problem with dovecot/config processes never ending and spawning new
>> one on each reload
>> (https://www.dovecot.org/list/dovecot/2016-November/106058.html) is
>> becoming a problem here:
>>
>> # ps aux|grep dovecot/config|wc -l
>> 206
> 
> I think you also have 206 other Dovecot processes that are keeping the config process open? Maybe 206 imap-login processes or something? Anyway I'd expect that this would happen only if some other process is keeping a UNIX socket connection open to the config process. Unless of course there's some bug that just isn't shutting them down even though they don't have any connections.. But at least I couldn't easily reproduce that.
> 
> I suppose there isn't much of a reason for existing processes to keep the config socket open after reload, so a patch like below would likely help. Although it probably should be delayed so that existing imap/pop3-login connections doing STARTTLS wouldn't fail if that causes a new config lookup.
> 
> diff --git a/src/lib-master/master-service.c b/src/lib-master/master-service.c
> index 3de11fa1b..41005cb5e 100644
> --- a/src/lib-master/master-service.c
> +++ b/src/lib-master/master-service.c
> @@ -815,6 +815,7 @@ void master_service_stop_new_connections(struct master_service *service)
>         }
>         if (service->login != NULL)
>                 master_login_stop(service->login);
> +       master_service_close_config_fd(service);
>  }
> 
>  bool master_service_is_killed(struct master_service *service)

Wouldn't be it better if these other process simply reconnected to
current config/stats/log processes?

(I'm killing n-1 processes leaving youngest one alive)

Hm, killing older "config" processes doesn't report that killed process
was used by anything but likely this is logging behaviour difference
only (between killing config/stats vs killing log (which reports thins
like: Shutting down logging for 'imap-login: ' with 16 clients))

Mar 14 06:10:10 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 06:22:11 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 06:52:13 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 07:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=4825 uid=0 code=kill)
Mar 14 07:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=4825 uid=0 code=kill)
Mar 14 07:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=4825 uid=0 code=kill)
Mar 14 07:10:15 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 07:16:16 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 08:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=20047 uid=0 code=kill)
Mar 14 08:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=20047 uid=0 code=kill)
Mar 14 08:28:21 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 08:32:17 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 08:44:16 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 08:56:17 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 09:01:04 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=31423 uid=0 code=kill)
Mar 14 09:01:04 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=31423 uid=0 code=kill)
Mar 14 09:01:04 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=31423 uid=0 code=kill)
Mar 14 09:01:04 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=31423 uid=0 code=kill)
Mar 14 11:00:22 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 11:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=31710 uid=0 code=kill)
Mar 14 11:02:22 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 11:08:21 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 11:40:20 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 12:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=3995 uid=0 code=kill)
Mar 14 12:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=3995 uid=0 code=kill)
Mar 14 12:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=3995 uid=0 code=kill)
Mar 14 12:06:19 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 12:16:21 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 12:36:20 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 12:52:17 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 13:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=7423 uid=0 code=kill)
Mar 14 13:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=7423 uid=0 code=kill)
Mar 14 13:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=7423 uid=0 code=kill)
Mar 14 13:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=7423 uid=0 code=kill)
Mar 14 13:58:18 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 14:01:03 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=13496 uid=0 code=kill)
Mar 14 14:42:19 mailbox dovecot: master: Warning: SIGHUP received -
reloading configuration
Mar 14 15:01:02 mailbox dovecot: config: Warning: Killed with signal 15
(by pid=17043 uid=0 code=kill)

Anyway the problem is not only with "config" processes. It is also with
"stats":

# ps aux|grep dovecot/stats | wc -l
71

and with with "log" processes:

# ps aux|grep dovecot/log | wc -l
71

And only log processes report about being used by other processes when
killed:

Mar 14 15:37:41 mailbox dovecot: log(1828): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(1828): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(1828): Warning: Shutting down
logging for 'pop3-login: ' with 14 clients
Mar 14 15:37:41 mailbox dovecot: log(1342): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(1342): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(1342): Warning: Shutting down
logging for 'pop3-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(13148): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(13148): Warning: Shutting down
logging for 'imap-login: ' with 15 clients
Mar 14 15:37:41 mailbox dovecot: log(13148): Warning: Shutting down
logging for 'pop3-login: ' with 15 clients
Mar 14 15:37:41 mailbox dovecot: log(31442): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(31442): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(31442): Warning: Shutting down
logging for 'imap: ' with 701 clients
Mar 14 15:37:41 mailbox dovecot: log(31442): Warning: Shutting down
logging for 'pop3-login: ' with 14 clients
Mar 14 15:37:41 mailbox dovecot: log(30150): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(30150): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(30150): Warning: Shutting down
logging for 'imap: ' with 759 clients
Mar 14 15:37:41 mailbox dovecot: log(30150): Warning: Shutting down
logging for 'pop3-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(25422): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(25422): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(25422): Warning: Shutting down
logging for 'imap: ' with 849 clients
Mar 14 15:37:41 mailbox dovecot: log(25422): Warning: Shutting down
logging for 'pop3-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(8969): Warning: Killed with signal
15 (by pid=2597 uid=0 code=kill)
Mar 14 15:37:41 mailbox dovecot: log(8969): Warning: Shutting down
logging for 'imap-login: ' with 16 clients
Mar 14 15:37:41 mailbox dovecot: log(8969): Warning: Shutting down
logging for 'imap: ' with 802 clients
Mar 14 15:37:41 mailbox dovecot: log(8969): Warning: Shutting down
logging for 'pop3-login: ' with 16 clients

Ok, so looks like my script should ask imap*, pop3* processes to be
terminated, too (in some smart way probably like quite old connection -
terminate, very fresh - don't touch. If all processes are gone then it
would be safe to terminate log/stats/config).

I'm reloading very often - SSL certs are very often changing here and
there is no lazy loading in dovecot.

> 
>> That's a lot of wasted memory - dovecot/config processes ate over 30GB
>> of ram on 64GB box.
> 
> Are you saying your config processes take 149 MB each?

Yes.

> That doesn't sound right, unless you have a huge number of SSL certificates?

Over 600 cert pairs at the moment and only that number because dovecot
cannot handle much more.

https://www.dovecot.org/list/dovecot/2016-October/105855.html
https://dovecot.org/list/dovecot/2016-November/106083.html

-- 
Arkadiusz Miśkiewicz, arekm / ( maven.pl | pld-linux.org )