Dovecot imap-hibernate errors in 2.3.21
Hello,
I recently upgraded a Dovecot install from 2.3.20 to 2.3.21 from the 2.3-latest repository ( http://repo.dovecot.org/ce-2.3-latest/rhel/$releasever/RPMS/$basearch )
However since then, I seem to be getting: Jan 13 01:08:32 mail01 dovecot[3646235]: imap-login: Login: user=<user@example.com>, method=PLAIN, rip=35.243.xxx.xxx, lip=176.9.xxx.xxx, mpid=3646265, TLS, session=<o9jJlMgOFzMj86dT> Jan 13 01:09:03 mail01 dovecot[3646235]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3646265,uid=1010): IMAP client fd not received Jan 13 01:09:03 mail01 dovecot[3646235]: imap(user@example.com)<3646265><o9jJlMgOFzMj86dT>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
This seems to be the case for every email-account on the system.
Related configs:
20-imap.conf: protocol imap { imap_hibernate_timeout = 30s
imap_idle_notify_interval = 24 mins
mail_plugins = $mail_plugins imap_quota quota_clone zlib fts fts_solr
mail_max_userip_connections = 20 }
10-master.conf: service imap { # Most of the memory goes to mmap()ing files. You may need to increase this # limit if you have huge mailboxes. #vsz_limit = $default_vsz_limit
unix_listener imap-master { user = $default_internal_user } extra_groups = $default_internal_group }
service imap-hibernate { unix_listener imap-hibernate { mode = 0660 group = $default_internal_group } }
10-metrics.conf event_exporter log { format = json format_args = time-rfc3339 transport = log }
metric hibernation_logging { exporter = log filter = event=imap_client_hibernated OR event=imap_client_unhibernated }
socket:
$ stat /run/dovecot/imap-hibernate File: /run/dovecot/imap-hibernate Size: 0 Blocks: 0 IO Block: 4096 socket Device: 19h/25d Inode: 48551407 Links: 1 Access: (0660/srw-rw----) Uid: ( 0/ root) Gid: ( 97/ dovecot) Context: system_u:object_r:dovecot_var_run_t:s0 Access: 2024-01-13 01:03:07.432084831 +0100 Modify: 2024-01-13 00:50:56.394662577 +0100 Change: 2024-01-13 00:50:56.394662577 +0100 Birth: -
From the change log, I see the following:
- imap-hibernate: If an IMAP client unhibernation timed out with
"(version received)", the unhibernation could still have successfully
finished later on and continued working normally. This was rather
confusing, because imap-hibernate already logged that the client got
disconnected. Avoid this by forcing the connection to shutdown on
unhibernation timeout.By the looks of it, it seems hibernation never actually happens anymore as of the new version. Downgrading to version 2.3.20 again seems to make hibernation function again based on the event logs.
In 2.3.21 I only see events being logged for imap_client_hibernated which matches the /run/dovecot/imap-hibernate disconnected:
"error":"/run/dovecot/imap-hibernate disconnected"
In 2.3.20 I get both imap_client_hibernated and imap_client_unhibernated events (that it happens and when idle_done is triggered).
Thank you in advance!
Jan 13 01:09:03 mail01 dovecot[3646235]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3646265,uid=1010): IMAP client fd not received
This is bit weird. Can you try enabling mail_debug=yes and trying once more on test system?
Aki
On 17/01/2024 21:06 EET lucas@lucasrolff.com wrote:
Hello,
I recently upgraded a Dovecot install from 2.3.20 to 2.3.21 from the 2.3-latest repository ( http://repo.dovecot.org/ce-2.3-latest/rhel/$releasever/RPMS/$basearch )
However since then, I seem to be getting: Jan 13 01:08:32 mail01 dovecot[3646235]: imap-login: Login: user=<user@example.com>, method=PLAIN, rip=35.243.xxx.xxx, lip=176.9.xxx.xxx, mpid=3646265, TLS, session=<o9jJlMgOFzMj86dT> Jan 13 01:09:03 mail01 dovecot[3646235]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3646265,uid=1010): IMAP client fd not received Jan 13 01:09:03 mail01 dovecot[3646235]: imap(user@example.com)<3646265><o9jJlMgOFzMj86dT>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
This seems to be the case for every email-account on the system.
Related configs:
20-imap.conf: protocol imap { imap_hibernate_timeout = 30s
imap_idle_notify_interval = 24 mins
mail_plugins = $mail_plugins imap_quota quota_clone zlib fts fts_solr
mail_max_userip_connections = 20 }
10-master.conf: service imap { # Most of the memory goes to mmap()ing files. You may need to increase this # limit if you have huge mailboxes. #vsz_limit = $default_vsz_limit
unix_listener imap-master { user = $default_internal_user } extra_groups = $default_internal_group }
service imap-hibernate { unix_listener imap-hibernate { mode = 0660 group = $default_internal_group } }
10-metrics.conf event_exporter log { format = json format_args = time-rfc3339 transport = log }
metric hibernation_logging { exporter = log filter = event=imap_client_hibernated OR event=imap_client_unhibernated }
socket:
$ stat /run/dovecot/imap-hibernate File: /run/dovecot/imap-hibernate Size: 0 Blocks: 0 IO Block: 4096 socket Device: 19h/25d Inode: 48551407 Links: 1 Access: (0660/srw-rw----) Uid: ( 0/ root) Gid: ( 97/ dovecot) Context: system_u:object_r:dovecot_var_run_t:s0 Access: 2024-01-13 01:03:07.432084831 +0100 Modify: 2024-01-13 00:50:56.394662577 +0100 Change: 2024-01-13 00:50:56.394662577 +0100 Birth: -
From the change log, I see the following:
- imap-hibernate: If an IMAP client unhibernation timed out with "(version received)", the unhibernation could still have successfully finished later on and continued working normally. This was rather confusing, because imap-hibernate already logged that the client got disconnected. Avoid this by forcing the connection to shutdown on unhibernation timeout.
By the looks of it, it seems hibernation never actually happens anymore as of the new version. Downgrading to version 2.3.20 again seems to make hibernation function again based on the event logs.
In 2.3.21 I only see events being logged for
imap_client_hibernatedwhich matches the /run/dovecot/imap-hibernate disconnected: "error":"/run/dovecot/imap-hibernate disconnected"In 2.3.20 I get both imap_client_hibernated and imap_client_unhibernated events (that it happens and when idle_done is triggered).
Thank you in advance!
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
Thanks for your reply Aki!
It doesn't seem to contain much more information sadly that points towards anything related to hibernate itself. "Debug: open(/proc/self/io) failed: Permission denied" being the main "thing" that seems a bit odd, but that also happens under 2.3.20 as well by the looks of it:
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap-login: Login: user=<customer@example.com>, method=PLAIN, rip=193.36.xx.xx, lip=176.9.151.xxx, mpid=3631534, TLS, session=<JVYMV8gOq5vBJIOe>
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Loading modules from directory: /usr/lib64/dovecot
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_fts_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_quota_clone_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_zlib_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib21_fts_solr_plugin.so
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Added userdb setting: mail=mdbox:~/mail/example.com/customer/
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10240M
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Effective uid=1098, gid=1098, home=/home/username/
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota root: name=User quota backend=count args=
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota grace: root=User quota bytes=1073741824 (10%)
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: dict(proxy): dict created (uri=proxy::sqlquota, base_dir=/run/dovecot)
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: open(/proc/self/io) failed: Permission denied
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mail/example.com/customer/
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: fs: root=/home/username//mail/example.com/customer, index=, indexpvt=, control=, inbox=, alt=
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping
Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:42:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received
Jan 17 20:42:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
Jan 17 20:43:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:43:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received
Jan 17 20:43:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
Jan 17 20:44:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:44:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received
Jan 17 20:44:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
Jan 17 20:45:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:45:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received
Jan 17 20:45:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
Jan 17 20:46:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened
Jan 17 20:46:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received
Jan 17 20:46:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected
Best Regards, Lucas Rolff
Did you check if maybe selinux is interfering here? I tested the 2.3.21-CE in a RHEL7 VM and hibernation seems to work there.
Aki
On 17/01/2024 22:51 EET lucas@lucasrolff.com wrote:
Thanks for your reply Aki!
It doesn't seem to contain much more information sadly that points towards anything related to hibernate itself. "Debug: open(/proc/self/io) failed: Permission denied" being the main "thing" that seems a bit odd, but that also happens under 2.3.20 as well by the looks of it:
Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap-login: Login: user=<customer@example.com>, method=PLAIN, rip=193.36.xx.xx, lip=176.9.151.xxx, mpid=3631534, TLS, session=<JVYMV8gOq5vBJIOe> Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Loading modules from directory: /usr/lib64/dovecot Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_fts_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_quota_clone_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib20_zlib_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Module loaded: /usr/lib64/dovecot/lib21_fts_solr_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Added userdb setting: mail=mdbox:~/mail/example.com/customer/ Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10240M Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Effective uid=1098, gid=1098, home=/home/username/ Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota root: name=User quota backend=count args= Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: dict(proxy): dict created (uri=proxy::sqlquota, base_dir=/run/dovecot) Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: open(/proc/self/io) failed: Permission denied Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=mdbox:~/mail/example.com/customer/ Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: fs: root=/home/username//mail/example.com/customer, index=, indexpvt=, control=, inbox=, alt= Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:42:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received Jan 17 20:42:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:43:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:43:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received Jan 17 20:43:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:44:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:44:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received Jan 17 20:44:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:45:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:45:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received Jan 17 20:45:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:46:16 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:46:49 de-mail01 dovecot[3631433]: imap-hibernate: Error: conn unix:imap-hibernate (pid=3631534,uid=1098): IMAP client fd not received Jan 17 20:46:49 de-mail01 dovecot[3631433]: imap(customer@example.com)<3631534><JVYMV8gOq5vBJIOe>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnectedBest Regards, Lucas Rolff
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
participants (2)
-
Aki Tuomi
-
lucas＠lucasrolff.com