Nikolai Schupbach
2012-Aug-01 08:13 UTC
[Dovecot] Erroneous operation not permitted when deleting mailbox with mdbox
I'm seeing the following error in our logs when removing mailboxes (we are
using mdbox and dovecot 2.1.8):
Aug 1 20:03:36 msgsrv dovecot: imap(test at test.com): Error:
stat(/mailstore/domains/test.com/test/mdbox/mailboxes/Spam) failed: Operation
not permitted
Aug 1 20:03:36 msgsrv dovecot: imap(test at test.com): Mailbox deleted: Spam
When I run truss against the process it appears the error relates to attempted
unlink of a directory, not a stat of it, as reported by the log. However the
mailbox does appear to be deleted fine, so it appears to be an erroneous error.
Here is the truss output from the "3 DELETE INBOX.Spam" IMAP command:
gettimeofday({1343808204.962165 },0x0) = 0 (0x0)
gettimeofday({1343808204.962351 },0x0) = 0 (0x0)
kevent(9,0x0,0,{0xb,EVFILT_READ,0x0,0,0x15,0x21c17a40},6,{1786.679649000 }) = 1
(0x1)
gettimeofday({1343808216.031493 },0x0) = 0 (0x0)
gettimeofday({1343808216.031676 },0x0) = 0 (0x0)
read(11,"3 DELETE INBOX.Spam\r\n",8179) = 21 (0x15)
getpid() = 6293 (0x1895)
__sysctl(0x7fffffffd850,0x4,0x0,0x0,0x21c8f000,0x2a) = 0 (0x0)
clock_gettime(13,{1343808216.000000000 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails",{
mode=drwx------ ,inode=28761,size=3,blksize=131072 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails",{
mode=drwx------ ,inode=28761,size=3,blksize=131072 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam",{
mode=drwx------ ,inode=28760,size=3,blksize=131072 }) = 0 (0x0)
open("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",O_RDWR,037777753160)
= 10 (0xa)
fstat(10,{ mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
pread(0xa,0x21c30000,0x90,0x0,0x1000,0x0) = 144 (0x90)
open("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index",O_RDWR,037777731760)
ERR#2 'No such file or directory'
open("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log.2",O_RDWR,037777731520)
ERR#2 'No such file or directory'
fstat(10,{ mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
unlink("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam") ERR#1
'Operation not permitted'
stat("/usr/share/nls/C/libc.cat",0x7fffffffd0a0) ERR#2 'No such
file or directory'
stat("/usr/share/nls/libc/C",0x7fffffffd0a0) ERR#2 'No such file
or directory'
stat("/usr/local/share/nls/C/libc.cat",0x7fffffffd0a0) ERR#2 'No
such file or directory'
stat("/usr/local/share/nls/libc/C",0x7fffffffd0a0) ERR#2 'No such
file or directory'
write(2,"\^A\b6293 prefix=imap(test at test."...,36) = 36 (0x24)
write(2,"\^A\^D6293 stat(/mailstore/domai"...,99) = 99 (0x63)
access("/etc/localtime",4) = 0 (0x0)
open("/etc/localtime",O_RDONLY,04160026530) = 12 (0xc)
fstat(12,{ mode=-r--r--r-- ,inode=16454,size=2434,blksize=4096 }) = 0 (0x0)
read(12,"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,41448) = 2434 (0x982)
close(12) = 0 (0x0)
issetugid(0x20ee7fd1,0x21e72000,0x0,0xa7,0x4e,0xc) = 1 (0x1)
open("/usr/share/zoneinfo/posixrules",O_RDONLY,056) = 12 (0xc)
fstat(12,{ mode=-r--r--r-- ,inode=545,size=3519,blksize=4096 }) = 0 (0x0)
read(12,"TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0"...,41448) = 3519 (0xdbf)
close(12) = 0 (0x0)
madvise(0x21eba000,0xb000,0x5,0x2b9,0x17,0x1) = 0 (0x0)
madvise(0x21e72000,0x5000,0x5,0x271,0x17,0x1) = 0 (0x0)
madvise(0x21e63000,0xc000,0x5,0x262,0x7fffffffcbf0,0x7fffffffcbf0) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
gettimeofday({1343808216.048607 },0x0) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log.2",0x7fffffffd600)
ERR#2 'No such file or directory'
setitimer(0,{0.000000, 180.000000 },{0.000000, 0.000000 }) = 0 (0x0)
fcntl(10,F_SETLKW,0x7fffffffd520) = 0 (0x0)
setitimer(0,{0.000000, 0.000000 },{0.000000, 180.000000 }) = 0 (0x0)
clock_gettime(13,{1343808216.000000000 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=144,blksize=4096 }) = 0 (0x0)
pwrite(0xa,0x21c09000,0xc,0x90,0x10ab6b8,0x2) = 12 (0xc)
pwrite(0xa,0x7fffffffd69c,0x4,0x90,0x10ab6b8,0x2) = 4 (0x4)
clock_gettime(13,{1343808216.000000000 }) = 0 (0x0)
fcntl(10,F_SETLK,0x7fffffffd5e0) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
setitimer(0,{0.000000, 180.000000 },{0.000000, 0.000000 }) = 0 (0x0)
fcntl(10,F_SETLKW,0x7fffffffd1f0) = 0 (0x0)
setitimer(0,{0.000000, 0.000000 },{0.000000, 180.000000 }) = 0 (0x0)
clock_gettime(13,{1343808216.000000000 }) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=156,blksize=4096 }) = 0 (0x0)
pwrite(0xa,0x21c09400,0x1c,0x9c,0xffff800021c0bea4,0x7fffffffa9f0) = 28 (0x1c)
pwrite(0xa,0x7fffffffd57c,0x4,0x9c,0xffff800021c0bea4,0x7fffffffa9f0) = 4 (0x4)
clock_gettime(13,{1343808216.000000000 }) = 0 (0x0)
fcntl(10,F_SETLK,0x7fffffffd610) = 0 (0x0)
stat("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails/dovecot.index.log",{
mode=-rw------- ,inode=28762,size=184,blksize=4096 }) = 0 (0x0)
fstat(10,{ mode=-rw------- ,inode=28762,size=184,blksize=4096 }) = 0 (0x0)
rename("/mailstore/domains/test.com/test/mdbox/mailboxes/Spam/dbox-Mails","/mailstore/domains/test.com/test/mdbox/..DOVECOT-TrasH")
= 0 (0x0)
open(".",O_RDONLY,00) = 12 (0xc)
open("/mailstore/domains/test.com/test/mdbox/..DOVECOT-TrasH",O_NOFOLLOW,00)
= 13 (0xd)
fchdir(0xd,0x100,0x0,0x7b30,0x101010101010101,0x8080808080808080) = 0 (0x0)
stat(".",{ mode=drwx------ ,inode=28761,size=3,blksize=131072 }) = 0
(0x0)
open(".",O_NONBLOCK|0x20000,00) = 14 (0xe)
fstat(14,{ mode=drwx------ ,inode=28761,size=3,blksize=131072 }) = 0 (0x0)
fcntl(14,F_SETFD,FD_CLOEXEC) = 0 (0x0)
fstatfs(0xe,0x7fffffffd3a0,0x21c00400,0x29,0x61ff20,0x0) = 0 (0x0)
getdirentries(0xe,0x21c31000,0x1000,0x21c284e8,0x61ff20,0x0) = 52 (0x34)
unlink("dovecot.index.log") = 0 (0x0)
getdirentries(0xe,0x21c31000,0x1000,0x21c284e8,0x61ff20,0x0) = 0 (0x0)
close(13) = 0 (0x0)
lseek(14,0x0,SEEK_SET) = 0 (0x0)
close(14) = 0 (0x0)
fchdir(0xc,0x0,0x21c07400,0x28,0x61ff20,0x0) = 0 (0x0)
close(12) = 0 (0x0)
rmdir(0x21c18470,0x0,0x21c07400,0x28,0x61ff20,0x0) = 0 (0x0)
rmdir(0x21c184f0,0x4,0x21c18000,0x7af8,0xffffffffffdd6669,0x21c8c298) = 0 (0x0)
open("/mailstore/domains/test.com/test/mdbox/dovecot.mailbox.log",O_RDWR|O_APPEND,0125337603)
= 12 (0xc)
write(12,"\^A\0\0\0\M^L\M-M%\^E\M^F\M-b\^X"...,24) = 24 (0x18)
fstat(12,{ mode=-rw------- ,inode=28751,size=144,blksize=4096 }) = 0 (0x0)
rmdir(0x21c186d0,0x21e41eb8,0x21c186d0,0x7918,0xffffffffffdd6849,0x21c8c298)
ERR#2 'No such file or directory'
write(12,"\^B\0\0\0\M-Xb\M^JRY\M-I{x\M--C"...,24) = 24 (0x18)
fstat(12,{ mode=-rw------- ,inode=28751,size=168,blksize=4096 }) = 0 (0x0)
write(2,"\^A\^B6293 Mailbox deleted: Spam"...,29) = 29 (0x1d)
gettimeofday({1343808216.058749 },0x0) = 0 (0x0)
madvise(0x21e65000,0x1000,0x5,0x264,0x7fffffffcfa0,0xffffffff) = 0 (0x0)
madvise(0x21e63000,0x1000,0x5,0x262,0x7fffffffcfa0,0xffffffff) = 0 (0x0)
madvise(0x21e41000,0x2000,0x5,0x240,0x7fffffffcfa0,0xffffffff) = 0 (0x0)
madvise(0x21d8d000,0x4000,0x5,0x18c,0x7fffffffcfa0,0xffffffff) = 0 (0x0)
madvise(0x21c91000,0x2000,0x5,0x90,0x7fffffffcfa0,0xffffffff) = 0 (0x0)
gettimeofday({1343808216.059531 },0x0) = 0 (0x0)
getpid() = 6293 (0x1895)
__sysctl(0x7fffffffd830,0x4,0x0,0x0,0x21c8f000,0x23) = 0 (0x0)
write(11,"3 OK Delete completed.\r\n",24) = 24 (0x18)
gettimeofday({1343808216.060105 },0x0) = 0 (0x0)
Regard, Nikolai.
Timo Sirainen
2012-Aug-01 11:22 UTC
[Dovecot] Erroneous operation not permitted when deleting mailbox with mdbox
On 1.8.2012, at 11.13, Nikolai Schupbach wrote:> I'm seeing the following error in our logs when removing mailboxes (we are using mdbox and dovecot 2.1.8): > > Aug 1 20:03:36 msgsrv dovecot: imap(test at test.com): Error: stat(/mailstore/domains/test.com/test/mdbox/mailboxes/Spam) failed: Operation not permitted > Aug 1 20:03:36 msgsrv dovecot: imap(test at test.com): Mailbox deleted: Spam > > When I run truss against the process it appears the error relates to attempted unlink of a directory, not a stat of it, as reported by the log. However the mailbox does appear to be deleted fine, so it appears to be an erroneous error.Fixed: http://hg.dovecot.org/dovecot-2.1/rev/8029f1b4afd0
Apparently Analagous Threads
- imap-hibernate returned failure: Failed to parse client input: Invalid peer_dev_minor value
- [nbdkit PATCH v2 2/2] cache, cow: Reduce use of bounce-buffer
- Re: [PATCH nbdkit] filters: Add copy-on-write filter.
- [PATCH nbdkit v5 3/3] cache: Implement cache-max-size and cache space reclaim.
- dovecot 2.1 Master account Error