[Dovecot] Erroneous operation not permitted when deleting mailbox with mdbox
Nikolai Schupbach
nikolai at net24.co.nz
Wed Aug 1 11:13:48 EEST 2012
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.
More information about the dovecot
mailing list