thr3ads.net - dovecot - [Dovecot] stats + fts squat plugins, indexer-worker error on message indexing [Apr 2012]

If this information is useful, please help other people find it:
Share via:

David Warden

2012-Apr-25 14:20 UTC

[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 at 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 at 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
}

Timo Sirainen

2012-Apr-25 14:43 UTC

head link

[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing

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?

-------------- next part --------------
A non-text attachment was scrubbed...
Name: diff
Type: application/octet-stream
Size: 2639 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20120425/63f4f2f1/attachment-0004.obj>
-------------- next part --------------
> The strange thing is it looks like the stats are still collected (unless I
am reading the output of the stats dump incorrectly):
> 
> [root at 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.

David Warden

2012-Apr-25 18:30 UTC

head link

[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing

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 at 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.

Possibly Parallel Threads

Search for more maybe matching threads

dovecot - Apr 2012 - stats + fts squat plugins, indexer-worker error on message indexing

[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing

[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing

[Dovecot] stats + fts squat plugins, indexer-worker error on message indexing

Possibly Parallel Threads