TL;DR

The backup gem contains a bug that causes it to crash when the HOME environment variable is not set. Notably, this is the case when jobs are started by ‘god’.

I have patched this and will soon send a pull request to the authors of the gem.

Read on to get a few hints on how to track down issues like this one.

The story of a painful bug hunt

0. Background

On several projects I’m using god to start and monitor daemon processes, especially resque workers. On one particular project, this just stopped working recently and as a workaround I had to start the resque workers manually under tmux.

Today I finally took the time to figure out what was going on.

1. Symptoms

In my god.conf I have a ‘resque’ watch configured which starts five workers. Here is the relevant snippet from god.conf:

num_workers = rails_env == 'production' ? 5 : 2
num_workers.times do |num|
  God.watch do |w|
    w.name     = "resque-#{num}"
    w.group    = 'resque'
    w.interval = 60.seconds
    w.env      = {"QUEUE"=>"*", "RAILS_ENV"=>rails_env}
    w.start    = "bundle exec bootup_rake -f #{rails_root}/Rakefile environment resque:work"
    w.dir      = "#{rails_root}"
...

When doing a “god start resque”, god tries to start up the workers but they crash almost immediately. If I do “ps aux | grep resque” within a few seconds I see the processes but then they just disappear.

2. What is god saying?

Finding the scroll that collects the utterings of god is easy:

/var/log/god.log

However, it quicly becomes apparent that god has nothing interesting to say:

I [2011-11-15 16:24:57]  INFO: Using pid file directory: /var/run/god
I [2011-11-15 16:30:55]  INFO: Syslog enabled.
I [2011-11-15 16:30:55]  INFO: Using pid file directory: /var/run/god
I [2011-11-15 16:39:30]  INFO: Syslog enabled.
I [2011-11-15 16:39:30]  INFO: Using pid file directory: /var/run/god
...

A bit of googling suggests that I try to run god in the foreground to see what is going on.

3. Non-daemonized god

So let’s see how god is being invoked:

root@foo:~# ps aux | grep god
root     27956  4.5  0.2 179304 19132 pts/1    Sl   10:12   \
   0:00 /usr/local/rvm/rubies/ruby-1.9.2-p290/bin/ruby      \
   /usr/local/rvm/gems/ruby-1.9.2-p290/bin/god -P /var/run/god.pid -l /var/log/god.log

We need to make a few tweaks:

  • don’t send output to a log file (remove -l)
  • load the config file with -c <config>
  • keep it in the foreground with -D

So our command becomes:

root@foo:~# /usr/local/rvm/rubies/ruby-1.9.2-p290/bin/ruby \ 
   /usr/local/rvm/gems/ruby-1.9.2-p290/bin/god             \
   -P /var/run/god.pid -c /etc/god.conf -D

This yields slightly more interesting output. Here are the lines for the worker ‘resque-1′:

I [2011-11-16 10:17:13]  INFO: resque-1 move 'unmonitored' to 'init'
I [2011-11-16 10:17:13]  INFO: resque-1 moved 'unmonitored' to 'init'
I [2011-11-16 10:17:13]  INFO: resque-1 [trigger] process is not running (ProcessRunning)
I [2011-11-16 10:17:13]  INFO: resque-1 move 'init' to 'start'
I [2011-11-16 10:17:13]  INFO: resque-1 start: bundle exec bootup_rake \ 
   -f /var/www/foo/current/Rakefile environment resque:work
I [2011-11-16 10:17:13]  INFO: resque-1 moved 'init' to 'start'
I [2011-11-16 10:17:13]  INFO: resque-1 [trigger] process is running (ProcessRunning)
I [2011-11-16 10:17:13]  INFO: resque-1 move 'start' to 'up'
I [2011-11-16 10:17:13]  INFO: resque-1 moved 'start' to 'up'
I [2011-11-16 10:17:13]  INFO: resque-1 [ok] memory within bounds [8952kb] (MemoryUsage)
I [2011-11-16 10:17:14]  INFO: resque-1 [ok] process is running (ProcessRunning)

OK, maybe that’s not so interesting after all. God starts the process and is satisfied with that.

What IS interesting is the fact that this actually works! The resque workers keep running and start processing jobs.

4 WTF?

So when I start god non-daemonized, it works. When god is started with ‘service god start’, it does not.

I need a way to see the log output from god when it is running in daemonized mode. This turns out to be as simple as:

god log resque

By default this gives me the output from the first worker in the group. I won’t repeat it here, but it is exactly the same as when running god in the foreground.

It seems to be safe to assume that god is behaving the same way whether started by me or via /etc/init.d/god. To be sure I also tried starting it by executing the exact two lines from this file. Same result.

