What documents did my TTL index delete?

Introduction

Have you ever had one or more documents removed from a MongoDB collection and you weren’t sure what they were? This can potentially occur if you have a TTL index defined, however the approach being shared below can be adapted to filter the replica set oplog for deletes over any custom time frame you may be interested in. Once the _id values of the deleted documents have been identified, the replica set oplog can be further filtered to attempt to surface details about the detailed documents.

Overview

TTL indexes are special single-field indexes that MongoDB can use to automatically remove documents from a collection after a certain amount of time or at a specific clock time. Data expiration is useful for certain types of information like machine generated event data, logs, and session information that only need to persist in a database for a finite amount of time.

The actual removal of documents is handled by a separate thread within the mongod process called the TTLMonitor (enabled by default via ttlMonitorEnabled), which will wake up and check all TTL indexes for expired documents every 60 seconds (the default value of ttlMonitorSleepSecs).

By default the mongod logs won’t record any information about TTL index activity unless the operation happens to exceed the slow query threshold (default of 100ms - may be different in MongoDB Atlas). For the purposes of this article we want to see more information regarding TTL index activity so we’ll begin by increasing the log verbosity for the index component:

db.setLogLevel(1, 'index');

The setLogLevel helper calls the setParameter command, which is unsupported in MongoDB Atlas

As we continue to monitor the mongod log we’ll begin to see messages such as the following begin to be recorded:

{"t":{"$date":"2023-03-14T06:41:26.314-04:00"},"s":"D1","c":"INDEX","id":22533,"ctx":"TTLMonitor","msg":"running TTL job for index","attr":{"namespace":"config.tenantMigrationRecipients","key":{"expireAt":1},"name":"TenantMigrationRecipientTTLIndex"}}
{"t":{"$date":"2023-03-14T06:41:26.314-04:00"},"s":"I","c":"INDEX","id":5479200,"ctx":"TTLMonitor","msg":"Deleted expired documents using index","attr":{"namespace":"config.tenantMigrationRecipients","index":"TenantMigrationRecipientTTLIndex","numDeleted":0,"durationMillis":0}}
{"t":{"$date":"2023-03-14T06:41:26.314-04:00"},"s":"D1","c":"INDEX","id":22533,"ctx":"TTLMonitor","msg":"running TTL job for index","attr":{"namespace":"config.external_validation_keys","key":{"ttlExpiresAt":1},"name":"ExternalKeysTTLIndex"}}
{"t":{"$date":"2023-03-14T06:41:26.315-04:00"},"s":"I","c":"INDEX","id":5479200,"ctx":"TTLMonitor","msg":"Deleted expired documents using index","attr":{"namespace":"config.external_validation_keys","index":"ExternalKeysTTLIndex","numDeleted":0,"durationMillis":0}}
{"t":{"$date":"2023-03-14T06:41:26.315-04:00"},"s":"D1","c":"INDEX","id":22533,"ctx":"TTLMonitor","msg":"running TTL job for index","attr":{"namespace":"config.tenantMigrationDonors","key":{"expireAt":1},"name":"TenantMigrationDonorTTLIndex"}}
{"t":{"$date":"2023-03-14T06:41:26.315-04:00"},"s":"I","c":"INDEX","id":5479200,"ctx":"TTLMonitor","msg":"Deleted expired documents using index","attr":{"namespace":"config.tenantMigrationDonors","index":"TenantMigrationDonorTTLIndex","numDeleted":0,"durationMillis":0}}
{"t":{"$date":"2023-03-14T06:41:26.315-04:00"},"s":"D1","c":"INDEX","id":22533,"ctx":"TTLMonitor","msg":"running TTL job for index","attr":{"namespace":"config.system.sessions","key":{"lastUse":1},"name":"lsidTTLIndex"}}
{"t":{"$date":"2023-03-14T06:41:26.315-04:00"},"s":"I","c":"INDEX","id":5479200,"ctx":"TTLMonitor","msg":"Deleted expired documents using index","attr":{"namespace":"config.system.sessions","index":"lsidTTLIndex","numDeleted":0,"durationMillis":0}}

The above logs represent pre-existing TTL indexes MongoDB creates to expire documents from internal collections. As these indexes are out of scope for this article we’ll skip over them for now and create a custom TTL index to fit our needs.

Setup

db.foo.drop();
db.foo.createIndex({ "created_at": 1 }, { expireAfterSeconds: 10 });
db.foo.insertOne({ created_at: new Date()});

Our new collection now has a single document, which should expire after 10 seconds of being created. Note that the timing will almost never be exact as the TTL monitor will only activate every minute.

The test cluster we’re running on is a replica set, and as such we’re only monitoring the logs for the primary member. The reason for this can be found in the TTL Indexes documentation regarding replica set behavior:

On replica set members, the TTL background thread only deletes documents when a member is in state primary. The TTL background thread is idle when a member is in state secondary. Secondary members replicate deletion operations from the primary.

Within a minute or two a log entry similar to the following will be recorded that indicates our test.foo namespace has been processed, the created_at_1 index has been executed and our document was expired:

