Some imapd processes getting permission denied setting flags

Bron Gondwana brong at fastmail.fm
Thu May 18 10:27:23 EDT 2006


This one is really strange.  I've just recently upgraded
one of our old Redhat 7.3 servers from Cyrus 2.2.something CVS
to Cyrus 2.3.3.

We're getting lots of users unable to mark messages read or
deleted.  Now, our code works by adding the 'selected' flag
to whatever messages it wishes to act upon, then using a search
on that flag to do the action.  Convoluted, but it allows us to
act on messages from multiple "pages" of a web interface.

The symptom - from one server I can log in just fine and do
things.  From another server I get "no messages selected"
from the web interface.  I found the matching processid on
the server as follows (username rewritten to protect the user:

[root at server1 imapproc]$ grep kkkk *
27285:web3.internal [10.202.2.212]      kkkk    user.kkkk
27827:heartbeat2.internal [10.202.2.161]        kkkk    user.kkkk
28773:web1.internal [10.202.2.210]      kkkk    user.kkkk
6342:web2.internal [10.202.2.211]       kkkk    user.kkkk


[root at server1 imapproc]$ strace -p 6342 -s 50000
select(1, [0], NULL, NULL, {3583, 423000}) = 1 (in [0], left {3575, 302000})
time(NULL)                              = 1147961382
time(NULL)                              = 1147961382
select(1, [0], NULL, NULL, {3575, 0})   = 1 (in [0], left {3575, 0})
time(NULL)                              = 1147961382
time(NULL)                              = 1147961382
read(0, "1 noop\r\n", 4096)             = 8
stat64("/var/spool/imap4/k/user/kkkk/cyrus.index", {st_mode=S_IFREG|0600, st_siz
e=1012, ...}) = 0
fstat64(16, {st_mode=S_IFREG|0600, st_size=18860, ...}) = 0
fcntl64(14, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(14, {st_mode=S_IFREG|0600, st_size=15068, ...}) = 0
stat64("/var/imap/user/k/kkkk.seen", {st_mode=S_IFREG|0600, st_size=15068, ...})
 = 0
fcntl64(14, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
write(1, "1 OK Completed\r\n", 16)      = 16
open("/var/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file or directory)
time(NULL)                              = 1147961382
select(1, [0], NULL, NULL, {3600, 0})   = 1 (in [0], left {3599, 997000})
time(NULL)                              = 1147961382
time(NULL)                              = 1147961382
select(1, [0], NULL, NULL, {3600, 0})   = 1 (in [0], left {3600, 0})
time(NULL)                              = 1147961382
time(NULL)                              = 1147961382
read(0, "2 uid store 11735 +flags.silent (selected)\r\n", 4096) = 44
fcntl64(6, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(6, {st_mode=S_IFREG|0600, st_size=76253908, ...}) = 0
stat64("/var/imap/mailboxes.db", {st_mode=S_IFREG|0600, st_size=76253908, ...})
= 0
fcntl64(6, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
stat64("/var/spool/imap4/k/user/kkkk/cyrus.index", {st_mode=S_IFREG|0600, st_siz
e=1012, ...}) = 0
fstat64(16, {st_mode=S_IFREG|0600, st_size=18860, ...}) = 0
write(1, "2 NO Permission denied\r\n", 24) = 24

But then from web3 I get:
[root at server1 imapproc]$ strace -p 27285 -s 50000
select(1, [0], NULL, NULL, {3525, 417000}) = 1 (in [0], left {3467, 635000})
time(NULL)                              = 1147962178
time(NULL)                              = 1147962178
select(1, [0], NULL, NULL, {3468, 0})   = 1 (in [0], left {3468, 0})
time(NULL)                              = 1147962178
time(NULL)                              = 1147962178
read(0, "1 noop\r\n", 4096)             = 8
stat64("/var/spool/imap4/k/user/kkkk/cyrus.index", {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
fstat64(15, {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
fstat64(16, {st_mode=S_IFREG|0600, st_size=19740, ...}) = 0
fcntl64(13, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(13, {st_mode=S_IFREG|0600, st_size=16508, ...}) = 0
stat64("/var/imap/user/k/kkkk.seen", {st_mode=S_IFREG|0600, st_size=16508, ...}) = 0
fcntl64(13, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
write(1, "* 13 FETCH (FLAGS (\\Seen hasnoatt))\r\n1 OK Completed\r\n", 53) = 53
open("/var/imap/msg/shutdown", O_RDONLY) = -1 ENOENT (No such file or directory)
time(NULL)                              = 1147962178
select(1, [0], NULL, NULL, {3600, 0})   = 1 (in [0], left {3599, 994000})
time(NULL)                              = 1147962178
time(NULL)                              = 1147962178
select(1, [0], NULL, NULL, {3600, 0})   = 1 (in [0], left {3600, 0})
time(NULL)                              = 1147962178
time(NULL)                              = 1147962178
read(0, "2 uid store 11735 +flags.silent (selected)\r\n", 4096) = 44
fcntl64(6, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(6, {st_mode=S_IFREG|0600, st_size=76254588, ...}) = 0
stat64("/var/imap/mailboxes.db", {st_mode=S_IFREG|0600, st_size=76254588, ...}) = 0
fcntl64(6, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
time(NULL)                              = 1147962178
fcntl64(15, F_SETLKW, {type=F_WRLCK, whence=SEEK_SET, start=0, len=0}) = 0
fstat64(15, {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
stat64("/var/spool/imap4/k/user/kkkk/cyrus.index", {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
fstat64(15, {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
lseek(15, 940, SEEK_SET)                = 940
write(15, "\0\0-\327DlwODl\232\0\0\0\6\255\0\0\5\340\0\0\5\340\0\0D\230Dl\203B\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\7\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0", 72) = 72
lseek(15, 0, SEEK_SET)                  = 0
write(15, "\254\5\6R\0\0\0\0\0\0\0\7\0\0\0L\0\0\0H\0\0\0\16Dl\200\236\0\0-\330\0\0\0\0\0\1\2516\0\0\0\0=\301\367\300\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0", 76) = 76
fsync(15)                               = 0
getpid()                                = 27285
sendto(7, "\2\0\0\0\225j\0\0user.kkkk\0", 18, 0, {sin_family=AF_UNIX, path="/var/imap/socket/idle"}, 24) = 18
fcntl64(15, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
stat64("/var/spool/imap4/k/user/kkkk/cyrus.index", {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
fstat64(15, {st_mode=S_IFREG|0600, st_size=1084, ...}) = 0
fstat64(16, {st_mode=S_IFREG|0600, st_size=19740, ...}) = 0
write(1, "2 OK Completed\r\n", 16)      = 16

Which worked just fine.  This makes me very confused since
it's the same backend server with the same files!

Can anyone shed any light on what might cause this?  It happened
last time we tried to upgrade to Cyrus-2.3.3 and we backed out
in a hurry because we'd tried to turn on virtual domains at the
same time and thought that must have caused it.  Then we hit changed
ACL letters and fun ensued.  Oops.

This still sucks though, especially for the poor users who
can't delete or mark "read" emails.

Bron.


More information about the Info-cyrus mailing list