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”

I’ve long found it annoying that the active tab in Google Chrome has almost the same color as the inactive ones.

This can be easily fixed by installing a custom theme such as this one. The active tab in this theme is dark and the inactive ones light. The contrast makes it possible for me to see in my peripheral vision where I am when switching between tabs.

Don’t know why I didn’t think of this before…

I’m running Gitosis on my home Linux server. I like to keep everything under source control, and this setup allows me to have dozens of small projects with very little overhead.

This is really convenient, except every time I start a new project I have to

  • Add it to gitosis-admin, commit and push
  • Set up the initial Git repo for the project
  • Touch, add and commit a README
  • Setup the remote
  • Do the inital push with “-u”

Obviously, this gets pretty tedious, so I automated it with the following script.

#!/bin/bash

PROJECT=$1
THIS_SCRIPT=`readlink $0`
GITOSIS_ADMIN_DIR=${THIS_SCRIPT%/*/*}
GIT_SERVER=chopmo.dk

echo "Project:" $PROJECT
echo "Gitosis admin is at $GITOSIS_ADMIN_DIR"
echo "Adding project to gitosis-admin"
cd $GITOSIS_ADMIN_DIR
sed -i "" "/just-me/,\$s/writable.*/& $PROJECT/" gitosis.conf
git add gitosis.conf
git ci -m "Adding new project $PROJECT"
git push

echo "Setting up local repo"
mkdir $PROJECT
cd $PROJECT
git init
touch README
git add README 
git ci -m "initial commit"
git remote add origin git@$GIT_SERVER:$PROJECT.git
git push -u origin master

echo "Done."

It is stored under “bin” in my gitosis-admin repo and symlinked to ~/bin/new_project (which is why the readlink at the top is important).

The “sed” call appends the new project name to the list of projects which are writable by only me. The just-me,$ addresses are necessary because the structure of my gitosis.conf is:

[gitosis]

[group gitosis-admin]
writable = gitosis-admin
members = ...

[group just-me]
writable = foo bar baz ...

members = ...

So without the limiting addresses, I would append the new project to the writable projects in the gitosis-admin group as well.

My bash skills are pretty weak, so feedback on the script would be very welcome. But this works, and it means that the amount of time from I get an idea for a new project until I can start hacking on it is brought down to just a few seconds.

 

Xoom review

September 1, 2011

For some reason, I have completely neglected to write about my favourite gadget of the year: The Motorola Xoom.

I just love this device. It is perfect for casual browsing, checking email, checking Twitter, Facebook, newssites and all that waste of time. And Amazon has created an excellent tablet-optimized Kindle app, which is probably what I’ve spent the most hours using (until now that I’ve bought a real Kindle – more about that in an upcoming post).

It has more storage space that I’m going to need anytime soon (32GB I think), it has Wifi of course, excellent battery life, nice and responsive screen. In short, the hardware is great and the build quality feels good.

This is the device that Google uses for developing Honeycomb, meaning that it is always up to date and contains no wierd-ware. This is just stock Android 3.x, and everything works together as it should.

App highlights: Kindle, Google Maps, the builtin browser, BeyondPod HD, Gmail, IMDB, the list goes on. We’re really starting to see some great tablet-optimized apps, even if most of them are from Google so far.

BeyondPod really stands out, they have done an excellent job of adapting their phone version (which I like a lot) to the larger screen. It offers a much better blog reading experience than eg. Google Reader in the browser.

Well, it can’t be all good, can it? On to the bad stuff.

Most obvious flaw: The reflective screen. This sucks exactly as much as it does on a laptop and makes it impossible to use the device outside except at night. I ended up buying a screen protector which has solved this problem at the cost of a little screen clarity. But you get used to that, and the screen protector also eliminates ugly fingerprints on the screen. It even makes it possible to use the tablet even if your fingers aren’t completely dry which was a welcome surprise. It is really a bitch to apply it, but well worth the effort.

Second slight drawback: It’s a bit heavy for extended reading sessions. However, you quickly get used to resting it on something.

Conclusion: If you like Android and want a tablet, I highly recommend this device. It’s more geeky than the iPad, but if you’re a geek like me, you’ll appreciate this.

~/bin/remind

August 29, 2011

Here is a very simple helper script I came up with today:

#!/bin/sh
grep $1 ~/.bash_history | uniq

I’m currently using Maven on a client project and I keep forgetting the various invocations of mvn. So this helps remind me.

Example:

[ ~/wb/foo ] $ remind mvn
mvn 
which mvn
mvn -v
mvn -cpu hpi:create
mvn package
mvn --help
mvn -o package
mvn install
mvn -DdownloadSources=true -DdownloadJavadocs=true -DoutputDirectory=target/eclipse-classes eclipse:eclipse
mvn hpi:run

This is handy for those cases where I want an overview of all ways in which I’ve recently used a command.

If I just want to recall a specific command, I use bash’s Ctrl-R and whichever few letters of the command I remember:

ctrl-R ec

This will recall the long second-to-last command in the example above.

 

I use my Xoom mainly for reading eBooks, and I really like Amazon’s Kindle app.

Unfortunately, it seems to have no support at all for syncing books that are not bought through Amazon (not surprisingly perhaps). This is a problem for me because I often buy from the Pragmatic Programmers, and I don’t want to copy those .mobi files to my tablet manually (I know that PragProg offers to sync the titles via Whispernet, but that only works for physical Kindle devices).

What I found out recently is that there is a pretty easy fix for this:

  1. Store your books in some folder in your Dropbox, say “/kindle”
  2. Install the app FolderSync Lite on your Android device
  3. Set up your Dropbox account in FolderSync. The interface is not very intuitive so pay attention.
  4. Set up a “folderpair” in FolderSync, mapping /kindle in your Dropbox to /mnt/sdcard/kindle on your device. Make sure the sync type is “to local folder”.
  5. Schedule this folderpair to sync as often as you like.
If you got the options in FolderSync right, you can now put your non-Amazon purchases into /kindle in your Dropbox and they will automatically appear in the Kindle app on your Android device.

You may be wondering if this conflicts with the books you bought through Amazon – after all, they’re also stored in /mnt/sdcard/kindle. The trick is that FolderSync does not take ownership of this folder, it simply copies files from the remote (Dropbox) folder into it. So I assume that it doesn’t even clean up deleted files, although I haven’t tried.

Follow

Get every new post delivered to your Inbox.