Subject: [sup-talk] Exception trying to run git source

From: [email-masked] (Carl Worth)
Date: Tue, 18 Aug 2009 17:49:03 -0700

Until now I've been running sup 0.8.1 from a Debian package. But in an
effort to get to where I can actually start implementing some of the
features I want, (and to get to where I can actually send a message
without triggering sent.mbox crashes), I'm trying to move to running
sup from a git checkout. But whenever I try, I get the following
exception:

    --- NoMethodError from thread: main
    undefined method `source_uri' for #<Redwood::SentManager:0xb74f1160 @source=nil, @fn="sup://sent">
    ./lib/sup/util.rb:519:in `send'
    ./lib/sup/util.rb:519:in `method_missing'
    bin/sup:171

I bisected this down to the following commit:

    commit 5057149d9c3b57c6b5c4d0964a0aae9d490aaa38
    Author: Ben Walton <bwalton at artsci.utoronto.ca>
    Date:   Wed May 6 22:44:24 2009 -0400
    
        SentManager: rework handling to allow for user specified source

That looks like an awfully nice commit since I'd like my sent messages
to go into a maildir anyway. So I tried configuring this by adding a
line to my ~/.sup/config.yaml as follows:

    :sent_source: maildir:/home/cworth/mail/sent

That didn't actually help too much, it just changed the stack trace
slightly:

    --- NoMethodError from thread: main
    undefined method `source_uri' for #<Redwood::SentManager:0xb73ce404>
    ./lib/sup/util.rb:519:in `send'
    ./lib/sup/util.rb:519:in `method_missing'
    bin/sup:171

So what am I actually missing here?

-Carl
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090818/a004f5e4/attachment.bin>

---

From: [email-masked] (Ben Walton)
Date: Tue, 18 Aug 2009 22:47:40 -0400

>     ./lib/sup/util.rb:519:in `method_missing'

Hmm...I think that's likely an easy fix.  I'll look tomorrow morning.

-Ben
-- 
Ben Walton
Systems Programmer - CHASS
University of Toronto
C:416.407.5610 | W:416.978.4302

GPG Key Id: 8E89F6D2; Key Server: pgp.mit.edu
Contact me to arrange for a CAcert assurance meeting.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090818/2ef0d45e/attachment.bin>

---

From: [email-masked] (Ben Walton)
Date: Wed, 19 Aug 2009 11:59:12 -0400

>     :sent_source: maildir:/home/cworth/mail/sent

Here is my configuration:

maildir:///u/bwalton/Maildir/.sent-mail/

I think you just need to fix the URI.  I'm looking into the code
though to see why it bombed out on you.

Thanks
-Ben

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/f9f554ee/attachment.bin>

---

From: [email-masked] (William Morgan)
Date: Wed, 19 Aug 2009 09:19:44 -0700

> @source=nil, @fn="sup://sent">

Very curious. SentManager most definitely has a source_uri method. If
you look at lib/sup/sent.rb, does it include the line "attr_reader
:source, :source_uri"? If so, is there a line in the log that says
"SentManager initialized with source uri: xxx"?
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Carl Worth)
Date: Wed, 19 Aug 2009 09:33:10 -0700

Excerpts from William Morgan's message of Wed Aug 19 09:19:44 -0700 2009:
> :source, :source_uri"?

Yes, that is there.

>                         If so, is there a line in the log that says

No, I don't think so. At least, that is, if I'm looking at the right
place. Is the "log" anything other than the output on stdout/err when
I run sup? Do I need to turn on any additional verbosity somehow?

Below you can see the entire output I get when running sup from git
master.

-Carl (wishing he had any skills for debugging ruby...)

0:~/src/sup:(master)$ ruby -I lib -w bin/sup
./lib/sup/util.rb:8: warning: method redefined; discarding old
gen_lock_id
./lib/sup/util.rb:19: warning: method redefined; discarding old
dump_lock_id
[Wed Aug 19 09:22:55 -0700 2009] using character set encoding "UTF-8"
./lib/sup/message-chunks.rb:36: warning: method redefined; discarding
old make_tmpname
./lib/sup/imap.rb:117: warning: ambiguous first argument; put
parentheses or even spaces
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:13:
warning: useless use of > in void context
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:19:
warning: useless use of > in void context
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:25:
warning: useless use of < in void context
[Wed Aug 19 09:22:55 -0700 2009] using index Redwood::FerretIndex
Warning: $KCODE is NONE.
[Wed Aug 19 09:22:55 -0700 2009] dynamically loading setlocale() from
libc.so.6
[Wed Aug 19 09:22:55 -0700 2009] setting locale...
[Wed Aug 19 09:22:55 -0700 2009] locking /home/cworth/.sup/lock...
[Wed Aug 19 09:22:55 -0700 2009] crypto: detected gpg binary in
/usr/bin/gpg
[Wed Aug 19 09:22:55 -0700 2009] loading index...
[Wed Aug 19 09:22:55 -0700 2009] loaded index of 557361 messages
./lib/sup/index.rb:53: warning: instance variable @lock_update_thread
not initialized
bin/sup:126: warning: global variable `$cursing' not initialized
[Wed Aug 19 09:22:55 -0700 2009] stopped cursing
[Wed Aug 19 09:22:55 -0700 2009] oh crap, an exception
[Wed Aug 19 09:22:55 -0700 2009] unlocking /home/cworth/.sup/lock...
----------------------------------------------------------------
I'm very sorry. It seems that an error occurred in Sup. Please
accept my sincere apologies. If you don't mind, please send the
contents of ~/.sup/exception-log.txt and a brief report of the
circumstances to sup-talk at rubyforge dot orgs so that I might
address this problem. Thank you!

