[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing
On RHEL 6.2 + dovecot 2.1.5 with the stats and fts (squat) plugins enabled and each user having their own uid on the system I get the following error in the logs when the indexer-worker process indexes some messages:
Apr 25 09:56:19 wardentest3 dovecot: imap-login: Login: user=warden, method=PLAIN, rip=137.238.60.164, lip=137.238.2.240, lport=1993, mpid=19464, encryption=TLS Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Indexed 12 messages in INBOX Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Error: open(/proc/self/io) failed: Permission denied Apr 25 09:56:29 wardentest3 dovecot: service=imap user=warden rip=137.238.60.164 Disconnected: Logged out bytes(in/out)=46/780
What I did to generate the above was remove the squat indexes for my Inbox then log in via telnet and search for a string in my Inbox, which forced an index of the messages in my Inbox.
Based on http://wiki2.dovecot.org/Services#indexer-worker it seems like this is because the indexer-worker process is created as root but at the time of indexing the indexer-worker drops privs to the mail user. In /proc/<indexer-worker pid>/, io is mode 0400 and owned by root, so it makes sense that the mail user would be unable to read that file.
The strange thing is it looks like the stats are still collected (unless I am reading the output of the stats dump incorrectly):
[root@wardentest3 mailtest]# doveadm stats dump -s /var/run/dovecot/mailtest/stats command user=warden cmd args session user last_update user_cpu sys_cpu min_faults maj_faults vol_cs invol_cs disk_input disk_output read_count read_bytes write_count write_bytes mail_lookup_path mail_lookup_attr mail_read_count mail_read_bytes mail_cache_hits select inbox 27fb87218302984f084c0000ae899e04 warden 1335362182.950250 0.000000 0.000000 172 0 46 0 0 12288 13 7883 4 381 0 0 0 0 0 search text "warden" 27fb87218302984f084c0000ae899e04 warden 1335362186.588023 0.001000 0.000000 32 0 4 1 0 0 4 108 1 43 0 0 0 0 0 logout 27fb87218302984f084c0000ae899e04 warden 1335362189.161790 0.000000 0.000000 1 0 0 3 0 0 1 108 3 157 0 0 0 0 0
This obviously isn't a show-stopper but if this is causing stats to be incorrect it would be great if this could be fixed.
-David Warden
My doveconf -n:
# 2.1.5: /etc/dovecot/mailtest/dovecot.conf doveconf: Warning: service auth { client_limit=4096 } is lower than required under max. load (12288) doveconf: Warning: service anvil { client_limit=4096 } is lower than required under max. load (12291) # OS: Linux 2.6.32-220.7.1.el6.x86_64 x86_64 Red Hat Enterprise Linux Server release 6.2 (Santiago) nfs auth_cache_negative_ttl = 0 auth_cache_size = 16 M auth_gssapi_hostname = $ALL auth_krb5_keytab = /etc/dovecot/mailtest.combined.keytab auth_master_user_separator = * auth_mechanisms = plain login gssapi auth_username_format = %Ln base_dir = /var/run/dovecot/mailtest/ default_client_limit = 4096 default_process_limit = 4096 deliver_log_format = msgid="%m" subject="%s" from="%f" size=%p result="%$" first_valid_uid = 0 hostname = mailtest.geneseo.edu instance_name = mailtest lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_log_format_elements = user=%u method=%m rip=%r lip=%l lport=%a mpid=%e encryption=%c mail_fsync = always mail_location = maildir:/Mail/mailhome/%Ln/mailtest/Maildir:CONTROL=/Mail/mailhome/%Ln/mailtest/.dovecot-control:INDEX=/Mail/mailhome/%Ln/mailtest/.dovecot-index mail_log_prefix = "service=%s user=%u rip=%r " mail_nfs_index = yes mail_nfs_storage = yes mail_plugins = zlib quota mail_log notify fts fts_squat stats maildir_very_dirty_syncs = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mbox_write_locks = fcntl mmap_disable = yes namespace default { inbox = yes location = mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { auto = no special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox Trash { auto = subscribe special_use = \Trash } prefix = separator = . type = private } passdb { args = /etc/dovecot/passwd.masterusers driver = passwd-file master = yes } passdb { args = cache_key=%u dovecot driver = pam } plugin { fts = squat mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename flag_change append mail_log_fields = uid box msgid size from subject flags mail_log_group_events = yes quota = maildir:User quota quota_exceeded_message = Quota exceeded (mailbox for user is full). Please see http://go.geneseo.edu/emailoverquota for help deleting messages while over quota. quota_rule = *:storage=200M quota_rule2 = Trash:storage=+50M sieve = /Mail/mailhome/%Ln/mailtest/.filter.sieve sieve_dir = /Mail/mailhome/%Ln/mailtest/.sievedir sieve_max_redirects = 25 stats_memory_limit = 32 M stats_refresh = 30 secs stats_track_cmds = yes } postmaster_address = postmaster@geneseo.edu protocols = imap sieve lmtp quota_full_tempfail = yes service auth { unix_listener auth-exim { group = exim mode = 0660 } } service imap-login { inet_listener imap { port = 1143 } inet_listener imaps { port = 1993 } service_count = 0 vsz_limit = 256 M } service imap { process_limit = 4096 } service lmtp { inet_listener lmtp { port = 124 } } service managesieve-login { inet_listener sieve { port = 14190 } inet_listener sieve_deprecated { port = 12000 } } service pop3 { process_limit = 4096 } service stats { fifo_listener stats-mail { mode = 0666 } } ssl_ca = </etc/pki/tls/certs/geotrust-intermediate.pem ssl_cert = </etc/pki/tls/certs/wildcard-geotrust.geneseo.edu.pem ssl_key = </etc/pki/tls/private/wildcard-geotrust.geneseo.edu.key userdb { driver = passwd } verbose_proctitle = yes protocol lmtp { mail_plugins = zlib quota mail_log notify fts fts_squat stats sieve } protocol lda { mail_location = maildir:/Mail/mailhome/%Ln/mailtest/Maildir:CONTROL=/Mail/mailhome/%Ln/mailtest/.dovecot-control:INDEX=/Mail/mailhome/%Ln/mailtest/.dovecot-index mail_plugins = zlib quota mail_log notify fts fts_squat stats sieve plugin { quota = maildir:User quota quota_rule = *:storage=200M quota_rule2 = Trash:storage=+50M zlib_save = gz zlib_save_level = 6 } } protocol imap { imap_logout_format = bytes(in/out)=%i/%o mail_max_userip_connections = 50 mail_plugins = zlib quota mail_log notify fts fts_squat stats imap_quota autocreate imap_zlib imap_stats } protocol sieve { managesieve_logout_format = bytes(in/out)=%i/%o } protocol pop3 { pop3_client_workarounds = outlook-no-nuls oe-ns-eoh pop3_logout_format = bytes(in/out)=%i/%o, top=%t/%p, retr=%r/%b, del=%d/%m, mailbox-size=%s pop3_uidl_format = UID%u-%v } remote 137.238.0.0/16/16 { disable_plaintext_auth = no }
On 25.4.2012, at 17.20, David Warden wrote:
Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Error: open(/proc/self/io) failed: Permission
..
Based on http://wiki2.dovecot.org/Services#indexer-worker it seems like this is because the indexer-worker process is created as root but at the time of indexing the indexer-worker drops privs to the mail user. In /proc/<indexer-worker pid>/, io is mode 0400 and owned by root, so it makes sense that the mail user would be unable to read that file.
Does the attached patch fix it?
The strange thing is it looks like the stats are still collected (unless I am reading the output of the stats dump incorrectly):
[root@wardentest3 mailtest]# doveadm stats dump -s /var/run/dovecot/mailtest/stats command user=warden cmd args session user last_update user_cpu sys_cpu min_faults maj_faults vol_cs invol_cs disk_input disk_output read_count read_bytes write_count write_bytes mail_lookup_path mail_lookup_attr mail_read_count mail_read_bytes mail_cache_hits select inbox 27fb87218302984f084c0000ae899e04 warden 1335362182.950250 0.000000 0.000000 172 0 46 0 0 12288 13 7883 4 381 0 0 0 0 0 search text "warden" 27fb87218302984f084c0000ae899e04 warden 1335362186.588023 0.001000 0.000000 32 0 4 1 0 0 4 108 1 43 0 0 0 0 0 logout 27fb87218302984f084c0000ae899e04 warden 1335362189.161790 0.000000 0.000000 1 0 0 3 0 0 1 108 3 157 0 0 0 0 0
These are IMAP command statistics. The problem was only with indexer-worker.
On Apr 25, 2012, at 10:43 AM, Timo Sirainen wrote:
On 25.4.2012, at 17.20, David Warden wrote:
Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Error: open(/proc/self/io) failed: Permission
..
Based on http://wiki2.dovecot.org/Services#indexer-worker it seems like this is because the indexer-worker process is created as root but at the time of indexing the indexer-worker drops privs to the mail user. In /proc/<indexer-worker pid>/, io is mode 0400 and owned by root, so it makes sense that the mail user would be unable to read that file.
Does the attached patch fix it?
<diff>
The error is still logged, but is that intentional on your part? It looks like the patch logs the failure to open() when the error returned is anything other than ENOENT and in my case the error is EACCESS. Other than that it looks like it correctly disables accessing that file.
The strange thing is it looks like the stats are still collected (unless I am reading the output of the stats dump incorrectly):
[root@wardentest3 mailtest]# doveadm stats dump -s /var/run/dovecot/mailtest/stats command user=warden cmd args session user last_update user_cpu sys_cpu min_faults maj_faults vol_cs invol_cs disk_input disk_output read_count read_bytes write_count write_bytes mail_lookup_path mail_lookup_attr mail_read_count mail_read_bytes mail_cache_hits select inbox 27fb87218302984f084c0000ae899e04 warden 1335362182.950250 0.000000 0.000000 172 0 46 0 0 12288 13 7883 4 381 0 0 0 0 0 search text "warden" 27fb87218302984f084c0000ae899e04 warden 1335362186.588023 0.001000 0.000000 32 0 4 1 0 0 4 108 1 43 0 0 0 0 0 logout 27fb87218302984f084c0000ae899e04 warden 1335362189.161790 0.000000 0.000000 1 0 0 3 0 0 1 108 3 157 0 0 0 0 0
These are IMAP command statistics. The problem was only with indexer-worker.
On 25.4.2012, at 21.30, David Warden wrote:
Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Error: open(/proc/self/io) failed: Permission
Does the attached patch fix it?
The error is still logged, but is that intentional on your part? It looks like the patch logs the failure to open() when the error returned is anything other than ENOENT and in my case the error is EACCESS. Other than that it looks like it correctly disables accessing that file.
The patch intended to open the /proc/self/io immediately at startup while still running as root.
Anyway, now that I'm testing it again myself, I see that it's supposed to work even without the patch, because /proc/self/io's permissions change after seteuid().
I noticed similar errors happening somewhat randomly in another CentOS 6.2 system. Changing the kernel fixed it. (Downgrading at least worked, possibly upgrading might also.)
Am 25.04.2012 21:09, schrieb Timo Sirainen:
On 25.4.2012, at 21.30, David Warden wrote:
Apr 25 09:56:26 wardentest3 dovecot: service=indexer-worker user=warden rip= Error: open(/proc/self/io) failed: Permission
Does the attached patch fix it?
The error is still logged, but is that intentional on your part? It looks like the patch logs the failure to open() when the error returned is anything other than ENOENT and in my case the error is EACCESS. Other than that it looks like it correctly disables accessing that file.
The patch intended to open the /proc/self/io immediately at startup while still running as root.
Anyway, now that I'm testing it again myself, I see that it's supposed to work even without the patch, because /proc/self/io's permissions change after seteuid().
I noticed similar errors happening somewhat randomly in another CentOS 6.2 system. Changing the kernel fixed it. (Downgrading at least worked, possibly upgrading might also.)
Hi Tim , i have also rare logs like
indexer-worker(user@user.examnple): Error: open(/proc/self/io) failed: Permission denied
but afterwards
indexer-worker(user@user.examnple): Indexed 253 messages in INBOX: 1 Time(s
the users reported no problem so it seems not to be a big problem anyway are there news related to the problem
participants (3)
-
David Warden
-
Robert Schetterer
-
Timo Sirainen