dovecot - Apr 2013 - Problem with fts lucene, on solaris 10

Hi all,
 I'm planning to migrate my courier-imap imap server to dovecot, but I'm
experiencing a strange issue
with fts-lucene plugin.

Basically, every time I start a search, the log starts to write:

Apr 05 19:30:53 indexer: Error: Indexer worker disconnected, discarding 1
requests for XXXXXX
Apr 05 19:30:53 indexer-worker(XXXXX): Fatal: master: service(indexer-worker):
child 809 killed with signal 11 (core not dumped)
Apr 05 19:30:53 imap(XXXXXX): Error: indexer failed to index mailbox INBOX
Apr 05 19:30:56 indexer-worker(XXXXX): Error: lucene index
/home/XXXXX/Maildir/lucene-indexes: IndexWriter() failed (#1): Lock obtain timed
out

When trussing the indexer-worker pid I can see it ends with:
...SNIP...
527:    brk(0x005A7840)                                 = 0
527:    brk(0x005AD840)                                 = 0
527:    pread64(16, " I   G E N E R I C I < /".., 8170, 24514) =
8170
527:    brk(0x005AD840)                                 = 0
527:    brk(0x005B3840)                                 = 0
527:        Incurred fault #5, FLTACCESS  %pc = 0xFEBD6DDC
527:          siginfo: SIGBUS BUS_ADRALN addr=0x005B50BA
527:        Received signal #10, SIGBUS [default]
527:          siginfo: SIGBUS BUS_ADRALN addr=0x005B50BA


I cannot get a core, but either root ( user that is starting the dovecot ) than
the user XXXXX have unlimited coresize
XXXXX /home/XXXXXXX > ulimit -a
time(seconds)        unlimited
file(blocks)         unlimited
data(kbytes)         unlimited
stack(kbytes)        8192
coredump(blocks)     unlimited
nofiles(descriptors) 256
vmemory(kbytes)      unlimited

root # ulimit -a
core file size        (blocks, -c) unlimited
data seg size         (kbytes, -d) unlimited
file size             (blocks, -f) unlimited
open files                    (-n) 1024
pipe size          (512 bytes, -p) 10
stack size            (kbytes, -s) 8192
cpu time             (seconds, -t) unlimited
max user processes            (-u) 29995
virtual memory        (kbytes, -v) unlimited

The mailbox for user XXXXXX ( Maildir stile, for speed-up migration ) has ~ 4000
messages.

The search ends, but I think it don't use the lucene plugin ( it crashes ).

I'm sure I'm missing something, but I can't really find what.


All stuff have been self compiled, using standard flags as per
"configure" scripts.


Thanks for any hint.

Pigi

here the environment:

uname -a
SunOS puma 5.10 Generic_137137-09 sun4u sparc SUNW,Sun-Fire-V240  
( yes, I know, it's quite old ;) )

======dovecot --version
2.1.15

======doveconf -n
# 2.1.15: /usr/local/dovecot/etc/dovecot/dovecot.conf
# OS: SunOS 5.10 sun4u
debug_log_path = /usr/local/dovecot/var/log/dovecot-debug.log
disable_plaintext_auth = no
first_valid_uid = 100
info_log_path = /usr/local/dovecot/var/log/dovecot-info.log
log_path = /usr/local/dovecot/var/log/dovecot.log
mail_location = maildir:~/Maildir
mail_plugins = " fts fts_lucene"
namespace {
  inbox = yes
  location   prefix = INBOX.
  separator = .
}
passdb {
  driver = pam
}
plugin {
  fts = lucene
  fts_lucene = whitespace_chars=@.
}
service imap-login {
  inet_listener imap {
    port = 144
  }
}
service indexer-worker {
  drop_priv_before_exec = yes
}
service pop3-login {
  inet_listener pop3 {
    port = 112
  }
}
ssl = no
userdb {
  driver = passwd
}




============gcc -v
Reading specs from /usr/sfw/lib/gcc/sparc-sun-solaris2.10/3.4.3/specs
Configured with:
/sfw10/builds/build/sfw10-patch/usr/src/cmd/gcc/gcc-3.4.3/configure
--prefix=/usr/sfw --with-as=/usr/ccs/bin/as --without-gnu-as
--with-ld=/usr/ccs/bin/ld --without-gnu-ld --enable-languages=c,c++
--enable-shared
Thread model: posix
gcc version 3.4.3 (csl-sol210-3_4-branch+sol_rpath)

============clucene clucene-core-2.3.3.4
libstemmer_c 
libtextcat-2.2
openssl-1.0.1e

On 5.4.2013, at 22.59, Pigi <pigi at frumar.it> wrote:
> I'm planning to migrate my courier-imap imap server to dovecot, but
I'm experiencing a strange issue
> with fts-lucene plugin.
> 
> Basically, every time I start a search, the log starts to write:
> 
> Apr 05 19:30:53 indexer: Error: Indexer worker disconnected, discarding 1
requests for XXXXXX
> Apr 05 19:30:53 indexer-worker(XXXXX): Fatal: master:
service(indexer-worker): child 809 killed with signal 11 (core not dumped)
> Apr 05 19:30:53 imap(XXXXXX): Error: indexer failed to index mailbox INBOX
> Apr 05 19:30:56 indexer-worker(XXXXX): Error: lucene index
/home/XXXXX/Maildir/lucene-indexes: IndexWriter() failed (#1): Lock obtain timed
out
> 
> When trussing the indexer-worker pid I can see it ends with:
If you can truss it, you can also gdb it, which is much more helpful:

gdb -p <pid of index-worker>
cont
<make it crash>
bt full
> 527:          siginfo: SIGBUS BUS_ADRALN addr=0x005B50BA
> 527:        Received signal #10, SIGBUS [default]
> 527:          siginfo: SIGBUS BUS_ADRALN addr=0x005B50BA
That says it's a SIGBUS, but the Dovecot log said it's a SIGSEGV. Wonder
what's the difference, or maybe you're getting both. Anyway I'd
guess this is a clucene bug related to CPU alignment with Sparc CPU. gdb would
confirm and could help with fixing it.

Sorry for top posting, but I have no additional info on this.
BTW I need to refresh the question as I have tried squat, and I'm biting the
dust with the already known problems
( "Corrupted squat uidlist file" or "Panic: file
squat-trie.c:" ).

Is there some pointer on where/how to find assist on fts-lucene to keep on
analisys for this problem on sparc ?

T.I.A.

Pigi

On Monday 08 April 2013, Pigi wrote:
> On Monday 08 April 2013, Timo Sirainen wrote:
> > On 8.4.2013, at 12.19, Pigi <pigi at frumar.it> wrote:
> > 
> > > Program received signal SIGSEGV, Segmentation fault.
> > > 0xfebd65dc in _malloc_unlocked () from /lib/libc.so.1
> > > (gdb) bt full
> > > #0  0xfebd65dc in _malloc_unlocked () from /lib/libc.so.1
> > > No symbol table info available.
> > > #1  0xfebd66e4 in realloc () from /lib/libc.so.1
> > > No symbol table info available.
> > > #2  0xff1d9a70 in pool_system_realloc (pool=0xff21576c,
mem=0xff21576c, old_size=0, new_size=8192) at mempool-system.c:115
> > > No locals.
> > > #3  0xff1cda28 in i_realloc (mem=0x0, old_size=0, new_size=8192)
at imem.c:14
> > > No locals.
> > 
> > Looks to me like memory corruption, which is just about impossible to
debug if you don't have valgrind or a similar tool (and I don't think
Solaris has any such free tools).
> 
> Yes, you're right. There aren't ( already packaged ) tool for
valgrinding or similar.
>  
> > Do you happen to get any other crashes where it doesn't crash in
malloc code? You showed previously that it was crashing with SIGBUS somewhere.
> 
> For what I can see, form dovecot.log I have a couple of error:
> Apr 08 12:02:18 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 12:02:18 imap(xxxx): Error: indexer failed to index mailbox INBOX
> Apr 08 12:02:18 indexer-worker(xxxx): Fatal: master:
service(indexer-worker): child 27242 killed with signal 11 (core not dumped)
> Apr 08 12:02:19 indexer-worker(xxxx): Error: lucene index
/home/xxxx/Maildir/lucene-indexes: IndexWriter() failed (#1): Lock obtain timed
out
> Apr 08 12:03:46 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 12:03:46 imap(xxxx): Error: indexer failed to index mailbox INBOX
> Apr 08 12:03:46 indexer-worker(xxxx): Fatal: master:
service(indexer-worker): child 27445 killed with signal 10 (core not dumped)
> Apr 08 12:06:57 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 12:06:57 imap(xxxx): Error: indexer failed to index mailbox INBOX
> Apr 08 12:06:57 indexer-worker(xxxx): Fatal: master:
service(indexer-worker): child 27761 killed with signal 11 (core not dumped)
> Apr 08 12:08:33 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> 
> Here a couple or more of gdb"ed" process, but tied to SEGV ( I
almost suspect that when gdbing I always catch a SEGV ) :
> 
> =============================================================> First gdb
> =============================================================> No symbol
table info available.
> #1  0xfebd6884 in realloc () from /lib/libc.so.1
> No symbol table info available.
> #2  0xfe83d270 in lucene::util::StringReader::init (this=0x8d328,
_value=0x2bb288, _length=3958, copyData=true)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/util/Reader.cpp:48
>         tmp = (TCHAR *) 0x2051e0
>         length = 3958
> #3  0xfe8837f0 in
lucene::index::DocumentsWriter::ThreadState::FieldData::invertField
(this=0x92df8, field=0x8d238, analyzer=0x2cb60, maxFieldLength=10000)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/index/DocumentsWriterThreadState.cpp:887
>         stringValue = (const TCHAR *) 0x2bb288
>         stringValueLength = 3958
>         stream = (class lucene::analysis::TokenStream *) 0x0
>         streamValue = (class lucene::analysis::TokenStream *) 0x8d328
> #4  0xfe883a58 in
lucene::index::DocumentsWriter::ThreadState::FieldData::processField
(this=0x92df8, analyzer=0x2cb60)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/index/DocumentsWriterThreadState.cpp:798
>         field = (class lucene::document::Field *) 0x8d238
> #5  0xfe883d6c in
lucene::index::DocumentsWriter::ThreadState::processDocument (this=0x8c0a8,
analyzer=0x2cb60)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/util/Array.h:90
>         i = 6
> #6  0xfe87ea00 in lucene::index::DocumentsWriter::updateDocument
(this=0x84790, doc=0x8b838, analyzer=0x2cb60, delTerm=0x0)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/index/DocumentsWriter.cpp:946
>         state = (class lucene::index::DocumentsWriter::ThreadState *)
0x8c0a8
> #7  0xfe87eb5c in lucene::index::DocumentsWriter::addDocument
(this=0x84790, doc=0x8b838, analyzer=0x2cb60)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/index/DocumentsWriter.cpp:930
> No locals.
> #8  0xfe8b1ea0 in lucene::index::IndexWriter::addDocument (this=0x8cc18,
doc=0x8b838, analyzer=0x2cb60)
>     at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/index/IndexWriter.cpp:682
> No locals.
> #9  0xfea18e04 in lucene_index_build_flush (index=0x37ba8) at
lucene-wrapper.cc:484
>         ret = 0
> #10 0xfea18f88 in lucene_index_build_more (index=0x37ba8, uid=2995,
data=0x185d18 "<xxxxxx at xxxxxxxx.xx>", size=23,
hdr_name=0x8ba60 "Return-Path")
>     at lucene-wrapper.cc:507
>         id = {4, 0, 0, 0, -4196824, -15011172, 534768, -4196336, 516256, 0,
11560, -20155708, 9, 10, 36, 2727408, 516256, 148, 0, 441, 148864, 534768, 3}
>         namesize = 9216
>         datasize = 9216
>         dest = Cannot access memory at address 0xbb3
> (gdb) quit
> 
> =============================================================> Second
gdb
> =============================================================> 
> gdb) bt full
> #0  0xfebd6b24 in realfree () from /lib/libc.so.1
> No symbol table info available.
> #1  0xfebd7354 in cleanfree () from /lib/libc.so.1
> No symbol table info available.
> #2  0xfebd64ac in _malloc_unlocked () from /lib/libc.so.1
> No symbol table info available.
> #3  0xfebd639c in malloc () from /lib/libc.so.1
> No symbol table info available.
> #4  0xfe737b38 in operator new () from /usr/sfw/lib/libstdc++.so.6
> No symbol table info available.
> #5  0xfe8613f4 in Document (this=0x8b838) at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/document/Document.cpp:57
> No locals.
> #6  0xfea18fa8 in lucene_index_build_more (index=0x37ba8, uid=2995,
data=0x8d7b0 "<xxxxxx at xxxxxxxx.xx>", size=23,
hdr_name=0x8b9d0 "Return-Path")
>     at lucene-wrapper.cc:511
>         id = {4, 0, 0, 0, -4196824, -15011172, 1605360, -4196336, 516256,
0, 11560, -20155708, 9, 10, 36, 2122656, 516256, 148, 0, 441, 148864, 1605360,
3}
>         namesize = 9216
>         datasize = 9216
>         dest = Cannot access memory at address 0xbb3
> (gdb) quit
> 
> ==============================================> third gdb 
> ====================================================> (gdb) cont
> Continuing.
> 
> Program received signal SIGSEGV, Segmentation fault.
> 0xfebd710c in t_splay () from /lib/libc.so.1
> (gdb) bt full
> #0  0xfebd710c in t_splay () from /lib/libc.so.1
> No symbol table info available.
> #1  0xfebd6eb8 in t_delete () from /lib/libc.so.1
> No symbol table info available.
> #2  0xfebd6acc in realfree () from /lib/libc.so.1
> No symbol table info available.
> #3  0xfebd72c8 in _free_unlocked () from /lib/libc.so.1
> No symbol table info available.
> #4  0xfebd7204 in free () from /lib/libc.so.1
> No symbol table info available.
> #5  0xfe862144 in lucene::document::Field::_resetValue (this=0x71e288) at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/document/Field.cpp:300
> No locals.
> #6  0xfe862248 in ~Field (this=0x71e288) at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/document/Field.cpp:103
> No locals.
> #7  0xfe90dcc8 in ~CLVector (this=0x23c248) at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/util/Equators.h:227
>         itr = {_M_current = 0x71eb00}
> #8  0xfe860dfc in ~Document (this=0x832e0) at
/extpool/PACKAGES/DOVECOT/clucene-core-2.3.3.4/src/core/CLucene/document/Document.cpp:69
> No locals.
> #9  0xfea18e30 in lucene_index_build_flush (index=0x8adc0) at
lucene-wrapper.cc:493
>         ret = 0
> #10 0xfea18f88 in lucene_index_build_more (index=0x8adc0, uid=4128,
data=0x6b2b00 "<YYYYYYYYY at yyyyyyyyyy.yyy>", size=23,
hdr_name=0x1b6508 "Return-Path")
>     at lucene-wrapper.cc:507
>         id = {4, 0, 0, 0, -4196824, -15011172, 3114656, -4196336, 584416,
0, 11560, 0, 0, 0, 36, 7697128, 584416, 845, 0, 2382, 148880, 3114656, 3}
>         namesize = 9216
>         datasize = 9216
>         dest = Cannot access memory at address 0x1020
> (gdb)
> 
> 
> 
> Here a couple of ( probably ) interesting stuff :
> 
> root # grep "signal 10" /usr/local/dovecot/var/log/dovecot.log 
|wc
>       33     284    2308
> root # grep "signal 11" /usr/local/dovecot/var/log/dovecot.log 
|wc
>       69     549    4457
> root # grep "Lock obtain timed out"
/usr/local/dovecot/var/log/dovecot.log  |wc
>       74     420    3976
> 
> Thus, 74 times of 102 seems to be tied to "IndexWriter() failed (#1):
Lock obtain timed out" ( which I don't really understand,
> or at least I have not enough comprehension of code to understand).
> The path where lucene try to get a lock is not NFS, but is an automount on
the same machine ( no NFS then ).
> 
> It seems that the "Lock obtain timed out" happens every time I
read a message with the MUA.
> 
> This error ("Lock obtain") happens every time I read a message
from my MUA, I think it's due to the indexing process running on READ
> imap command:
> 
> Apr 08 15:18:13 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 15:18:13 imap(xxxx): Error: indexer failed to index mailbox INBOX
> Apr 08 15:18:13 indexer-worker(xxxx): Fatal: master:
service(indexer-worker): child 18171 killed with signal 11 (core not dumped)
> Apr 08 15:18:15 indexer-worker(xxxx): Error: lucene index
/home/xxxx/Maildir/lucene-indexes: IndexWriter() failed (#1): Lock obtain timed
out
> 
> 
> When searching, instead, get the "Lock timeout" followed by
another error:
> 
> Apr 08 15:11:37 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 15:11:37 imap(xxxx): Error: indexer failed to index mailbox INBOX
> Apr 08 15:11:37 indexer-worker(xxxx): Fatal: master:
service(indexer-worker): child 17438 killed with signal 10 (core not dumped)
> Apr 08 15:11:38 indexer-worker(xxxx): Error: lucene index
/home/xxxx/Maildir/lucene-indexes: IndexWriter() failed (#1): Lock obtain timed
out
> Apr 08 15:11:51 indexer: Error: Indexer worker disconnected, discarding 1
requests for xxxx
> Apr 08 15:11:51 imap(xxxx): Error: indexer failed to index mailbox INBOX
> 
> 
> 
> In both case the signal ( 11 or 10, SEGV or SIGBUS ) it's indifferent (
sometimes is 10 sometimes is 11 ).
> 
> Hope I've been able to explain, as my english seems to get worst every
time ;)
> 
> Pigi
> 
>