How to start debug Ruby programs?

Last days I was busy in my free time with some strange error in Ruby on Rails. Or probably with my own application, rather Rails itself.

Problem which I’m trying to solve is described in more details in this post to Ruby Forum. In short – my app encounter some strange delay when I’m sending JavaScript code direct from controller, via send_data method, rather than RJS or embedding JS in .rhtml.

When I was sure it is some real delay (Ethereal said packet was delayed and logs from application said send_data) I start browsing Rails code, to find out how looks flow through application. I was sure that:

  • send_data is finishing without delay
  • response is delayed (packets with data were not delayed, only TCP seassion teardown was delayed – FIN from server was 30 seconds after last packet of data)
  • there is no network issues between client and server

I was looking for something after my controller method was invoked. After few hours (span on few days) looking through Rails code I realised I can not learn in such way how Rails works behind scenes. So what to do? Fortunatley Ruby is open source language.

I started from Ruby C API reference. After short time I knew where to start. My idea was to find place in code responsible for calling any method (Ruby is interpreted language) and wrap it with some code to dump method, class and time stamp. Now it was easy part. I downloaded Ruby, patched eval.c and I was ready to test.

I started WEBrick, waited and did test. When timeout happened I rushed to examine logs. To my surprise nothing looked like some delay. After send_data flow goes smoothly up to selects. What? And then I jumped 30 seconds forward and…

rb_call: WEBrick::HTTPServer->raise at Tue Sep 18 22:17:49 2006
rb_call: Class->exception at Tue Sep 18 22:17:49 2006
rb_call: Class->(null) at Tue Sep 18 22:17:49 2006
rb_call: WEBrick::HTTPStatus::EOFError->initialize at Tue Sep 18 22:17:49 2006
rb_call: WEBrick::HTTPStatus::EOFError->backtrace at Tue Sep 18 22:17:49 2006
rb_call: WEBrick::HTTPStatus::EOFError->set_backtrace at Tue Sep 18 22:17:49 2006

So looks like it is some kind of timeout in WEBrick. But I can not tell what is the root cause. I’m suspecting my squid proxy (with direct connection there is no delay), but also when I moved app to windows machine and tested connection from localhost (no proxy) I noticed delay. Also feeding to squid copy of request from my test suite (FF, IE, Flock) with identical headers – no delay. Well vanila rails application with some test send_data does not delay. Is this some kind of puzzle?

I finally dumped WEBrick in favor of lighttpd and all works OK with or without proxy. To much time spend on this issue, and I happily acceped solution/workaround good enough.

As a result there is a patch to ruby (I used 1.8.5) dumping to STDERR trace of all method calls. Can be used to approach to start debuging some Ruby program, especially when bug is time based and hard to tell what is happening exactly when bug happens.

How to use it?

Download Ruby source code (http://www.ruby-lang.org/en/downloads/) unpack it and run (I assume You use Ruby 1.8.5, bash shell and Your username is user):
tar -xzf ruby-1.8.5.tgz
cd ruby-1.8.5
mkdir /home/user/ruby-lang
./configure --prefix=/home/user/ruby-lang

Fetch my patch (http://nhw.pl/download/ruby.patch) to and apply it:
patch eval.c ruby.patch
make install
export PATH=~/ruby-lang/bin:${PATH}

Now from this shell You can start Your application and examine stderr to search for hints what is causing problems. In case of Rails just issue standard ./script/server >& log/server.log& and search for STDERR in log/server.log.

Since I was dealing with times like 30 seconds, 1 second time resolution was good enough for me. Don’t use it on production environments (generates a lot of logs and may cause even worse Ruby performance).

Leave a comment

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.