Sincerely,
William
----------------------------------------------------------------
--- NoMethodError from thread: main
undefined method `source_uri' for #<Redwood::SentManager:0xb75441a8
@source=nil, @fn="sup://sent">
./lib/sup/util.rb:519:in `send'
./lib/sup/util.rb:519:in `method_missing'
bin/sup:171
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/9feb1415/attachment.bin>

---

From: [email-masked] (Ben Walton)
Date: Wed, 19 Aug 2009 12:34:09 -0400

> "SentManager initialized with source uri: xxx"?

Also, is bin/sup part of your git checkout (meaning it lines up with
the rest of your lib/, etc)?  Are you running from the next branch?
I'm looking at bin/sup here (5f393122), and the line numbers don't
"add up."  Line 152 is where I see the call into
SentManager.source_uri, not 171.

-Ben

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/4c299b1e/attachment.bin>

---

From: [email-masked] (Carl Worth)
Date: Wed, 19 Aug 2009 10:53:54 -0700

Excerpts from Ben Walton's message of Wed Aug 19 09:34:09 -0700 2009:
> the rest of your lib/, etc)?

Yes.

>                              Are you running from the next branch?

No, I was running from master, (so line 171 does make sense there).

I tried running from next and got a different failure (see below).  I
suspected I might have something just broken in my configuration, so I
moved ~/.sup away for the run below, (which didn't seem to change
anything).

This new failure seems to be occurring earlier, so I bisected,
(labelling the previous source_uri exception as "good" and the new
no-SentManager-instance as "bad"), and that pointed at the following
commit:

9dd4f50b9f62ab5642241359bf6f7c291ccfa738 is first bad commit
commit 9dd4f50b9f62ab5642241359bf6f7c291ccfa738
Author: William Morgan <wmorgan-sup at masanjin.net>
Date:   Wed Aug 12 13:14:34 2009 -0400

    rewrite Singleton to not require i_am_the_instance
    
    The flip side is that you have to use .init instead of .new.

I'm really wondering why I'm getting what appear to be unique crashes
compared to others. Is it my ruby version:

$ ruby --version
ruby 1.8.7 (2009-06-12 patchlevel 174) [i486-linux]

Any ideas?

-Carl

0:~/src/sup:(next)$ ruby -I lib -w ./bin/sup
./lib/sup/util.rb:9: warning: method redefined; discarding old gen_lock_id
./lib/sup/util.rb:20: warning: method redefined; discarding old dump_lock_id
./lib/sup/message-chunks.rb:36: warning: method redefined; discarding old make_tmpname
./lib/sup/imap.rb:118: warning: ambiguous first argument; put parentheses or even spaces
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:13: warning: useless use of > in void context
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:19: warning: useless use of > in void context
/usr/lib/ruby/1.8/chronic/repeaters/repeater_month_name.rb:25: warning: useless use of < in void context
[Wed Aug 19 10:26:50 -0700 2009] WARNING: Warning: $KCODE is NONE.
./lib/sup/index.rb:54: warning: instance variable @lock_update_thread not initialized
./bin/sup:127: warning: global variable `$cursing' not initialized
./bin/sup:329: warning: global variable `$die' not initialized
[Wed Aug 19 10:26:50 -0700 2009] ERROR: oh crap, an exception
----------------------------------------------------------------
I'm very sorry. It seems that an error occurred in Sup. Please
accept my sincere apologies. If you don't mind, please send the
contents of ~/.sup/exception-log.txt and a brief report of the
circumstances to sup-talk at rubyforge dot orgs so that I might
address this problem. Thank you!

Sincerely,
William
----------------------------------------------------------------
--- RuntimeError from thread: main
no Redwood::SentManager instance defined in method call to i_am_the_instance!
./lib/sup/util.rb:512:in `method_missing'
/usr/lib/ruby/1.8/sup/sent.rb:10:in `initialize'
./lib/sup/util.rb:524:in `new'
./lib/sup/util.rb:524:in `init'
./lib/sup.rb:110:in `start'
./bin/sup:138

---

From: [email-masked] (Ben Walton)
Date: Wed, 19 Aug 2009 14:08:19 -0400

