dovecot - Oct 2009 - 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 at
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 at noc4.net): Effective uid=512,
gid=512, home=/nmail/noc4/cache
Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul at noc4.net): maildir: data=~/
Oct 15 09:40:38 10.0.1.2 dovecot: IMAP(paul at 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 at 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 at 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 at noc4.net): Unexpected eof
found when reading file 'UNOPENED' (Errcode: -1)
Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul at 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 at noc4.net): Unexpected eof
found when reading file 'UNOPENED' (Errcode: -1)
Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul at 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 at noc4.net): Unexpected eof
found when reading file 'UNOPENED' (Errcode: -1)
Oct 15 09:40:59 10.0.1.2 dovecot: IMAP(paul at 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 at 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 at noc4.net): Effective uid=512,
gid=512, home=/nmail/noc4/cache
Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul at noc4.net): maildir:
data=~/:INDEX=/nmail/.Indexes/paul at noc4.net
Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul at noc4.net): maildir++:
root=/nmail/noc4/cache, index=/nmail/.Indexes/paul at noc4.net, control=,
inbox=/nmail/noc4/cache
Oct 15 09:43:30 10.0.1.2 dovecot: imap-login: Login: user=<paul at
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 at 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 at noc4.net): Unexpected eof
found when reading file 'UNOPENED' (Errcode: -1)
Oct 15 09:43:30 10.0.1.2 dovecot: IMAP(paul at 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 at 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:
> (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)
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.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20091015/08b31bdb/attachment-0002.bin>

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 at iki.fi>
wrote:
> On Thu, 2009-10-15 at 10:06 +0100, Paul Freeman wrote:
>> (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)
> 
> 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 I'm still getting the same errors, so just as a test I tried the same
process on an x86_32 build host, it's binaries now give a different error,
one which I have also seen mentioned before I think:

----

banshee-x86-32 / # /NOC4/dovecot/sbin/dovecot -F
Error: Missing auth section for server default
Fatal: Invalid configuration in /NOC4/etc/dovecot/dovecot.conf

-----

I do notice this though,
 with x86_64 binaries strace shows calls to pread() 
 with x86_32 binaries strace shows calls to pread64()

this looks round the wrong way? hmm

in both builds file offset bits is 64, with config.h:

---- config.h check...
/* Define to 1 if you have the `pread' function. */
/* Defint if pread/pwrite implementation is broken */
#define PREAD_BROKEN 1
/* Define if pread/pwrite needs _XOPEN_SOURCE 500 */




On Thu, 15 Oct 2009 15:33:47 -0400, Timo Sirainen <tss at iki.fi>
wrote:
> On Thu, 2009-10-15 at 20:30 +0100, Paul Freeman wrote:
>> banshee-x86-64 dovecot-1.2.6 # grep -i pread config.h
>> /* Define to 1 if you have the `pread' function. */
>> /* #undef HAVE_PREAD */
>> /* Defint if pread/pwrite implementation is broken */
>> /* #undef PREAD_BROKEN */
>> /* Define if pread/pwrite needs _XOPEN_SOURCE 500 */
>> #define PREAD_WRAPPERS /**/
>> 
>> i'll give PREAD_BROKEN a try now
> 
> And remove PREAD_WRAPPERS if that doesn't work. It shouldn't matter
> though.