Debugging with the MongoDB oplog

by Charlie Harris

Debugging allows us developers to assume the role of detective, and like any good detective, we need to consult all of our sources to understand what’s going on. If your application uses MongoDB for persistence, one source you have available is the oplog.

What is the oplog?

The MongoDB oplog, or operations log, is a standard capped MongoDB collection. Each document in the collection is a record of a write operation (a delete, update or insertion) that has resulted in data being changed.

What is it used for?

The oplog is used by MongoDB for replication, which refers to the process of copying and storing the same data across members of a ‘replica set’. When you use MongoDB in production you’ll be running one of these replica sets, which consists of at least two members, a primary and a secondary.

The purpose of replication is to provide high levels of redundancy and availability, so that if, for example, one of the members of your replica set becomes unreachable, then the requests being sent from your application can be handled by another.

Within a replica set, copies of the same data are held on the primary and all of the secondaries. When your application gives orders for write operations, they are all executed on the primary. Read operations, on the other hand, can be handled by both your primary and your secondary member(s), depending on the preference you specify.

Maintaining copies of the same data across multiple members of a replica set is where the oplog comes in. Every time a write operation is executed on the primary, an associated log detailing what happened is stored in the oplog.rs collection. The other members of the replica set then copy over the operations in the collection and apply them to their own data, thereby making the data stored across the members eventually consistent.

Why did we look at the oplog?

The team I work on is responsible for a microservice that handles job applications. When a job application is submitted we set a flag from null to true. We then use the flag to ensure that submitted applications cannot be updated.

We were made aware of a bug by a downstream microservice that uses job application data. It had been informed (via a rabbitMQ message) that an application had been submitted. When the downstream microservice then made a call to fetch the data, it found that the submitted flag was null.

A job application should never be unsubmitted, so we headed to the oplog to see if the submitted flag had been set to true and then back to null by a subsequent operation.

Where can you find the oplog?

As mentioned earlier, the oplog is just a standard MongoDB collection. The only difference is its location when compared to your other databases. You’ll see in the image below that it’s inside the local database within the System directory.


What does an entry look like?

Field Description
ts The value for this field is a timestamp, which is a data type supported by BSON that is only ever used for replication. The first half is a standard Unix timestamp, whilst the second is a counter that is incremented for each operation that occurs within a second.
h The hash field gives each entry a unique identity.
v Version of the oplog format.
op The type of operation. This will be either d (delete), u (update) or i (insert).
ns The value of the namespace field is the name of the database followed by the name of the collection.
o2 For updates, the value for this field will be the _id of the document being updated. This field won’t exist for insertions or deletions.
o For updates, this field contains the operation that was performed, whilst for inserts and deletions, it will be the _id of the document that was operated on.


Operations in more detail

Oplog entries are idempotent, which means that no matter how many times they are applied to a document, they will always have the same outcome. So if, for example, you use $pop in your application code, you’ll never see an entry for a $pop in the oplog. Instead, you will see a $set operation that achieves the same outcome as the first application of the $pop that was requested.

When looking at the operations field of an oplog entry, you should know that only the part of your document that was actually updated will appear. It’s a contrived example, but if you had a document in one of your collections that looked like:

{ _id: "5131121332", "a": 1, "b": 2 }

And in your application code the following was requested:

collection.findOneAndUpdate(
 { _id: new ObjectId("5131121332") },
 { $set: { a:1, b:3 } }
)

The value of theo2 field in the oplog would only show field b being updated:

{ $set: {"b":3 } }

You should also be aware that if a request is sent to operate on multiple documents, then there will be an oplog entry for the operation being applied to each of the documents individually.

How can you query the oplog?

You can’t create indexes on the oplog.rs collection and in our case over it is over 1GB in size, which makes querying it using a GUI like Robomongo a challenge. For our investigation we simply ran a mongoexport and searched for the entries we were interested in using grep. A member of the Ops team here at Tes told me that there are more intelligent ways to investigate the oplog, but we decided that implementing a more sophisticated solution wasn’t necessary for what we were trying to achieve.

Conclusion

We were trying to find out whether or not the submitted flag of a job application had been set to null after an operation that had set it to true. By looking at the oplog we were able to see that it had, which then allowed us to look at how this had happened and what steps we could take to prevent it from occurring again.

Whilst debugging is not the purpose of the oplog, it can be an incredibly useful source of information. You just have to be aware of how to find it and what you’re looking at.

Want to know more?

Have a look at the MongoDB replication docs.