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”
Follow

Get every new post delivered to your Inbox.