dovecot - Aug 2008 - Bad file descriptor with maildir and bzip2 files

Hi,

I'm using the zlib plugin with dovecot 1.1.2 (on Centos 4.5, x86, ext3) and 
some bzip2 (version 1.0.2) compressed mail files are causing the following 
error to show in the logs when I click on the folder in outlook express.

Aug 27 11:39:15 server-2 dovecot: IMAP(marchive): fstat(maildir) failed: Bad 
file descriptor

Aug 27 11:39:17 Info: IMAP(marchive): Loading modules from directory: 
/usr/local/lib/dovecot/imap/
Aug 27 11:39:17 Info: IMAP(marchive): Module loaded: 
/usr/local/lib/dovecot/imap//lib20_zlib_plugin.so
Aug 27 11:39:17 Info: IMAP(marchive): Effective uid=606, gid=609, 
home=/home/marchive
Aug 27 11:39:17 Info: IMAP(marchive): maildir: 
data=/var/spool/maildir/marchive
Aug 27 11:39:17 Info: IMAP(marchive): maildir++: 
root=/var/spool/maildir/marchive, index=, control=, 
inbox=/var/spool/maildir/marchive
Aug 27 11:39:18 Info: IMAP(marchive): Disconnected: Internal error occurred. 
Refer to server log for more information. [20
08-08-27 11:39:18] bytes=246/1040


I attached strace to it and got the following:
11:39:18.193667 
open("/var/spool/maildir/marchive/.2003.INBOX.Charlie.Old.OldInbox.2004/cur/1169027932.P30745Q17M499928.server-2:2,S=103418,Z",
O_RDONLY|O_LARGEFILE) = 11
11:39:18.194130 fstat64(11, {st_mode=S_IFREG|0644, st_size=47637, ...}) = 0
11:39:18.194494 pread64(11, 
"BZh91AY&SY\231\206Z\257\0S\360\377\200\177\3746,U\357\377\377\377\377\377\360\277"...,
4096, 0) = 4096
11:39:18.200204 dup(11) = 12
11:39:18.200557 close(11) = 0
11:39:18.200916 fcntl64(12, F_GETFL) = 0x8000 (flags O_RDONLY|O_LARGEFILE)
11:39:18.200971 fstat64(12, {st_mode=S_IFREG|0644, st_size=47637, ...}) = 0
11:39:18.201104 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7ff2000
11:39:18.201216 _llseek(12, 0, [0], SEEK_CUR) = 0
11:39:18.201355 fstat64(12, {st_mode=S_IFREG|0644, st_size=47637, ...}) = 0
11:39:18.201478 brk(0x9e61000)          = 0x9e61000
11:39:18.201612 read(12, 
"BZh91AY&SY\231\206Z\257\0S\360\377\200\177\3746,U\357\377\377\377\377\377\360\277"...,
4096) = 4096
11:39:18.201694 read(12, 
"\277\217\261\0g!\273\')/3\343V\336\276}\273/\210I\26^\255\304\323\r\275Wts\3773"...,
4096) = 4096
11:39:18.201793 mmap2(NULL, 3600384, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7c68000
11:39:18.205993 read(12, 
"~\214\261E*@[\200\245\302\232\201\334\331\272\225NQ\244\260\371\3473cc\312\255\326\246\17\'\222"...,
4096) = 4096
< continues reading from the file >
11:39:18.225970 read(12, 
"+:E\225\7\217W\264\367\27\226\262i9\34\227=\350\250BcmF\306\'\231m\265\233\337\343\237"...,
4096) = 2581
11:39:18.226040 read(12, "", 4096)      = 0
< 26x more of this read >
11:39:18.233913 munmap(0xb7c68000, 3600384) = 0
11:39:18.234070 close(12)               = 0
11:39:18.234120 munmap(0xb7ff2000, 4096) = 0
11:39:18.234184 fcntl64(12, F_GETFL)    = -1 EBADF (Bad file descriptor)
11:39:18.234255 fstat64(12, 0xbff0a9a0) = -1 EBADF (Bad file descriptor)
11:39:18.234347 write(2, "\1Efstat(maildir) failed: Bad fil"..., 45) =
45

To me it looks like its trying to call fcntl on the handle its just closed?

I've since decompressed these files and recompressed with "gzip
-9" and they
seem to be opening OK.


dovecot -n gives:
# 1.1.2: /usr/local/etc/dovecot.conf
info_log_path: /var/log/dovecot.log
protocols: imap imaps pop3
ssl_disable: yes
disable_plaintext_auth: no
login_dir: /usr/local/var/run/dovecot/login
login_executable(default): /usr/local/libexec/dovecot/imap-login
login_executable(imap): /usr/local/libexec/dovecot/imap-login
login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
mail_location: maildir:/var/spool/maildir/%u
mail_debug: yes
mail_executable(default): /usr/local/libexec/dovecot/imap
mail_executable(imap): /usr/local/libexec/dovecot/imap
mail_executable(pop3): /usr/local/libexec/dovecot/pop3
mail_plugins: zlib
mail_plugin_dir(default): /usr/local/lib/dovecot/imap/
mail_plugin_dir(imap): /usr/local/lib/dovecot/imap/
mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3/
imap_client_workarounds(default): delay-newmail
imap_client_workarounds(imap): delay-newmail
imap_client_workarounds(pop3):
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls
auth default:
  passdb:
    driver: pam
  userdb:
    driver: passwd


ChrisB.

On Aug 27, 2008, at 6:39 PM, Chris Burton wrote:
> Hi,
>
> I'm using the zlib plugin with dovecot 1.1.2 (on Centos 4.5, x86,  
> ext3) and some bzip2 (version 1.0.2) compressed mail files are  
> causing the following error to show in the logs when I click on the  
> folder in outlook express.
>
> Aug 27 11:39:15 server-2 dovecot: IMAP(marchive): fstat(maildir)  
> failed: Bad file descriptor
See if this helps: http://hg.dovecot.org/dovecot-1.1/rev/e024baa42a4f

-------------- next part --------------
A non-text attachment was scrubbed...
Name: PGP.sig
Type: application/pgp-signature
Size: 194 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20080827/30b80385/attachment-0002.bin>

Hi,
 Thanks for the quick reply - it didn't work as is (caused the same error), 
here's what the strace looks like with your patch.

19:34:20.233363 read(12, "", 4096)      = 0
19:34:20.233455 dup(12)                 = 11
19:34:20.233540 munmap(0xb7bd8000, 3600384) = 0
19:34:20.233909 close(12)               = 0
19:34:20.233986 munmap(0xb7f62000, 4096) = 0
19:34:20.234088 fcntl64(11, F_GETFL)    = 0x8000 (flags 
O_RDONLY|O_LARGEFILE)
19:34:20.234169 fstat64(11, {st_mode=S_IFREG|0644, st_size=170988, ...}) = 0
19:34:20.234563 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, 
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f62000
19:34:20.234646 _llseek(11, 0, [170988], SEEK_CUR) = 0
19:34:20.234765 fstat64(12, 0xbfea37d0) = -1 EBADF (Bad file descriptor)
19:34:20.234986 write(2, "\1Efstat(maildir) failed: Bad fil"..., 45) =
45

I took a look at the code and the logic being different depending on 
HAVE_GZSEEK didn't seem right so I tried adding a "else" before
the "#else"
and recompiled and it's working now with the same bzip2 files that caused 
the problem previously.

I'm not sure if that's a fluke or a fix though :).

ChrisB.