Upgraded to ruby 1.9.1 - Narnach's blog

The short story

Today I upgraded my Macbook to ruby 1.9.1 (patchlevel 129) as the main version of Ruby I use. It was not really intentional, but now that I have it, I’m kind of sticking with it. That’s the short story. There’s also a long story that involves a server, lots of logs and me not paying attention.

The long story

Earlier today I wanted to analyze 2.5GB of Rails log files. Because it is not such a good idea to do that on a live production server, I decided to use the one server that never really does anything: the backup server. It’s hidden all the way in the back of our server network, far away from the business of our webservers, so it is the perfect place to do some heavy number crunching. After sending the 2.5GB of Rails log files over with scp -C (-C stands for compress) I tried to install the request-log-analyzer gem, but there was no gem command.

A quick ruby -v resulted in bash telling me there is no ruby. My confused reaction went along the lines of: “No Ruby? What? We have a server without Ruby? How can this be?” I checked the server’s sources dir and there was actually a dusty tarball for ruby 1.8.6 sitting undisturbed. I immediately jumped on it and started to unpack it and ran ./configure.

While waiting for this to end, I thought about Ruby 1.9.1 and it’s promise of speed and the huge stack of logs I was planning to start working on. I never made it to the make && sudo make install part for Ruby 1.8.6.

After downloading the latest Ruby 1.9.1 tarball to my desktop and sending it through a chain of servers to the poor ruby-less backup server, a ./configure && make && sudo make install made it all happy again. It actually purrs if you listen close enough to your SSH session.

In the meanwhile I figured I’d upgrade my local Ruby 1.9.0p0 install to the latest patchlevel, so I also perfomed the ./configure && make && sudo make install ritual on my own machine as well. As a habit I always run a ‘-v’ check to see if the version did get installed, but I accidentally typed ruby -v instead of ruby1.9 -v and to my surprise it said:

ruby 1.9.1p129 (2009-05-12 revision 23412) [i386-darwin9.7.0]

Oh, oh. That was not supposed to happen. That should have been Ruby 1.8.6! A check for ruby1.9 showed it was still the old Ruby 1.9.1:

ruby 1.9.1p0 (2009-01-20 revision 21700) [i386-darwin9]

Since the server was done installing as well, I jumped over to there. Unfortunately, request-log-analyzer did not like ruby 1.9:

$ request-log-analyzer log/production.log
Request-log-analyzer, by Willem van Bergen and Bart ten Brinke - version 1.1
Website: http://github.com/wvanbergen/request-log-analyzer

/usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer.rb:27:in `require': /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/output/fixed_width.rb:48: invalid multibyte char (US-ASCII) (SyntaxError)
/usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/output/fixed_width.rb:48: invalid multibyte char (US-ASCII)
/usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/output/fixed_width.rb:48: syntax error, unexpected $end, expecting '}'
...   => { :horizontal_line => '━', :vertical_line => '┃', ...
...                               ^
      from /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer.rb:27:in `load_default_class_file'
      from /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/output.rb:4:in `const_missing'
      from /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/controller.rb:38:in `const_get'
      from /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/lib/request_log_analyzer/controller.rb:38:in `build'
      from /usr/local/lib/ruby/gems/1.9.1/gems/request-log-analyzer-1.1.6/bin/request-log-analyzer:88:in `'
      from /usr/local/bin/request-log-analyzer:19:in `load'
      from /usr/local/bin/request-log-analyzer:19:in `'

So now we know Ruby 1.9 is strict on character encoding and does not like this particular version of the gem. My natural reaction is to switch to my local machine and do a github checkout of the source and build a new gem:

$ gh clone wvanbergen/request-log-analyzer
/usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github/extensions.rb:11: warning: undefining `object_id' may cause serious problem
/usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github.rb:149:in `module_eval': /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/commands/commands.rb:40: syntax error, unexpected ')' (SyntaxError)
helper.tracking.sort { |(a,),(b,)| a == helper.origin ? -...
                            ^
/usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/commands/commands.rb:40: syntax error, unexpected '|', expecting '='
...per.tracking.sort { |(a,),(b,)| a == helper.origin ? -1 : b ...
...                               ^
/usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/commands/commands.rb:40: syntax error, unexpected '}', expecting keyword_end
...rigin ? 1 : a.to_s <=> b.to_s }.each do |(name,user_or_url)|
...                               ^
      from /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github.rb:149:in `load'
      from /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github.rb:66:in `block in activate'
      from /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github.rb:65:in `each'
      from /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/lib/github.rb:65:in `activate'
      from /usr/local/lib/ruby/gems/1.9.1/gems/github-0.3.4/bin/gh:8:in `'
      from /usr/local/bin/gh:19:in `load'
      from /usr/local/bin/gh:19:in `'

Aargh! Another gem that does not play well with Ruby 1.9.

At this point I was kind of fed up with gems not working with Ruby 1.9, so I decided to use a script I wrote ages ago to do simple log crunching. It did not look as pretty as request-log-analyzer, but since it was my script, I felt it would be easiest to fix if it was wrong.

The script did needed a little tweaking to work on Ruby 1.9, but that went pretty ok. The script started crunching, and crunching, and crunching and grew to about 800M (not bad for holding about a gazillion URLs and their call times, standard deviations and more relevant numbers). It was mostly done, generating a new report to highlight different stats every minute or so. And then the Ruby process died. There was something about character encoding and UTF-8:

analyze_log.rb:232:in `split': invalid byte sequence in UTF-8 (ArgumentError)
      from analyze_log.rb:232:in `block in '
      from analyze_log.rb:231:in `each'
      from analyze_log.rb:231:in `'

Luckily, there were enough reports done so that I could look at the numbers I wanted to see.

Conclusion

This experience has taught me two things:

Being an early adopter is rarely a smooth experience. You’re playing with new features before other people do, but the flip side is that you will run into problems and that you will have to fix them yourself.
I really dislike character encodings. Tell me again, why aren’t we just using plain old ASCII? *grumbles*

Next up is checking/fixing my own Rubygems to guarantee they at least do work with Ruby 1.9.1p129. A better world starts with you doing your best to improve it.