systemctl status dovecot.service issue

[msullivan]

Hello:

On one of three servers I am administering is currently running 74.0.4 on CentOS 7.5 (in a Virtuozzo container). I have a systemctl status process that runs often enough that I think it is causing a performance hit on the system.

Every few minutes I see the following process appear in the process log. (I've gone to watch it in the shell using top as well.)

/usr/bin/systemctl status dovecot.service with >90% CPU & about 10% memory (4GB available), the process runs for about a minute then ends. It starts up again after a minute or two and repeats.

I've tried to manually run the command to see what is going on and the output is MASSIVE!

I get the typical status information about the process

Show/Hide: Output from /usr/bin/systemctl status dovecot.service

● dovecot.service - Dovecot Imap Server

Loaded: loaded (/etc/systemd/system/dovecot.service; enabled; vendor preset: disabled)

Active: active (running) since Sun 2018-08-19 15:41:22 EDT; 1 day 6h ago

Main PID: 1624 (dovecot)

CGroup: /system.slice/dovecot.service

├─ 684 dovecot/imap

├─ 742 dovecot/imap

├─ 743 dovecot/imap

├─ 744 dovecot/imap

├─ 745 dovecot/imap

├─ 1027 dovecot/imap

├─ 1035 dovecot/imap

├─ 1392 dovecot/imap

├─ 1394 dovecot/imap

├─ 1395 dovecot/imap

├─ 1396 dovecot/imap

├─ 1397 dovecot/imap

├─ 1399 dovecot/imap

├─ 1404 dovecot/imap

├─ 1405 dovecot/imap

├─ 1624 /usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf

├─ 1625 dovecot/pop3-login

├─ 1626 dovecot/imap-login

├─ 1627 dovecot/anvil

├─ 1628 dovecot/log

├─ 1630 dovecot/pop3-login

├─ 1631 dovecot/imap-login

├─ 1632 dovecot/config

├─ 1643 dovecot/imap

├─ 1652 dovecot/imap

├─ 1760 dovecot/imap

├─ 2639 dovecot/imap

├─ 2640 dovecot/imap

├─ 2646 dovecot/imap

├─ 2648 dovecot/imap

├─ 4490 dovecot/imap

├─ 5211 dovecot/imap

├─ 5212 dovecot/imap

├─ 6078 dovecot/imap

├─ 7071 dovecot/imap

├─ 7595 dovecot/imap

├─ 7623 dovecot/ssl-params

├─ 7852 dovecot/imap

├─ 7855 dovecot/imap

├─ 7992 dovecot/lmtp

├─ 8000 dovecot/auth -w

├─ 8002 dovecot/imap

├─ 8003 dovecot/imap

├─ 8168 dovecot/imap

├─11779 dovecot/imap

├─15338 dovecot/imap

├─20340 dovecot/indexer

├─20341 dovecot/indexer-worker

├─27071 dovecot/auth

├─29532 dovecot/imap

├─29621 dovecot/imap

├─29653 dovecot/imap

├─29659 dovecot/imap

├─31185 dovecot/imap

├─31273 dovecot/imap

├─31433 dovecot/imap

├─31434 dovecot/imap

├─31441 dovecot/imap

├─32013 dovecot/imap

└─32014 dovecot/imap

This output pauses for a few seconds then follows with what looks like the dovecot login/logout log from April until July. There are thousands of lines that are spit out here.

Show/Hide: Output following status...

Jul 02 19:55:45 kirk dovecot[1645]: imap([email protected]): Logged out in=422, out=1426, bytes=422/1426

Jul 02 19:55:54 kirk dovecot[1645]: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=REDACTED, lip=REDACTED, mpid=24725, TLS, sessi...Axwp9SuXHZJ>

Jul 02 19:55:54 kirk dovecot[1645]: imap([email protected]): Logged out in=497, out=1681, bytes=497/1681

Jul 02 19:56:04 kirk dovecot[1645]: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=REDACTED, lip=REDACTED, mpid=24740, TLS, sessi...AxwrNSuXHZJ>

Jul 02 19:56:05 kirk dovecot[1645]: imap([email protected]): Connection closed (COMPRESS finished 20.857 secs ago) in=106, out=536, bytes=106/536

Jul 02 19:56:05 kirk dovecot[1645]: imap([email protected]): Connection closed (No commands sent) in=0, out=424, bytes=0/424

Jul 02 19:56:11 kirk dovecot[1645]: lmtp(24763): Connect from local

Jul 02 19:56:11 kirk dovecot[1645]: lmtp([email protected]): XAPS NOTIFY {"dovecot-username":"[email protected]","dovecot-mailbox":"INBOX"}

Jul 02 19:56:11 kirk dovecot[1645]: lmtp([email protected]): msgid=<[email protected]om>: saved mail to INBOX

Does anyone have any idea why all the log output? Or for that matter why the process is running so often?

Thanks,
Michael

 

[cPanelLauren]

Hi @msullivan

Dovecot is responsible for POP and IMAP connections. If you have users connecting to check their mail, the more user's you have the more dovecot related processes you'll see. What I do find odd is that you're seeing output from Apr-Jul when it's Aug. If you restart the service does this behavior continue?

/scripts/restartsrv_dovecot --stop
/scripts/restartsrv_dovecot --start

 

[msullivan]

Hi @msullivan

Dovecot is responsible for POP and IMAP connections. If you have users connecting to check their mail, the more user's you have the more dovecot related processes you'll see. What I do find odd is that you're seeing output from Apr-Jul when it's Aug. If you restart the service does this behavior continue?

/scripts/restartsrv_dovecot --stop
/scripts/restartsrv_dovecot --start

Thanks for the reply. I get what Dovecot is doing on the server.

I’ve never seen this behaviour before over the past 9 years of administering several VPS.

When I tried to restart Dovecot with the commands you suggested, the service took about a minute and a half to stop, and currently running the “start” script and it’s spewing out the logs from April again, similar to as I noted in my first post. Also just got an email from the system telling me that POP is down.

Not sure what’s up with the super old logs either. Is there any way to flush them?

Thanks,
Michael

 

[cPanelLauren]

Hi @msullivan

I'm not sure either without actually seeing what's going on. Can you please open a ticket using the link in my signature? Once open please reply with the Ticket ID here so that we can update this thread with the resolution once the ticket is resolved.


Thanks!

 

[msullivan]

Hi @cPanelLauren! I've opened a ticket.

Ticket ID is: 10171883

Thanks,
Michael

 

[cPanelLauren]

Hi @msullivan

I just took a look at your ticket and it looks like the analyst believes these older logs are a result of a customization made. You noted you were going to check with your provider, please let us know what becomes of that.

Thanks!

 

[tui]

Did you resolved your problem? im having exactly the same problem

 

[msullivan]

@tui, No direct solution from my provider either. They suggested I use lsof -p to watch the process and see if I could find out what was going on. I also used journalctl --vaccum=500M to reduce the log from gigabytes to 500 megabytes. This reduced the length the process was running, in the end, after having done that I haven't noticed the process running as hard on the system like I was when I asked my initial question.

Somewhere along the line (maybe a CentOS update) I've noticed that when I run systemctl status dovecot.service, the output prints nearly immediately instead of running through thousands of lines of log output.

Currently running:
centos-release-7-5.1804.4.el7.centos.x86_64 & cPanel 74.0.8

Hope this helps in some way!

Michael