[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@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@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@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.
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@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@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.
participants (2)
-
Nikolai Schupbach
-
Timo Sirainen