Excessive Resource usage for IMAP Hibernate since upgrade to 86.0.4

[martin MHC]

Immediately since updating to 86.0.4 on the release tier, I am now getting a constant trickle of notifications:

Time:         Wed Feb 19 17:16:31 2020 +0000
Account:      dovecot
Resource:     Process Time
Exceeded:     2054 > 2000 (seconds)
Executable:   /usr/libexec/dovecot/imap-hibernate
Command Line: dovecot/imap-hibernate
PID:          22239 (Parent PID:21994)
Killed:       No

Nothing else at all has changed on the server in any way. I have as far as I remember never seen this excessive resource notification until now.

Can this be explained why this is occuring (I realise the obvious literal reason; excessive resource usage, but why since the upgrade?

And, what can/should be done to avoid excessive resource hogging by this/these process(es).

Cheers

P.S> Parent process is:

21994

root

0

0.01

0.01

/usr/sbin/dovecot -F -c /etc/dovecot/dovecot.conf

 

[quietFinn]

Add this line:

exe:/usr/libexec/dovecot/imap-hibernate

to file /etc/csf/csf.pignore
and restart CSF/LFD

csf -ra

 

[martin MHC]

No, this simply ignores the issue; I don't want to ignore the issue but I want to understand why it is occurring since the update and solve it at source.

Ignoring issues is not a good approach to server management.

 

[avinash.pudota]

i'm not sure, but it might be something related to this new feature

86 Release Notes | cPanel & WHM Documentation

Release notes for cPanel & WHM version 86.

docs.cpanel.net

New Mailserver Configuration setting for the IMAP hibernation process delay
We’ve added a new Idle Hibernate Timeout (Seconds) setting to WHM’s Mailserver Configuration interface (WHM >> Home >> Service Configuration >> Mailserver Configuration). This setting allows you to configure the delay (in seconds) before the system moves users to the IMAP hibernate process. This will help save system memory. This value defaults to 5.

 

[martin MHC]

Thanks avinash.pudota - I had looked at that page but missed that vital entry! That solves the "why" part; but my setting is at 15 seconds; so the hibernate process should not be rolling on to 2000+ seconds!

 

[cPanelLauren]

Yep - the hibernate is a new thing, thanks @avinash.pudota

my setting is at 15 seconds; so the hibernate process should not be rolling on to 2000+ seconds!

It won't kill the process as far as I am aware unless you set that directive - PT_USERKILL

# This User Process Tracking option sends an alert if any cPanel user process
# exceeds the time usage set (seconds). To ignore specific processes or users
# use csf.pignore
#
# Set to 0 to disable this feature
PT_USERTIME = "1800"

# If this option is set then processes detected by PT_USERMEM, PT_USERTIME or
# PT_USERPROC are killed
#
# Warning: We don't recommend enabling this option unless absolutely necessary
# as it can cause unexpected problems when processes are suddenly terminated.
# It can also lead to system processes being terminated which could cause
# stability issues. It is much better to leave this option disabled and to
# investigate each case as it is reported when the triggers above are breached
#
# Note: Processes that are running deleted excecutables (see PT_DELETED) will
# not be killed by lfd
PT_USERKILL = "0"

But I would think that 20 seconds would be **REALLY** restrictive.

 

[Matt.R]

To add to the conversation we're getting the same notifications as well since the 86.0.4 release.

 

[nellybongo]

yes Ive also started getting this email sent, every hour or so

Thanks avinash.pudota - I had looked at that page but missed that vital entry! That solves the "why" part; but my setting is at 15 seconds; so the hibernate process should not be rolling on to 2000+ seconds!

 

[cPanelLauren]

To clarify as there should be no confusion as to why you're receiving this while using CSF:

• The email is from CSF's Process Time tracking which tracks the length of time a process runs. When the process exceeds a runtime of the threshold set an email is sent.
• In v86 as is clearly stated above we added the following setting to WHM>>Service Configuration>>Mailserver Configuration -> Idle Hibernate Timeout
  

  The number of seconds to delay before moving users to the IMAP hibernate process. This will help save system memory. A value of “0” disables this option.

• Your valid choices here are:
  • Modify your threshold for PT_USERTIME notices in CSF though this process can run for a long period of time
  • Set this process to be ignored with the instructions provided here: Tutorial - CSF/LFD - Excessive Resource Usage - Process Time

@martin MHC I just re-read your response and I believe there is some confusion:

• IMAP Hibernate is the following: Hibernation — Dovecot documentation
• The setting we added is a timeout for the length of time we will wait *BEFORE* moving a user to IMAP Hibernate - not a timeout for the hibernation process.
• Setting this to 20 seconds means that the user will be moved to IMAP Hibernate after 20 seconds of being idle.

I mistakenly thought you were referring to 20 seconds for PT_USERTIME

 

[martin MHC]

Hi Lauren, thank you for your clarifications --

Is it correct that the /usr/libexec/dovecot/imap-hibernate process will never cease while the system is running? It's currently running on 48,000 seconds for me. This Dovecot process has never run for this length of time (as noticed by CSF) prior to the update to WHM 86.0.4. If this is expected behaviour then I can add it to the ignore list, but I'm curious about a process that never ends !



Cheers

 

[cPanelLauren]

Hi Lauren, thank you for your clarifications --

Is it correct that the /usr/libexec/dovecot/imap-hibernate process will never cease while the system is running? It's currently running on 48,000 seconds for me. This Dovecot process has never run for this length of time (as noticed by CSF) prior to the update to WHM 86.0.4. If this is expected behaviour then I can add it to the ignore list, but I'm curious about a process that never ends !



Cheers

It is expected behavior if you have idle IMAP users that maintain their connection. I can tell you though that I have several accounts with mail clients connected all using IMAP and I'm not seeing this process live for this long.

[root@server ~]# ps faux |grep -i ima[p]
dovenull 34972  0.0  0.0  48928  3636 ?        S    Feb18   0:26  \_ dovecot/imap-login
dovenull 34977  0.0  0.0  48772  3420 ?        S    Feb18   0:25  \_ dovecot/imap-login
skellyf+ 29720  0.0  0.1  88736  4912 ?        S    09:20   0:00  \_ dovecot/imap
skellyf+ 26433  0.0  0.1  89036  4996 ?        S    14:34   0:00  \_ dovecot/imap
skellyf+ 26434  0.0  0.1  89044  5112 ?        S    14:34   0:00  \_ dovecot/imap

In most cases, it can be dismissed but in yours where the process has been running an exceedingly long amount of time, I'd just be curious to see the process. I don't think it's a concern but it might just be good form to be aware of what is occurring. What's the output of the command I show above when run on your server?

 

[Duke C]

Hi there,

Since the update we've also encountered a long-running instance of the dovecot/imap-hibernate process:

Time: Mon Feb 24 08:41:20 2020 +1000
Account: dovecot
Resource: Process Time
Exceeded: 21658 > 14400 (seconds)
Executable: /usr/libexec/dovecot/imap-hibernate
Command Line: dovecot/imap-hibernate
PID: 1841359 (Parent PID:1839931)
Killed: No

Upon inspection of this process I noticed there were several unique users and domains mentioned:

root@server: ~# strace -ff -p 1841359 2>&1|grep '@'
write(13, "[email protected]\tsession"..., 1000) = 1000
read(13, "[email protected]\t%s(%u)<%"..., 8164) = 1104
write(13, "[email protected]\tsession=NdQ650C"..., 942) = 942
read(13, "[email protected]\t%s(%u)<%{pid}><"..., 8164) = 1064
write(13, "[email protected]\tsession=WhQ75"..., 939) = 939
write(13, "[email protected]"..., 1036) = 1036
write(13, "[email protected]\tsession="..., 977) = 977
write(13, "[email protected]\tsession=YRLt"..., 962) = 962
write(13, "[email protected]\tsession="..., 1000) = 1000
read(13, "[email protected]\t%s(%u)<"..., 8164) = 1127
write(13, "[email protected]\tsession=kJ0650C"..., 939) = 939
read(13, "[email protected]\t%s(%u)<%{pid}><"..., 8164) = 1067
read(13, "[email protected]\t%s(%u)<%{pid}"..., 8164) = 1064
read(13, "[email protected]\t%s(%u)<%{pi"..., 8164) = 1096
write(13, "[email protected]\tsession=ZfS"..., 955) = 955
read(13, "[email protected]\t%s(%u)<%"..., 8164) = 1105
read(13, "[email protected]\t%s(%u)<%{pid"..., 8164) = 1089
write(13, "[email protected]\tsession"..., 985) = 985
read(13, "[email protected]\t%s(%u)<%"..., 8164) = 1127
write(13, "[email protected]\tsession=NdQ650C"..., 942) = 942
read(13, "[email protected]\t%s(%u)<%{pid}><"..., 8164) = 1064
write(13, "[email protected]\tsession=WhQ75"..., 939) = 939
write(13, "[email protected]\tsession="..., 977) = 977
write(13, "[email protected]\tsession=lFqB"..., 961) = 961

From Dovecot's documentation:

When client issues IDLE, the connection socket is moved to the hibernation process. This process is responsible for keeping all connections that are idling, until they issue some command that requires them to be thawed into a imap process. This way, memory and CPU resources are saved, since there is only one hibernation process.

Since I started typing this reply, the above process has actually finished and a new one has been spawned. Unsurprisingly, the new process shows activity from a similar list of clients with idle IMAP connections. At a glance, this seems to match the IDLE activity shown in /var/log/maillog, e.g:

Feb 24 08:43:31 server dovecot: imap([email protected])<2078244><kUmw+0WfhMySWBfC>: Connection closed (IDLE finished 3.493 secs ago) in=91, out=1327, bytes=91/1327
Feb 24 09:02:37 server dovecot: imap([email protected])<2078267><tWjn+0WfksySWBfC>: Connection closed (IDLE finished 931.455 secs ago) in=119, out=1626, bytes=119/1626
Feb 24 09:29:20 server dovecot: imap([email protected])<2101643><hIWAekaf4t1nG+Kl>: Connection closed (IDLE finished 625.201 secs ago) in=91, out=1333, bytes=91/1333
Feb 24 09:43:09 server dovecot: imap([email protected])<2100682><3ubqc0afotWSWBfC>: Connection closed (IDLE finished 893.559 secs ago) in=105, out=1417, bytes=105/1417
Feb 24 10:53:22 server dovecot: imap([email protected])<2167713><Sj7lykef07EBhGp2>: Connection closed (IDLE finished 20.309 secs ago) in=91, out=1338, bytes=91/1338
Feb 24 10:56:30 server dovecot: imap([email protected])<2169963><wfqB1kefDhYBj5ja>: Connection closed (IDLE finished 16.546 secs ago) in=91, out=1338, bytes=91/1338

This leads me to believe that in our case (and for those with similar patterns of IMAP activity) the long-running nature of this process is likely normal and is to be expected; the process will hang around for as long as it's needed by at least one idle connection.

 

[martin MHC]

Hello @cPanelLauren

What's the output of the command I show above when run on your server?

This outputs:

dovenull 32598  0.0  0.0  54408 11276 ?        S    Feb23   0:03  \_ dovecot/imap-login
dovenull 32602  0.0  0.1  61540 17888 ?        S    Feb23   0:19  \_ dovecot/imap-login
dovenull 32603  0.0  0.1  56188 12748 ?        S    Feb23   0:05  \_ dovecot/imap-login
dovecot  32677  0.0  0.0  10164  1452 ?        S    Feb23   0:01  \_ dovecot/imap-hibernate
(( ... And a set of dovecot/imap connections from client users similar to your example... ))

And with stacktrace process live logging (from WHM) for PID 32677 giving me (heavily abridged!):

epoll_wait(10, [{EPOLLIN, {u32=1322965120, u64=94318804785280}}], 23, 56513) = 1
read(16, "DONE\r\n", 141)               = 6
socket(AF_LOCAL, SOCK_STREAM, 0)        = 13
fcntl(13, F_GETFL)                      = 0x2 (flags O_RDWR)
fcntl(13, F_SETFL, O_RDWR|O_NONBLOCK)   = 0
connect(13, {sa_family=AF_LOCAL, sun_path="/var/run/dovecot/imap-master"}, 110) = 0
getpeername(13, {sa_family=AF_LOCAL, sun_path="/var/run/dovecot/imap-mast\r"}, [31]) = 0
fstat(13, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fcntl(13, F_GETFL)                      = 0x802 (flags O_RDWR|O_NONBLOCK)
epoll_ctl(10, EPOLL_CTL_ADD, 13, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=1323007776, u64=94318804827936}}) = 0
write(13, "VERSION\timap-master\t1\t0\n", 24) = 24
epoll_ctl(10, EPOLL_CTL_DEL, 16, 0x7ffd13b8aba0) = 0
epoll_ctl(10, EPOLL_CTL_DEL, 17, 0x7ffd13b8aba0) = 0
close(17)                               = 0
epoll_wait(10, [{EPOLLIN, {u32=1323007776, u64=94318804827936}}], 23, 30000) = 1
read(13, "VERSION\timap-master\t1\t0\n", 8192) = 24
sendmsg(13, {msg_name(0)=NULL, msg_iov(1)=[{"i", 1}], msg_controllen=20, [{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, [16]}], msg_flags=0}, 0) = 1
setsockopt(13, SOL_TCP, TCP_CORK, [1], 4) = -1 EOPNOTSUPP (Operation not supported)
write(13, "[email protected]"..., 1047) = 1047
setsockopt(13, SOL_TCP, TCP_NODELAY, [1], 4) = -1 EOPNOTSUPP (Operation not supported)
epoll_wait(10, [{EPOLLIN, {u32=1323007776, u64=94318804827936}}], 23, 29997) = 1
read(13, "+\n", 8168)                   = 2
write(3, "DISCONNECT\t32677\timap/52.125.141"..., 73) = 73
close(16)                               = 0

 