5. Inspecting the environment

I have suspected for a while that this issue has to do with the environment in which the rake command is being run. This seems to be the only major source of difference between the working and the non-working experiments.

So I need to know the environment in which the failing rake invocations are being run. I know that for all running processes, the environment is available in the file /proc/<pid>/environ. But how can I get to this file when the process dies within seconds?

My solution is to run the following command immediately after god tries to start the workers:

less -f /proc/`ps aux | grep resque | head -1 | cut -d ' ' -f 4`/environ

What this does is

  • ps aux | grep resque finds the process info for the about-to-die resque workers
  • head -1 grabs the first one
  • cut -d ‘ ‘ -f 4 cuts out the PID (fourth field when using a space as the delimiter)
  • This PID is then used as part of the path passed to the outer less command

The environ file is in some kind of binary format (which is why I need -f on the less command) the details of which I haven’t bothered to look up.

I don’t really need to, because after running the above command I see this in my iTerm:

GEM_HOME=/usr/local/rvm/gems/ruby-1.9.2-p290^@TERM=xterm^@IRBRC=/usr/local/rvm/r\
ubies/ruby-1.9.2-p290/.irbrc^@MY_RUBY_HOME=/usr/local/rvm/rubies/ruby-1.9.2-p290\
^@QUEUE=*^@rvm_path=/usr/local/rvm^@PATH=/usr/local/rvm/gems/ruby-1.9.2-p290/bin\
:/usr/local/rvm/gems/ruby-1.9.2-p290@global/bin:/usr/local/rvm/rubies/ruby-1.9.2\
-p290/bin:/usr/local/rvm/bin:/var/www/foo/shared/bundle/ruby/1.9.1/bin:/usr/loca\
l/rvm/gems/ruby-1.9.2-p290/bin:/usr/local/rvm/gems/ruby-1.9.2-p290@global/bin:/u\
sr/local/rvm/rubies/ruby-1.9.2-p290/bin:/usr/local/rvm/bin:/usr/local/sbin:/usr/\
local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games^@PWD=/var/www/foo/releases/20\
111115153743^@LANG=en_US.UTF-8^@SHLVL=1^@BUNDLE_GEMFILE=/var/www/foo/releases/20\
111115153743/Gemfile^@RAILS_ENV=production^@rvm_ruby_string=ruby-1.9.2-p290^@GEM\
_PATH=/usr/local/rvm/gems/ruby-1.9.2-p290:/usr/local/rvm/gems/ruby-1.9.2-p290@gl\
obal^@RUBYOPT=-I/usr/local/rvm/gems/ruby-1.9.2-p290/gems/bundler-1.0.18/lib -rbu\
ndler/setup^@BUNDLE_BIN_PATH=/usr/local/rvm/gems/ruby-1.9.2-p290/gems/bundler-1.\
0.18/bin/bundle^@RUBY_VERSION=ruby-1.9.2-p290^@

Notice that the variables are separated by some byte that less renders as “^@”. Good!

6. Reproducing the bug

Off to Emacs to transform this into something useful. I won’t bore you with the details, but a quick keyboard macro transforms the above into:

export GEM_HOME=/usr/local/rvm/gems/ruby-1.9.2-p290
export TERM=xterm
export IRBRC=/usr/local/rvm/rubies/ruby-1.9.2-p290/.irbrc
export MY_RUBY_HOME=/usr/local/rvm/rubies/ruby-1.9.2-p290
export QUEUE=*
export rvm_path=/usr/local/rvm
export PATH=/usr/local/rvm/gems/ruby-1.9.2-p290/bin:/usr/local/rvm/gems/ruby-1.9.2-p290@global/bin:\
   /usr/local/rvm/rubies/ruby-1.9.2-p290/bin:/usr/local/rvm/bin:/var/www/foo/shared
export PWD=/var/www/foo/releases/20111115153743
export LANG=en_US.UTF-8
export SHLVL=1
export BUNDLE_GEMFILE=/var/www/foo/releases/20111115153743/Gemfile
export RAILS_ENV=production
export rvm_ruby_string=ruby-1.9.2-p290
export GEM_PATH=/usr/local/rvm/gems/ruby-1.9.2-p290:/usr/local/rvm/gems/ruby-1.9.2-p290@global
export RUBYOPT=-I/usr/local/rvm/gems/ruby-1.9.2-p290/gems/bundler-1.0.18/lib -rbundler/setup
export BUNDLE_BIN_PATH=/usr/local/rvm/gems/ruby-1.9.2-p290/gems/bundler-1.0.18/bin/bundle
export RUBY_VERSION=ruby-1.9.2-p2

