[Dovecot] 1.2.6 Spurious pread()/stream errors/index corruption
Hi,
We're currently testing 1.2.x with a move from 1.1.x in mind however with the current 1.2 series we are encountering some serious problems. simply editing the main conf and restarting dovecot gives these errors seemingly randomly:
(some previous posts indicated this might be todo with 64bit file offsets so we've played around with disable-largefile and setting _FILE_OFFSET_BITS manually but without any success)
---- error while reading main dovecot conf file
Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Panic: file istream-file.c: line 80 (i_stream_file_read): assertion failed: (errno != 0) Error: Raw backtrace: /NOC4/dovecot/sbin/dovecot [0x41ad42] -> /NOC4/dovecot/sbin/dovecot(default_fatal_handler+0x34) [0x41ae54] -> /NOC4/dovecot/sbin/dovecot [0x41a486] -> /NOC4/dovecot/sbin/dovecot [0x41d9b0] -> /NOC4/dovecot/sbin/dovecot(i_stream_read+0x4c) [0x41cbbc] -> /NOC4/dovecot/sbin/dovecot(i_stream_read_next_line+0x28) [0x41d408] -> /NOC4/dovecot/sbin/dovecot(settings_read+0x129) [0x4174d9] -> /NOC4/dovecot/sbin/dovecot(master_settings_read+0x89) [0x4155a9] -> /NOC4/dovecot/sbin/dovecot(main+0x1d2) [0x413162] -> /lib/libc.so.6(__libc_start_main+0xe6) [0x2b6b8258c5c6] -> /NOC4/dovecot/sbin/dovecot [0x40aec9]
---- when we do get past this error it surfaces again inside the imap process:
Oct 15 09:40:25 10.0.1.2 dovecot: Dovecot v1.2.6 starting up (core dumps disabled) Oct 15 09:40:25 10.0.1.2 dovecot: auth-worker(default): mysql: Connected to x.x.x.x (Services) Oct 15 09:40:38 10.0.1.2 dovecot: imap-login: Login: user=<paul@noc4.net>, method=PLAIN, rip=192.168.167.4, lip=10.0.1.2 Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul@noc4.net): Effective uid=512, gid=512, home=/nmail/noc4/cache Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul@noc4.net): maildir: data=~/ Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul@noc4.net): maildir++: root=/nmail/noc4/cache, index=, control=, inbox=/nmail/noc4/cache Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul@noc4.net): Namespace : Using permissions from /nmail/noc4/cache: mode=0700 gid=-1 Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul@noc4.net): Corrupted transaction log file /nmail/noc4/cache/dovecot.index.log seq 2: unexpected end of file while reading header (sync_offset=0) Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): pread() failed with file /nmail/noc4/cache/dovecot.index.log: Success Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): pread() failed with file /nmail/noc4/cache/dovecot.index.log: Success Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul@noc4.net): pread() failed with file /nmail/noc4/cache/dovecot.index.log: Success Oct 15 09:43:18 10.0.1.2 dovecot: IMAP(paul@noc4.net): Server shutting down bytes=11746/855
---- test with different INDEX location
Oct 15 09:43:20 10.0.1.2 dovecot: Dovecot v1.2.6 starting up (core dumps disabled) Oct 15 09:43:20 10.0.1.2 dovecot: auth-worker(default): mysql: Connected to x.x.x.x (Services) Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): Effective uid=512, gid=512, home=/nmail/noc4/cache Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): maildir: data=~/:INDEX=/nmail/.Indexes/paul@noc4.net Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): maildir++: root=/nmail/noc4/cache, index=/nmail/.Indexes/paul@noc4.net, control=, inbox=/nmail/noc4/cache Oct 15 09:43:30 10.0.1.2 dovecot: imap-login: Login: user=<paul@noc4.net>, method=PLAIN, rip=192.168.167.4, lip=10.0.1.2 Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): Namespace : Using permissions from /nmail/noc4/cache: mode=0700 gid=-1 Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul@noc4.net): Panic: file istream-file.c: line 80 (i_stream_file_read): assertion failed: (errno != 0) Oct 15 09:43:31 10.0.1.2 dovecot: IMAP(paul@noc4.net): Raw backtrace: imap [0x4a6642] -> imap [0x4a66c3] -> imap [0x4a5d86] -> imap [0x4ace20] -> imap(i_stream_read+0x4c) [0x4ab0dc] -> imap(i_stream_read_next_line+0x28) [0x4ab928] -> imap(maildir_uidlist_refresh+0x183) [0x443b23] -> imap [0x440d28] -> imap(maildir_storage_sync_init+0x148) [0x441208] -> imap(mailbox_sync+0x30) [0x46ce00] -> imap(cmd_select_full+0x383) [0x4210e3] -> imap [0x42392c] -> imap [0x4239ce] -> imap(client_handle_input+0x45) [0x423b95] -> imap(client_input+0x5f) [0x42458f] -> imap(io_loop_handler_run+0xcb) [0x4ae6cb] -> imap(io_loop_run+0x18) [0x4adb48] -> imap(main+0x537) [0x42c587] -> /lib/libc.so.6(__libc_start_main+0xe6) [0x2b5edbbdb5c6] -> imap [0x41c699] Oct 15 09:43:31 10.0.1.2 dovecot: dovecot: child 30298 (imap) killed with signal 6 (core dumps disabled)
---- our build & test host is
Using built-in specs. Target: x86_64-pc-linux-gnu Configured with: /var/tmp/portage/sys-devel/gcc-4.3.2-r3/work/gcc-4.3.2/configure --prefix=/usr --bindir=/usr/x86_64-pc-linux-gnu/gcc-bin/4.3.2 --includedir=/usr/lib/gcc/x86_64-pc-linux-gnu/4.3.2/include --datadir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.3.2 --mandir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.3.2/man --infodir=/usr/share/gcc-data/x86_64-pc-linux-gnu/4.3.2/info --with-gxx-include-dir=/usr/lib/gcc/x86_64-pc-linux-gnu/4.3.2/include/g++-v4 --host=x86_64-pc-linux-gnu --build=x86_64-pc-linux-gnu --disable-altivec --disable-fixed-point --enable-nls --without-included-gettext --with-system-zlib --disable-checking --disable-werror --enable-secureplt --enable-multilib --enable-libmudflap --disable-libssp --enable-libgomp --disable-libgcj --enable-languages=c,c++,treelang,fortran --enable-shared --enable-threads=posix --enable-__cxa_atexit --enable-clocale=gnu --with-bugurl=http://bugs.gentoo.org/ --with-pkgversion='Gentoo 4.3.2-r3 p1.6, pie-10.1.5' Thread model: posix gcc version 4.3.2 (Gentoo 4.3.2-r3 p1.6, pie-10.1.5)
any input graciously accepted
Regards Paul
On Thu, 2009-10-15 at 10:06 +0100, Paul Freeman wrote:
If your OS is 64bit, you can't disable 64bit file offsets. But yes, your problems clearly points to pread() being broken for some reason. The easiest way to see if that's the only thing broken is to comment out HAVE_PREAD from config.h after configure and recompile.
OK it seems that pread(), for whatever reason is still used even with with HAVE_PREAD undefined, I also removed the pread ac from configure.in and rebuilt configure just to make sure it was not defined anywhere else.
---- a quick snippet from strace...
<snip> open("/NOC4/etc/dovecot/dovecot.conf", O_RDONLY) = 4 fstat(4, {st_mode=S_IFREG|0644, st_size=7333, ...}) = 0 pread(4, "## Dovecot configuration file\n\nba"..., 4096, 0) = 4096 pread(4, " = no\n pop3_enable_last "..., 4067, 4096) = 3237 write(2, "\7"..., 1) = 1 write(2, "Unexpected eof found when reading"..., 63Unexpected eof found when reading file 'UNOPENED' (Errcode: -1)) = 63 write(2, "\n"..., 1 ) = 1 write(2, "Panic: file istream-file.c: line "..., 89Panic: file istream-file.c: line 80 (i_stream_file_read): assertion failed: (errno != 0) ) = 89
---- actual output
Unexpected eof found when reading file 'UNOPENED' (Errcode: -1) Panic: file istream-file.c: line 80 (i_stream_file_read): assertion failed: (errno != 0) Error: Raw backtrace: /NOC4/dovecot/sbin/dovecot [0x41d10e] -> /NOC4/dovecot/sbin/dovecot(default_error_handler+0) [0x41d18a] -> /NOC4/dovecot/sbin/dovecot(i_fatal+0) [0x41d402] -> /NOC4/dovecot/sbin/dovecot [0x421901] -> /NOC4/dovecot/sbin/dovecot(i_stream_read+0x8b) [0x42045b] -> /NOC4/dovecot/sbin/dovecot(i_stream_read_next_line+0x29) [0x420edb] -> /NOC4/dovecot/sbin/dovecot [0x41a715] -> /NOC4/dovecot/sbin/dovecot(settings_read+0x40) [0x41a7ba] -> /NOC4/dovecot/sbin/dovecot(master_settings_read+0xb1) [0x418413] -> /NOC4/dovecot/sbin/dovecot(main+0x32c) [0x41540a] -> /lib/libc.so.6(__libc_start_main+0xe6) [0x2aedb29455c6] -> /NOC4/dovecot/sbin/dovecot [0x40b0a9] Aborted
On Thu, 15 Oct 2009 13:38:22 -0400, Timo Sirainen <tss@iki.fi> wrote:
participants (2)
-
Paul Freeman
-
Timo Sirainen