Subject: [sup-talk] EOFError crash

From: [email-masked] (Decklin Foster)
Date: Thu, 30 Oct 2008 14:42:40 -0400

Sup just crashed on me (I was sending an edited draft):

--- EOFError from thread: main
End-of-File Error occured at <except.c>:93 in xraise
Error occured in compound_io.c:137 - cmpdi_read_i
	Tried to read past end of file. File length is <120> and tried to read to <33392>

/usr/lib/ruby/1.8/sup/draft.rb:38:in `default'
/usr/lib/ruby/1.8/sup/draft.rb:38:in `[]'
/usr/lib/ruby/1.8/sup/draft.rb:38:in `discard'
/usr/lib/ruby/1.8/sup/util.rb:499:in `send'
/usr/lib/ruby/1.8/sup/util.rb:499:in `method_missing'
/usr/lib/ruby/1.8/sup/modes/resume-mode.rb:36:in `send_message'
/usr/lib/ruby/1.8/sup/mode.rb:49:in `send'
/usr/lib/ruby/1.8/sup/mode.rb:49:in `handle_input'
/usr/lib/ruby/1.8/sup/buffer.rb:240:in `handle_input'
/usr/bin/sup-mail:188

Any ideas? I got nothing. (Might be a total fluke, but I don't have
time to investigate so I'll just throw it out there.)
-- 
things change.
decklin at red-bean.com

---

From: [email-masked] (Decklin Foster)
Date: Sun, 02 Nov 2008 12:40:12 -0500

> --- EOFError from thread: main

This just happened again. Should I put it into ditz or something? (I feel
exceedingly lame, but I don't have time to debug it today either.)

-- 
things change.
decklin at red-bean.com

---

From: [email-masked] (William Morgan)
Date: Wed, 05 Nov 2008 09:48:34 -0800

Reformatted excerpts from Decklin Foster's message of 2008-11-02:
> This just happened again. Should I put it into ditz or something? (I
> feel exceedingly lame, but I don't have time to debug it today
> either.)

No. Sadly, this is one of the innumerable Ferret errors that crop up
from time to time, which spurred STS.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Eduardo Habkost)
Date: Thu, 06 Nov 2008 12:33:23 -0200

> from time to time, which spurred STS.

I've been easily reproducing crashes similar to this one. The only thing
I need to reproduce it is making sure I load another label while sup is
still polling for new messages.

If I deliver a lot of new messages to a maildir source and don't run
sup-sync, sup will spend a few seconds loading the new messages and
there is plenty of time to hit L, go to a label (I don't know if it
needs to be the same label the new messages being loaded are getting),
and see the crash.

The "workaround" I am using here is being careful to never hit L when the
"polling for new messages" message is shown on the screen.

I have a small collection of core files, also (6 of them, by now),
all of them are from segfaults on the following line on ferret source:

#6  0x00421752 in is_seek (is=0xab75220, pos=31838147) at store.c:285
285             is->m->seek_i(is, pos);

Where is->m is corrupted (either 0 or a bogus value such as 0x10c0).

I don't have the ruby abort message for all of them, but I remember one
of them was triggered on lib/sup/index.rb, line 377 (at the
'fake_header = { ... }' stuff). Unfortunately ruby doesn't produce a
ruby stack trace on segfault, so I don't know what else was running at
the time of the crash (especially on the other threads).

The C backtrace looks like this:

#0  0x00110416 in __kernel_vsyscall ()
#1  0x00c76660 in raise () from /lib/libc.so.6
#2  0x00c78028 in abort () from /lib/libc.so.6
#3  0x004b6f08 in rb_bug (fmt=<value optimized out>) at error.c:214
#4  0x00525dfb in sigsegv (sig=<value optimized out>) at signal.c:629
#5  <signal handler called>
#6  0x00421752 in is_seek (is=0xa67f3a0, pos=24745648) at store.c:285
#7  0x003f42ea in cmpdi_read_i (is=0xafdbfa0, b=0xacda138 "\030\"?", len=170) at compound_io.c:140
#8  0x00421605 in is_read_bytes (is=0xafdbfa0, buf=0xacda138 "\030\"?", len=170) at store.c:267
#9  0x00432c93 in lazy_df_get_data (self=0xafe7100, i=<value optimized out>) at index.c:1207
#10 0x0042b1c8 in frt_lazy_df_load (self=3063423180, rkey=13439246, lazy_df=0xafe7100) at r_index.c:1949
#11 0x004ba02b in call_cfunc (func=<value optimized out>, recv=<value optimized out>, len=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>) at eval.c:5721
#12 0x004c4e66 in rb_call0 (klass=<value optimized out>, recv=<value optimized out>, id=<value optimized out>, oid=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>, body=<value optimized out>, flags=<value optimized out>) at eval.c:5861
#13 0x004c50ba in rb_call (klass=<value optimized out>, recv=<value optimized out>, mid=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>, scope=<value optimized out>, self=<value optimized out>) at eval.c:6117
#14 0x004c5e9c in vafuncall (recv=<value optimized out>, mid=<value optimized out>, n=<value optimized out>, ar=<value optimized out>) at eval.c:6194
#15 0x004c6014 in rb_funcall (recv=Could not find the frame base for "rb_funcall".
) at eval.c:6211
#16 0x004dcb3e in rb_hash_aref (hash=<value optimized out>, key=<value optimized out>) at hash.c:429
#17 0x004ba02b in call_cfunc (func=<value optimized out>, recv=<value optimized out>, len=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>) at eval.c:5721
#18 0x004c4e66 in rb_call0 (klass=<value optimized out>, recv=<value optimized out>, id=<value optimized out>, oid=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>, body=<value optimized out>, flags=<value optimized out>) at eval.c:5861
#19 0x004c50ba in rb_call (klass=<value optimized out>, recv=<value optimized out>, mid=<value optimized out>, argc=<value optimized out>,
    argv=<value optimized out>, scope=<value optimized out>, self=<value optimized out>) at eval.c:6117
#20 0x004bf821 in rb_eval (self=<value optimized out>, n=<value optimized out>) at eval.c:3490
#21 0x004bf73a in rb_eval (self=<value optimized out>, n=<value optimized out>) at eval.c:3484
#22 0x004bf73a in rb_eval (self=<value optimized out>, n=<value optimized out>) at eval.c:3484
[lots of rb_eval calls]
-- 
Eduardo

---

From: [email-masked] (Nicolas Pouillard)
Date: Thu, 06 Nov 2008 16:06:02 +0100

> needs to be the same label the new messages being loaded are getting),

I rarely use 'L', however I often search for particular set of mails
using '\', maybe it's a general problem with search during poll.

In this case perhaps making sup a little bit more sequential would make
it more robust (this could help us to wait for STS).

Best regards,

-- 
Nicolas Pouillard aka Ertai

---

From: [email-masked] (William Morgan)
Date: Thu, 06 Nov 2008 13:40:17 -0800

> still polling for new messages.

Can you try the next branch? I've just pushed some patches there that
might help this.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Eduardo Habkost)
Date: Fri, 07 Nov 2008 00:52:01 -0200

> Can you try the next branch? I've just pushed some patches there that

Just tried it (commit 6831c5966aa0a6021978bffc071734d03cabf2b1).

Triggered the same kind of exceptions of before (two samples below),
when pressing P and M multiple times quickly on inbox-mode, followed by
pressing 'end' and 'j'.

Trying to load a label while polling for new messages triggered a segfault
with the same backtrace as before.

----------------------------------------------------------------
--- IOError from thread: load threads for thread-index-mode
IO Error occured at <except.c>:93 in xraise
Error occured in fs_store.c:293 - fsi_seek_i
        seeking pos 20882841: <Descritor de arquivo inv?lido>

./lib/sup/index.rb:399:in `default'
./lib/sup/index.rb:399:in `[]'
./lib/sup/index.rb:399:in `build_message'
./lib/sup/index.rb:369:in `each_message_in_thread_for'
./lib/sup/thread.rb:341:in `call'
./lib/sup/thread.rb:341:in `load_thread_for_message'
./lib/sup/index.rb:382:in `each_message_in_thread_for'
./lib/sup/index.rb:382:in `each'
./lib/sup/index.rb:382:in `each_message_in_thread_for'
./lib/sup/thread.rb:339:in `load_thread_for_message'
./lib/sup/thread.rb:331:in `load_n_threads'
./lib/sup/index.rb:288:in `each_id_by_date'
./lib/sup/index.rb:287:in `each'
./lib/sup/index.rb:287:in `each_id_by_date'
./lib/sup/thread.rb:326:in `load_n_threads'
./lib/sup/modes/thread-index-mode.rb:499:in `__unprotected_load_n_threads'
(eval):12:in `load_n_threads'
./lib/sup/modes/thread-index-mode.rb:483:in `load_n_threads_background'
./lib/sup.rb:85:in `reporting_thread'
./lib/sup.rb:83:in `initialize'
./lib/sup.rb:83:in `new'
./lib/sup.rb:83:in `reporting_thread'
./lib/sup/modes/thread-index-mode.rb:482:in `load_n_threads_background'
./lib/sup/modes/thread-index-mode.rb:552:in `__unprotected_load_threads'
(eval):12:in `load_threads'
bin/sup:167

