mode-debug by kylemcdonald

TL;DR Using the $push operator in mongo fails silently on null fields. Turn on safe mode in your mongoid.yml.

The problem

One of our Rails/mongo projects recently had a bug where one of the array data fields we were appending to was not persisting properly. The app uses Rails 3.2.x (one of our older projects) and Mongoid as an object document mapper. The following code snippet shows the has_many relationship between Fleets, Garages, Motorcycles and Automobiles. I've omitted the Motorcycle and Automobile classes here, but they have basically the same structure.

We'd recently converted a bunch of fleets of motorcycles to automobiles in garages (they needed some mechanical work done). The script looked like this:

The problem we were having was with the newly created Garages. We were able to remove an automobile from a garage fine, but if there was a garage with no automobiles that was created from a fleet with no motorcycles, appending a new automobile to the garage wouldn't save properly.

Writing a test script

Ordinarily, I would write a unit test to create a repeatable test scenario so as to automate the testing process. In this case, I wasn't sure where in the code the problem was, so this was not an option. Manually adding and removing entries in the web app directly got tiresome pretty quickly, so I whipped up a quick script to run after every change. Every time we reloaded the model, g.automobiles would be an empty array again, no matter how many automobiles we appended to the Garage.

Going through mongoid logs

A coworker suggested going through the mongo logs to see if the app was sending the correct updates to the database. Mongoid allows you to set two variables within Rails's application.rb to set the log level to DEBUG. See here for more details on Mongoid and logging.

After tracing through each database query, I could see that the app was indeed telling mongo to $push a new Automobile document to the Garage's :automobiles field. Finally, after googling "mongo array push not persisting", I found the issue. In mongo's documentation on the $push operator there is a note that says:

  • If the field is absent in the document to update, $push adds the array field with the value as its element.
  • If the field is not an array, the operation will fail.

When I pulled up some of the problematic Garage records to see what the :automobiles field looked like, sure enough, they were nil instead of unset like their corresponding Fleet records. I dug back into the earlier script to see why there were a bunch of nils hanging out in empty Garages and discovered the problematic line:

If a fleet had no motorcycles in it to begin with, the script set garage['automobiles'] to nil, which caused any mongo $push operations to that field to fail silently.

We've now set safe: true in mongoid.yml as per the Mongoid's documentation on safe mode, so these types of exceptions will be caught faster in the future. That being said, the docs do mention that mongo sometimes logs an error on the server, but sends a message back to the client that the operation was successful, so I'll be watching the mongo logs more closely in the future.

Main image from Flickr user kylemcdonald.