> ruby 1.8.7 (2009-06-12 patchlevel 174) [i486-linux]

I'm running the (now fossilized):
$ ruby --version
ruby 1.8.5 (2006-08-25) [i386-linux]

(as shipped with rhel5).

> Any ideas?

Not right now, but I'll think about it.

Thanks
-Ben

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/cd6d7c32/attachment.bin>

---

From: [email-masked] (William Morgan)
Date: Wed, 19 Aug 2009 11:52:26 -0700

> ruby 1.8.7 (2009-06-12 patchlevel 174) [i486-linux]

Fine.

> ./lib/sup.rb:110:in `start'

Do you get this error in next head, and in the "first bad commit" you
reported? Neither of those should have any calls to i_am_the_instance!
anywhere in the code.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Carl Worth)
Date: Wed, 19 Aug 2009 12:40:15 -0700

Excerpts from William Morgan's message of Wed Aug 19 11:52:26 -0700 2009:
> reported?

Yes.

> Neither of those should have any calls to i_am_the_instance!
> anywhere in the code.

Thanks. That confirms that I'm not running the code I think I am, and
the above stack trace makes that obvious, (see
/usr/lib/ruby/1.8/sup/sent.rb). So I was running some unholy mixture
of the installed Debian sup and the from-git sup and it worked no
better than one would expect.

My previously reported crashes didn't happen to fail in a way that
made /usr/lib show up in the stack trace, but both crashes are fixed
by just moving /usr/lib/ruby/1.8/sup out of the way.

So I'm glad to have things working now, but I'm still curious to know
why ruby goes digging into /usr/lib/ruby/1.8 to find sup/sent.rb when
there's a ./lib/sub/sent.rb present and I've passed a "-I ./lib"
option to ruby, (and plainly, ruby is interpreting other files from
./lib).

And I'd be glad if someone could recommend a ruby-esque way to debug a
situation like this. I mean, I could obviously have just run ruby
under strace and looked for the paths of various *.rb files getting
loaded, but surely there's some more ruby-specific way to list files
that are being used?

-Carl

PS. I'm intrigued by the following mention:

	You?ve got the same sort of command-line debugger available.
	[http://www.ruby-lang.org/en/documentation/ruby-from-other-languages/to-ruby-from-c-and-c-/]

so that's clearly something I'm going to have to learn to use.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/b7de0a71/attachment.bin>

---

From: [email-masked] (William Morgan)
Date: Wed, 19 Aug 2009 13:02:26 -0700

Reformatted excerpts from Carl Worth's message of 2009-08-19:
> Thanks. That confirms that I'm not running the code I think I am,

Good, that explains a lot.

> option to ruby, (and plainly, ruby is interpreting other files from

I find it surprising too. I haven't seen taht behavior before. FWIW, Sup
does try and detect if bin/sup and lib/sup have mismatched versions, and
that didn't fire... I wonder if it's just sent.rb that's been loaded.
Did you somehow delete sent.rb from your git directory, or something
like that?
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Carl Worth)
Date: Wed, 19 Aug 2009 14:37:15 -0700

> Did you somehow delete sent.rb from your git directory, or something

Nope. The git checkout is entirely intact, and it was quite a large
number of modules getting misloaded.

I ran an strace on the ruby process[*] and was able to plainly see
that modules were being correctly loaded from ./lib until after
/usr/lib/ruby/1.8/chronic.rb was loaded. After that, ruby would look
for modules in /usr/lib/ruby/1.8 before ./lib. And sure enough, the
first line of my chronic.rb has:

$:.unshift File.dirname(__FILE__)     # For use/testing when no gem is installed

I'll go ahead and find the right place to file that bug, but at least
the mystery is solved now.

-Carl

[*] http://cworth.org/~cworth/tmp/ruby-sup.strace
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090819/5e1ba854/attachment.bin>

---

From: [email-masked] (William Morgan)
Date: Sat, 22 Aug 2009 13:23:17 -0700

> $:.unshift File.dirname(__FILE__)     # For use/testing when no gem is installed

I'd call that a bug in chronic. It shouldn't be screwing with the load
path. Nice debug work.
-- 
William <wmorgan-sup at masanjin.net>

---

From: [email-masked] (Carl Worth)
Date: Wed, 26 Aug 2009 14:26:18 -0700

Reformatted excerpts from William Morgan's message of Sat Aug 22 13:23:17 -0700 2009:
> path.

That's what I thought too. I filed a Debian bug against the
libchronic-ruby package here:

    http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=542491

But I reall only did that because I didn't find any contact
information for how to submit an upstream bug against chronic
(http://chronic.rubyforge.net didn't have any details that I could
find).

So if someone knows a better place to file the bug, I'd be glad to do
that.

> Nice debug work.

Thanks.

-Carl
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: not available
URL: <http://rubyforge.org/pipermail/sup-talk/attachments/20090826/41bd963c/attachment.bin>