----------------------------------------------------------------
--- EOFError from thread: load threads for thread-index-mode
End-of-File Error occured at <except.c>:93 in xraise
Error occured in compound_io.c:137 - cmpdi_read_i
        Tried to read past end of file. File length is <60759> and tried to read to <452160>

./lib/sup/index.rb:396:in `default'
./lib/sup/index.rb:396:in `[]'
./lib/sup/index.rb:396:in `build_message'
./lib/sup/index.rb:288:in `each_id_by_date'
./lib/sup/thread.rb:330:in `call'
./lib/sup/thread.rb:330:in `load_n_threads'
./lib/sup/index.rb:288:in `each_id_by_date'
./lib/sup/index.rb:287:in `each'
./lib/sup/index.rb:287:in `each_id_by_date'
./lib/sup/thread.rb:326:in `load_n_threads'
./lib/sup/modes/thread-index-mode.rb:499:in `__unprotected_load_n_threads'
(eval):12:in `load_n_threads'
./lib/sup/modes/thread-index-mode.rb:483:in `load_n_threads_background'
./lib/sup.rb:85:in `reporting_thread'
./lib/sup.rb:83:in `initialize'
./lib/sup.rb:83:in `new'
./lib/sup.rb:83:in `reporting_thread'
./lib/sup/modes/thread-index-mode.rb:482:in `load_n_threads_background'
./lib/sup/modes/thread-index-mode.rb:552:in `__unprotected_load_threads'
(eval):12:in `load_threads'
bin/sup:167
-- 
Eduardo