{"t":{"$date":"2023-03-14T06:47:41.336-04:00"},"s":"D1","c":"INDEX","id":22533,"ctx":"TTLMonitor","msg":"running TTL job for index","attr":{"namespace":"test.foo","key":{"created_at":1},"name":"created_at_1"}}
{"t":{"$date":"2023-03-14T06:47:41.336-04:00"},"s":"I","c":"INDEX","id":5479200,"ctx":"TTLMonitor","msg":"Deleted expired documents using index","attr":{"namespace":"test.foo","index":"created_at_1","numDeleted":1,"durationMillis":0}}

Unfortunately all this presents us with is confirmation that one document ("numDeleted":1) was removed, but is it possible to find out what was removed?

Enter the Oplog

As the cluster we’re connected to is a replica set all write operations are recorded in the operations log (oplog). The oplog is a capped collection present on each replica set member, and as such we can query it directly to see what write operations have propagated at a given time!

Using the log entry above that confirmed 1 document was deleted we can prepare the following operation to filter the contents of the oplog collection:

// the namespace from the log entry indicating nDeleted > 0
// that we're interested in
var ns = "test.foo";
// the time (with timezone) from the log message
var t1 = new Date("2023-03-14T06:47:41.336-04:00");
// the number of seconds between TTLMonitor sweeps - default: 60
var ttlSleep = db.adminCommand({
  getParameter: 1, ttlMonitorSleepSecs: 1
}).ttlMonitorSleepSecs;
// get the time (in milliseconds) of the starting time and convert
// the TTLMonitor sleep threshold to milliseconds
var t2 = new Date(t1.getTime() + (ttlSleep * 1000));
db.getSiblingDB("local").oplog.rs.find({
  op: "d",
  ns: ns,
  wall: { $gte: t1, $lt: t2 }
});

Any query targeting the oplog will perform a full collection scan as you cannot create indexes on the oplog collection!

The above operation is purposely more verbose than necessary to illustrate where all the necessary pieces of information came from. Once this is executed it should return a single document as seen below, which represents the document that was deleted:

[
  {
    "op": "d",
    "ns": "test.foo",
    "ui": {
      "$binary": {
        "base64": "K4vB+Oh9RgC5scSLCiYWiA==",
        "subType": "04"
      }
    },
    "o": {
      "_id": {
        "$oid": "641050bae52e6d96ee3c40fa"
      }
    },
    "ts": {
      "$timestamp": {
        "t": 1678790861,
        "i": 1
      }
    },
    "t": 8,
    "v": 2,
    "wall": {
      "$date": "2023-03-14T10:47:41.336Z"
    }
  }
]

The only information the oplog records for delete commands is the _id value of the document that was removed. Unless you manage your own custom _id generation, the values will likely just be generated ObjectId values.

We can try to find out additional information about this deleted document by extracting the _id from the oplog document’s o field, and using that to further filter the oplog:

db.getSiblingDB("local").oplog.rs.find({
  // filter by namespace
  ns: "test.foo",
  // filter by insert or update
  op: { $in: ["i", "u"] },
  // filter on the o2._id field as it will be present
  // in both inserts and updates
  "o2._id": ObjectId("641050bae52e6d96ee3c40fa")
}).sort({ ts: -1 });

As documents within the local.oplog.rs namespace will eventually roll over the above query is not guaranteed to return anything, however it’s possible that document creation or update commands may still exist that can give you additional information regarding what this removed document contained:

[
  {
    "lsid": {
      "id": {
        "$binary": {
          "base64": "SHocj0XsSTC25zlbzywaOA==",
          "subType": "04"
        }
      },
      "uid": {
        "$binary": {
          "base64": "47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=",
          "subType": "00"
        }
      }
    },
    "txnNumber": 1,
    // an insert operation
    "op": "i",
    // the namespace the document was created in
    "ns": "test.foo",
    "ui": {
      "$binary": {
        "base64": "K4vB+Oh9RgC5scSLCiYWiA==",
        "subType": "04"
      }
    },
    // this field contains the values that were set when
    // the document was created
    "o": {
      "_id": {
        "$oid": "641050bae52e6d96ee3c40fa"
      },
      "created_at": {
        "$date": "2023-03-14T10:47:22.445Z"
      }
    },
    "o2": {
      "_id": {
        "$oid": "641050bae52e6d96ee3c40fa"
      }
    },
    "stmtId": 0,
    "ts": {
      "$timestamp": {
        "t": 1678790842,
        "i": 4
      }
    },
    "t": 8,
    "v": 2,
    // when the document was created
    "wall": {
      "$date": "2023-03-14T10:47:22.448Z"
    },
    "prevOpTime": {
      "ts": {
        "$timestamp": {
          "t": 0,
          "i": 0
        }
      },
      "t": -1
    }
  }
]

The result above represents an insert and under the o field contains the values that were initially set.

As stated earlier, this method is not guaranteed to work, however it may prove useful if you’re trying to identify what document was deleted and your oplog window is large enough that it still contains the document’s creation. See Change the Size of the Oplog for more information regarding sizing the oplog.