threehv

A project I’ve been working on was recently moved up to Rails 2.2 (Rails 2.3 migration coming soon, but we wanted to take things one step at a time).

All the tests passed. Poking it on the staging server worked well. On to production and all was good.

Time passed.

Then, the app needed to be moved to a new server. Actually to a cluster. Slightly more nerve-wracking, but some playing around with the ghost gem and DNS settings and the deployment completed.

More time passed.

And then disaster struck. Well, not disaster, but it wasn’t good. Not at all.

The app had a rake task that was cronned to run every night. And it failed silently. We found out the day after and I scanned the production log file looking for evidence of what went wrong. Nowt. It didn’t even look like the rake task had run – but it had, as I had the data in front of me.

And the day after, it failed again. Another scan of the production log revealed nothing. Things were getting serious.

I suspected the cluster deployment. Maybe cron didn’t have permission to write to the log file, even though Passenger did. But everything looked good on that front. Maybe there was something else weird about the cluster setup – all the cron jobs were set to run on one of the app-servers; maybe moving it would make a difference?

To test this, I opened the Rails console and started manually recreating what the rake task was doing, on a different app-server. Which is when I noticed that script/console wasn’t writing to the production log either. What?

After a couple of hours of head scratching, I finally found out that the cluster deployment was not at fault. In fact, it seems to be the move to Rails 2.2 that had happened many weeks before – in particular it appears that the logger object no longer auto-flushes itself after writing.

We added a quick Rails.logger.auto_flushing = 1 to an initialiser and both script/console and the rake tasks wrote to the log as expected. Phew!