Re: [EXT] Re: Dovecot imap-hibernate errors in 2.3.21
Can you send `doveconf -n`? I think it might be related to the separete user accounts somehow. Aki > On 18/01/2024 09:45 EET Lucas Rolff wrote: > > > SELinux runs in permissive mode on the system (so doesn't take action, and no > violations are logged either), the OS specifically is Oracle Linux 8.9, the > only main thing that differs from RHEL or eg rocky/almalinux is I use the > newer oracle kernel they release, but shouldn't have any effect > > > The only "special" thing being that mail users are isolated on their own > Linux user (a domain will result in a local Linux user being created), but > that's about it. > There's nothing with eg virtualized file systems or anything like that, that > would result in per user mount points as well > > > Sent from Outlook for iOS (https://aka.ms/o0ukef) > -- > From: Aki Tuomi > Sent: Thursday, January 18, 2024 8:37:07 AM > To: Lucas Rolff ; dovecot@dovecot.org > > Subject: Re: Dovecot imap-hibernate errors in 2.3.21 > 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 lu...@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=, method=PLAIN, rip=193.36.xx.xx, > lip=176.9.151.xxx, mpid=3631534, TLS, session= > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Loading modules > from directory: /usr/lib64/dovecot > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib10_quota_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib11_imap_quota_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_fts_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_quota_clone_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_zlib_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib21_fts_solr_plugin.so > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Added userdb > setting: mail=mdbox:~/mail/example.com/customer/ > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Added userdb > setting: plugin/quota_rule=*:bytes=10240M > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Effective > uid=1098, gid=1098, home=/home/username/ > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota root: > name=User quota backend=count args= > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota rule: > root=User quota mailbox=* bytes=10737418240 messages=0 > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota grace: > root=User quota bytes=1073741824 (10%) > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: dict(proxy): > dict created (uri=proxy::sqlquota, base_dir=/run/dovecot) > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: > open(/proc/self/io) failed: Permission denied > > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Debug: fs: > root=/home/username//mail/example.com/customer, index=, indexpvt=, con
Re: Dovecot imap-hibernate errors in 2.3.21
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 lu...@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=, method=PLAIN, rip=193.36.xx.xx, > lip=176.9.151.xxx, mpid=3631534, TLS, session= > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Loading modules > from directory: /usr/lib64/dovecot > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib10_quota_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib11_imap_quota_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_fts_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_quota_clone_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib20_zlib_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Module loaded: > /usr/lib64/dovecot/lib21_fts_solr_plugin.so > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Added userdb > setting: mail=mdbox:~/mail/example.com/customer/ > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Added userdb > setting: plugin/quota_rule=*:bytes=10240M > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Effective > uid=1098, gid=1098, home=/home/username/ > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota root: > name=User quota backend=count args= > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota rule: > root=User quota mailbox=* bytes=10737418240 messages=0 > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Quota grace: > root=User quota bytes=1073741824 (10%) > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: dict(proxy): > dict created (uri=proxy::sqlquota, base_dir=/run/dovecot) > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: > open(/proc/self/io) failed: Permission denied > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Debug: fs: > root=/home/username//mail/example.com/customer, index=, indexpvt=, control=, > inbox=, alt= > Jan 17 20:42:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: quota: > quota_over_flag check: quota_over_script unset - skipping > Jan 17 20:42:17 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: Debug: Mailbox INBOX: > Mailbox opened > Jan 17 20:42:17 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't > hibernate imap client: /run/dovecot/imap-hibernate disconnected > Jan 17 20:43:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't > hibernate imap client: /run/dovecot/imap-hibernate disconnected > Jan 17 20:44:16 de-mail01 dovecot[3631433]: > imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't > hibernate imap client:
Re: Dovecot imap-hibernate errors in 2.3.21
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=, method=PLAIN, rip=193.36.xx.xx, lip=176.9.151.xxx, mpid=3631534, TLS, session= Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Loading modules from directory: /usr/lib64/dovecot Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib10_quota_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib11_imap_quota_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib20_fts_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib20_quota_clone_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib20_zlib_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Module loaded: /usr/lib64/dovecot/lib21_fts_solr_plugin.so Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Added userdb setting: mail=mdbox:~/mail/example.com/customer/ Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Added userdb setting: plugin/quota_rule=*:bytes=10240M Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Effective uid=1098, gid=1098, home=/home/username/ Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Quota root: name=User quota backend=count args= Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Quota rule: root=User quota mailbox=* bytes=10737418240 messages=0 Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Quota grace: root=User quota bytes=1073741824 (10%) Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: dict(proxy): dict created (uri=proxy::sqlquota, base_dir=/run/dovecot) Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: open(/proc/self/io) failed: Permission denied Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Debug: fs: root=/home/username//mail/example.com/customer, index=, indexpvt=, control=, inbox=, alt= Jan 17 20:42:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: Debug: Mailbox INBOX: Mailbox opened Jan 17 20:42:17 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:43:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:44:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error: Couldn't hibernate imap client: /run/dovecot/imap-hibernate disconnected Jan 17 20:45:16 de-mail01 dovecot[3631433]: imap(custo...@example.com)<3631534>: 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(custo...@example.com)<3631534>: Error:
Re: Dovecot imap-hibernate errors in 2.3.21
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 lu...@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=, method=PLAIN, rip=35.243.xxx.xxx, lip=176.9.xxx.xxx, > mpid=3646265, TLS, session= > 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(u...@example.com)<3646265>: 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: 48551407Links: 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! > ___ > dovecot mailing list -- dovecot@dovecot.org > To unsubscribe send an email to dovecot-le...@dovecot.org ___ dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-le...@dovecot.org
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=, method=PLAIN, rip=35.243.xxx.xxx, lip=176.9.xxx.xxx, mpid=3646265, TLS, session= 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(u...@example.com)<3646265>: 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: 48551407Links: 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! ___ dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-le...@dovecot.org