---

From: [email-masked] (William Morgan)
Date: Thu, 06 Nov 2008 22:21:06 -0800

> when pressing P and M multiple times quickly on inbox-mode, followed by

Interesting. I can't reproduce this on my end.

Can you please try commit d66cbee, which you can find if you check out
the 'index-locking' branch?

Thanks for helping me test this!
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Eduardo Habkost)
Date: Fri, 07 Nov 2008 09:32:07 -0200

> Thanks for helping me test this!

Looks better!  :D

I didn't manage to reproduce the crash yet. With the previous version
I could crash sup in a few seconds.

> Interesting. I can't reproduce this on my end.

What version of ferret are you using?

In case the info is useful, my 'gem list' output is below. The rest of
ruby packages are the latest ones from Fedora 9 updates ('rpm -qa | grep
ruby' output below).

BTW, do you know what happened to the ferret project site
(http://ferret.davebalmain.com/)? Maybe this is a known bug on ferret,
or something that could be investigated and tracked on the ferret project,
but the site seems to be offline for days.

*** LOCAL GEMS ***

chronic (0.2.3)
columnize (0.2)
ditz (0.5)
fastthread (1.0.1)
ferret (0.11.6)
gettext (1.93.0)
highline (1.4.0)
hoe (1.8.2)
linecache (0.43)
lockfile (1.4.3)
mime-types (1.15)
ncurses (0.9.1)
net-ssh (2.0.4)
rake (0.8.3)
rmail (1.0.0)
ruby-debug (0.10.2)
ruby-debug-base (0.10.2)
rubyforge (1.0.1)
sup (999, 0.6)
trollop (1.10.2)

# rpm -qa | grep -i ruby
libselinux-ruby-2.0.67-4.fc9.i386
ruby-libs-1.8.6.287-2.fc9.i386
ruby-devel-1.8.6.287-2.fc9.i386
ruby-rdoc-1.8.6.287-2.fc9.i386
rubygem-rubyforge-1.0.1-1.fc9.noarch
ruby-1.8.6.287-2.fc9.i386
ruby-irb-1.8.6.287-2.fc9.i386
ruby-debuginfo-1.8.6.287-2.fc9.i386
rubygems-1.2.0-2.fc9.noarch
-- 
Eduardo

---

From: [email-masked] (Eduardo Habkost)
Date: Fri, 07 Nov 2008 11:08:51 -0200

> I could crash sup in a few seconds.

Got a different crash, now, while pressing P and M repeatedly on
inbox-mode.

Maybe related: a killed thread somehow appeared on my inbox listing
(then I killed it again), right before this crash.

--- Ferret::StateError from thread: load threads for thread-index-mode
State Error occured at <except.c>:93 in xraise
Error occured in index.c:4150 - sr_get_lazy_doc
        Document 1 has already been deleted

/usr/lib/ruby/gems/1.8/gems/ferret-0.11.6/lib/ferret/index.rb:421:in `[]'
/usr/lib/ruby/gems/1.8/gems/ferret-0.11.6/lib/ferret/index.rb:421:in `[]'
/usr/lib/ruby/1.8/monitor.rb:242:in `synchronize'
/usr/lib/ruby/gems/1.8/gems/ferret-0.11.6/lib/ferret/index.rb:413:in `[]'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/index.rb:288:in `each_id_by_date'
/usr/lib/ruby/1.8/monitor.rb:242:in `synchronize'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/index.rb:288:in `each_id_by_date'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/index.rb:287:in `each'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/index.rb:287:in `each_id_by_date'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/thread.rb:326:in `load_n_threads'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/thread-index-mode.rb:499:in `__unprotected_load_n_threads'
(eval):12:in `load_n_threads'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/thread-index-mode.rb:483:in `load_n_threads_background'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup.rb:85:in `reporting_thread'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup.rb:83:in `initialize'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup.rb:83:in `new'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup.rb:83:in `reporting_thread'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/thread-index-mode.rb:482:in `load_n_threads_background'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/modes/thread-index-mode.rb:552:in `__unprotected_load_threads'
(eval):12:in `load_threads'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/mode.rb:49:in `send'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/mode.rb:49:in `handle_input'
/usr/lib/ruby/gems/1.8/gems/sup-999/lib/sup/buffer.rb:240:in `handle_input'
/usr/lib/ruby/gems/1.8/gems/sup-999/bin/sup:190
/usr/bin/sup:19:in `load'
/usr/bin/sup:19
-- 
Eduardo

---

From: [email-masked] (William Morgan)
Date: Sun, 09 Nov 2008 19:59:27 -0800

> I could crash sup in a few seconds.

Great, I'm going to merge this into next then.

> What version of ferret are you using?

0.11.6, same as you.

> or something that could be investigated and tracked on the ferret
> project, but the site seems to be offline for days.

I haven't seen that up for a while. I think poor Ferret is very, very
dead.
-- 
William <wmorgan-sup at masanjin.net>