Back on the server, I clear all existing environment vars with a snippet I found here:

unset  $ ( /usr/bin/env | egrep '^(\w+)=(.*)$' | \
  egrep -vw 'PWD|USER|LANG' | /usr/bin/cut -d= -f1);

Next, I paste all the exports above into iTerm and finally I am ready to try starting the worker again.

Voila!! It crashes:

rake aborted!
can't convert nil into String
/var/www/foo/shared/bundle/ruby/1.9.1/gems/backup-3.0.16/lib/backup.rb:40:in `join'
/var/www/foo/shared/bundle/ruby/1.9.1/gems/backup-3.0.16/lib/backup.rb:40:in `<module:Backup>'
/var/www/foo/shared/bundle/ruby/1.9.1/gems/backup-3.0.16/lib/backup.rb:8:in `<top (required)>'
...

Here are the lines around line 40 of backup.rb:

##                                                                                                                                                                                                                                                                                                                                                                      
# Backup's Environment paths                                                                                                                                                                                                                                                                                                                                            
PATH               = File.join(ENV['HOME'], 'Backup')
DATA_PATH          = File.join(ENV['HOME'], 'Backup', 'data')

Ah, so the backup gem assumes that the HOME environment variable is set. If not, it crashes.

7. Done

Fortunately the source for “backup” is on Github, so I could easily fork the project and apply the very simple patch that was needed.

If you need to run scheduled jobs in your Rails app (!= background jobs as in Resque), you should use the excellent whenever gem.

However, one detail that is really easy to miss is which shell environment the cron job actually runs under.

bundle: command not found

And an easy way to confuse yourself even further is by trying to debug issues in this area by:

  1. Logging into your  server as the deployment user
  2. Doing crontab -l to see which entries whenever installed
  3. Testing an entry by cut’n’pasting it to the shell prompt
The outcome will not be reliable, because you’re running it from a login shell and cron is not. So for example, your rbenv shims may be in the path while testing, but cron does not load your .bashrc or .bash_profile files.

On a project I work on, the staging and production machines are currently quite different. In production we use RVM (globally installed) while staging has rbenv locally installed for the deployment user.

So in staging I need to assume that no binaries are available and use the full path to bundler, in my case /home/passenger/.rbenv/versions/1.9.2-p290/bin/bundle.

(I know, symlinking this to eg. /usr/local/bin/bundle would probably be more elegant, but I actually like the reminder of where my ruby is actually installed. I don’t spend much time on the servers, so I tend to forget.)

Running stuff only on certain stages

EDIT: See Markham’s comment for a better way to do achieve the same result.

Another issue I struggled with for a while is how to schedule jobs only in production. For example, I don’t want to run S3 backups from staging.

I use capistrano/multistage, so I needed to inspect the value of the current “stage” from schedule.rb. It turns out that by including this:

require 'capistrano/ext/multistage'

set :whenever_environment, defer { stage }
require "whenever/capistrano"

…the stage is available in schedule.rb as @environment. Very simple, but it took some googling to find.

Example schedule.rb

Below is my anonymized schedule.rb. It should be pretty self explanatory, post questions in the comments if not.

def production?
 @environment == 'production'
end

set :bundler, production? ? "gp_bundle" : "/home/passenger/.rbenv/versions/1.9.2-p290/bin/bundle"

job_type :gp_rake, "cd :path && RAILS_ENV=:environment :bundler exec rake :task --silent :output"
job_type :gp_runner, "cd :path && :bundler exec rails runner -e :environment ':task' :output"
job_type :gp_bundle_exec, "cd :path && RAILS_ENV=:environment :bundler exec :task"

every 5.minutes do
 gp_rake "thinking_sphinx:index"
end

every 30.minutes do
 gp_runner "FooBar.update"
end

every 1.day, :at => "4:00am" do
 gp_runner "Baz.purge_inactive"
end

if production?
 every 1.day, :at => "4:00am" do
   gp_bundle_exec 'backup perform --trigger my_backup --config-file config/backup.rb --log-path log'
 end
end

EDIT: Jakob Skjerning posted this snippet in the comments:

job_type :rake, “cd /var/www/appname/#{environment}/current && /home/appname/.rvm/gems/ree-1.8.7-2010.02@appname-#{environment}/bin/bundle exec /home/appname/.rvm/wrappers/ree-1.8.7-2010.02@appname-#{environment}/rake –silent RAILS_ENV=#{environment} :task :output”

A few weeks ago I attended a great Geek night at Trifork. The speaker was @drkrab, and he was talking about “Actor oriented programming”.

Knowing Kresten’s work in recent years, it is obvious that this talk was very inspired by Erlang. In fact, much of it was about Erlang, but he only briefly touched on his Erjang project (which was nice for those of us who saw his Erjang talk at last year’s GOTOcon).

Erlang

Erlang is “designed for reliability in the presence of errors”. Others (notably @drkrab) can explain what this means better than me, but the following is a quick tour of some of the highlights as I understood them from the talk.

An actor is an “active object” (ie. an object containing its own thread) plus a state machine. In Erlang, actors are implemented as processes which are designed to be very lightweight. Kresten mentioned that the size of a process in Erlang is comparable to that of a Hashtable in Java, so literally millions of processes can coexist in the same Erlang VM. Processes can be hooked up to monitor each other, so that if one process dies, it can be restarted by its monitor process. Error handling is done very differently than in other languages: In general, don’t try to cover all possible error cases by coding defensively. Instead, let stuff crash and make sure that the system as a whole is resilient.

Processes communicate with each other by passing messages in the form of immutable data structures. Often, communication will simply be one-way, or it may be indirect in the sense that process A receives a message from process C in response to a message it sent to process B. In this scenario, process B will typically have spawned process C as a worker for handling that particular request. The interface of an actor is called a protocol. It can be thought of as an API except that it may change with the internal state of the actor.

Revolution

The basic premise of Kresten’s talk was that we as developers are headed towards a revolution. Just like object orientation was a revolution about 15 years ago, the internet age will be forcing to change horses again soon.

This is a very interesting theory which sounds very plausible to me. I’ve heard the topic mentioned many times before in different forms, but this was the first time I had heard anyone systematically explore what may be going on right now, and I found that really interesting.

Kresten started by exploring the anatomy of a scientific revolution, using the classic example of the geocentric vs. the heliocentric model of our solar system. Assuming that the earth is at the centre of the universe obviously made the orbits of our neighboring planets look very strange. Also, I’m sure there was a multitude of other problems I know nothing about.

Revolution needed

So there were a lot of observations that were hard to fit into the model, and this is a sign that a revolution is needed. And indeed, a very painful revolution was needed in which lots of scientific effort was suddenly rendered obsolete, and lots of frustration had to be endured.

Software professionals saw the same thing happen with the advent of object orientation. There were lots of misconceptions and resistance initially, but as history has shown, OO turned out to be a very useful paradigm.

However, we may be on the verge of the next revolution. The internet age is profoundly changing the way we build software – everything is now much more decoupled than is used to be. We often build new systems by integrating lots of existing services, each of which is outside our control. So increasingly, we need to design for reliability in the presence of errors. Sounds familiar?

My thoughts

I have thought about this talk a couple of times over the last few weeks, and I am pretty convinced that Kresten is on to something. And when I try to put these ideas in the context of my day to day work, there’s at least a partial match.

Much of what I do is Ruby on Rails programming, and in that community we do a lot of integration work. Not integration in the SOA sense, but integration in the form of consuming services provided by other parties. More and more frequently, we use web services to supply functionality that is just easier to buy than to develop from scratch. A good example is mailing lists. I don’t know anyone who would still opt for a DIY mailing list system when we have services like Mailchimp which are feature-rich, affordable and very solid. It has just become cheaper to buy services like this. Error reporting is another good example. I pay $5 per month for my Hoptoad account – this is so cheap that I wouldn’t dream of rolling my own solution. It just wouldn’t be cost effective because my time is much better spent working for clients.

These external services may be down from time to time, and we need to be prepared for that. Were we to implement them in our own software, they would be down from time to time as well, but that downtime would often coincide with the downtime of the client software (which is especially scary in the case of error reporting – related, check Avdi Grimm’s war story on the latest PragProg podcast).

Apart from RoR I do a lot of Android programming, and some of the ideas apply here as well, but I think putting them into practice is further off into the future. Mobile devices certainly need to handle errors well (loss of network connectivity is a very real issue), but changing the programming paradigm to something like Erlang doesn’t seem to be right around the corner.

However, the Android app I’m working on right now is written in Scala, so maybe I should try to sneak in a few actors ;-)

 

One of the things that bothers me the most in software development is when you come across a problem for which there simply is no nice solution to be found. You come up with some ugly hack and get the job done, but the nagging feeling of having fallen short lingers for days.

Problem in question: A project I’m working on sells stuff and uses a payment gateway for this. API access is expensive so we’re opting for the proxy method, meaning that the page that reads credit card information is actually served by the payment provider. It looks something like this:

http://epay.dk/proxy.cgi/http://myshop.com/payment

This means that our /payment page is a very special case. All asset paths must be relative, ie. images/foo.png instead of /images/foo.png. In contrast, links must be absolute, http://shop.com/about instead of /about.

I want the rest of the site to follow normal Rails conventions, so I need to special case this very page. This in itself is a challenge, because as it turns out my ugly hack will affect the application layout as well.

I first tried a few different routes:

  1. Override url_for and set :path_only => false. This solves only half of the problem (asset paths would still be wrong) and turned out to be painful because of the two different url_for implementations. Figuring out why is left as an exercise for the reader because frankly, I can’t be bothered to explain why. Leave a comment if you want to know.
  2. Define some default_url_options. For some reason, I never got this to work reliably, and after some time of fruitless digging trough the Rails source, I abandoned the idea.
  3. Create middleware that kicks in only if controller == Xxx and action == Yyy. It would then process the HTML and change href=”/…” instances to be relative etc. You may object that this is a terrible way of abusing the middleware system, but if it had worked, it would actually have been the least intrusive option. The reason it broke down was unexpected and enlightening: I was able to rewrite the HTML, but afterwards the Apache module pagespeed rewrote it again to optimize CSS includes etc. Obviously this only happened in our production environment, so it took me a couple of hours to track down.
So it would seem that my quest to solve this (somewhat) elegantly had failed. So be it. Time to resort to the nasty hacks.

The solution

Warning: You will be appalled.

What I ended up doing was:

  • In views/layouts/application.html.haml, I only include JS and CSS if we’re not on the payment page.
  • In the payment view, I include all JS/CSS like this (notice that the path does not begin with a slash): %script{ :src => “javascripts/jquery.min.js”, :type => “text/javascript” }
  • Also in the payment view, I added some JS that absolutifies all links. It looks like this:
  $('a[href^="/"]').each(function (idx) {
    fullUrl = "http://myshop.com" + $(this).attr("href");
    $(this).attr("href", fullUrl);
  });

Conclusion

I have created some code that works, but which I’m really, really unhappy about. I hope that some day I’ll come up with a better idea and fix this, but I doubt it. Suggestions are obviously welcome – please leave a comment.

On a project, I have a “Revision” resource and URL’s like

http://foobar.dev/revisions/1

Now suddenly the client wants to rename “revision” to “edition”, so all URLs should be changed to the format

http://foobar.dev/editions/1

Unless I’m missing something in the Rails docs, there is no option to change the base part of the path without renaming the resource itself. Actions can be renamed, eg. “nuevo” instead of “new”, but I don’t think the path segment for the resource name can be changed (please correct me if I’m wrong).

I guess the proper way to go would be to rename everything: The AR model, all helper calls, controllers, tests etc. Even with lots of automation, this would be a really annoying task and I’m not inclined to spend time on this right now. Who knows if the client will change his mind again?

So instead, I ended up changes the resource from

  resources :revisions

to

  resources :editions, :controller => "revisions", :as => "revisions"

I’m changing the name of the resource, but the :controller option makes sure the right controller is still called, and the :as option controls the generation of path helpers (so I can keep using eg. edit_revision_path).

Remember to make the same change for nested resources.

EDIT: As Rasmus and Jakob point out, the :path option sets the actual path, not a prefix. I have made some minor updates to the Rails docs to correct this (most instances were already fixed).

Today, I found a bug in Rails.

On a project, I need to mail PDF files to users, and I would like to use PDFKit for that. The contents of the PDF are generated by rendering a view, but I don’t really want PDFKit to hit the server to get the content. Both because this breaks down in unit tests where the server may not be running, but also because there’s just no reason to go through the entire stack.

So I decided to generate the HTML with render_to_string, then convert it to PDF with PDFkit, and finally mail it to the user.

However, it turned out that this doesn’t work. Here is a minimal example:

class NoteMailer < ActionMailer::Base
  default :from => "from@example.com"

  def foo
    @notes = []
    render_to_string(:template => "notes/index.html.erb")
    # self.instance_variable_set(:@lookup_context, nil) # <-- Workaround
    mail(:to => "example@example.com")  
  end
end

It turns out that the call to render_to_string initializes the @lookup_context of the controller (== mailer in this case). The lookup context is the object that is responsible for locating templates to render, so it contains (among other things) a list of template extensions to look for.

The call to mail() renders the actual mail, but the mailer now reuses the lookup context that was created by render_to_string. This prevents it from finding the mail template, which is (in this example) named “foo.text.erb”, because the lookup context doesn’t recognize the “.text.erb” extension.

A workaround is to manually clear the lookup context on the mailer after the call to render_to_string, but obviously this is a really bad solution.

Follow

Get every new post delivered to your Inbox.