[cPanelLauren]

Well, this gives you the email address:

write(13, "[email protected]"..., 1047) = 1047

I assume from the stack trace that's the account that's idling. Ultimately I'd be curious what mail client that account is using and search through the logs a bit to see if I could find any issues/errrors with it. It may just be that they've got it configured to do this. I don't think it's an issue at all, I was just curious, what client is staying connected like that. After a certain time being idle most mail clients end the connection with the server, then poll again during set intervals. This looks like it maintains a persistent connection.

 

[martin MHC]

Thank you @cPanelLauren I will explore what they're upto and what the logs say. Cheers.

 

[nellybongo]

So from following all the posts, its ok to switch the warning off in CSF? I am still getting the warnings also.

 

[cPanelLauren]

So from following all the posts, its ok to switch the warning off in CSF? I am still getting the warnings also.

It'd be ok to ignore it, yes.

I also wanted to update here that I've opened a request with ConfigServer to see if they can autowhitelist/ignore this process on cPanel servers moving forward (or some other method). I'll update here with more information when available.

 

[sadasan]

Hello,

I have also encountered the same issue.

To stop this troublesome notification, I knew that there were two ways,

Disabling "Idle Hibernate Timeout (Seconds)" to 0 at WHM.

Adding "exe:/usr/libexec/dovecot/imap-hibernate" to "/etc/csf/csf.pignore".

Which one is better?
Is either or both configurations ok?

 

[quietFinn]

...
Disabling "Idle Hibernate Timeout (Seconds)" to 0 at WHM.

Adding "exe:/usr/libexec/dovecot/imap-hibernate" to "/etc/csf/csf.pignore".

Which one is better?
Is either or both configurations ok?

Depends on what you mean by "ok".
If you do the 1st you don't need to do the second.

Moving users to the IMAP hibernate process will, as they say in the documentation, help save system memory.
If that is true then I would definitely suggest doing the second one, i.e. just ignoring it.

 

[sadasan]

Hello quietFinn,

Thank you, I see, I will try the second one
Also I will check this thread for a while to check how counter measure other members take.
Next update may fix this problem..