TTL Deletion not working

Other MongoDB Topics
#1

We are using MongoDB 4.4.3 as a replica set with PSSSA setup. Earlier without replica set, the TTL was working fine but now with the replica set it is not.

Details:
I created an index on the date, here’s how db.TestTTL.getIndexes() shows it:

	{
		"v" : 2,
		"key" : {
			"date" : 1
		},
		"name" : "date_1",
		"expireAfterSeconds" : 60
	}

Sample document:

{
	"_id" : ObjectId("645b571f15f29c26c0eb0367"),
	"created" : NumberLong("1683707679869"),
	"byUid" : "1513736125051203587",
	"toUid" : "f75f87d8-f59b-49fb-a2f0-7212434cf7a6",
	"date" : ISODate("2023-06-18T00:00:00Z")
}

Output of db.adminCommand({getParameter:1, ttlMonitorSleepSecs: 1});

{
	"ttlMonitorSleepSecs" : 60,
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1690613147, 259),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1690613147, 259)
}

Output of db.adminCommand({getParameter:1, ttlMonitorEnabled:1});

{
	"ttlMonitorEnabled" : true,
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1690613223, 316),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1690613223, 316)
}

Output of db.serverStatus().metrics.ttl has remained same for the last 7 days:

{ "deletedDocuments" : NumberLong(75598788), "passes" : NumberLong(10) }

We increased the log verbosity for “index” but were unable to see any TTL logs. Using
db.setLogLevel(1, "index"); and grep -i ttl /var/log/mongod/mongodb.log giving no results.

#2

Is your cluster currently healthy and has a Primary?

#3

Yes. This is the output of rs.status()

{
	"set" : "rs",
	"date" : ISODate("2023-07-31T05:00:39.684Z"),
	"myState" : 1,
	"term" : NumberLong(7),
	"syncSourceHost" : "",
	"syncSourceId" : -1,
	"heartbeatIntervalMillis" : NumberLong(2000),
	"majorityVoteCount" : 3,
	"writeMajorityCount" : 3,
	"votingMembersCount" : 5,
	"writableVotingMembersCount" : 4,
	"optimes" : {
		"lastCommittedOpTime" : {
			"ts" : Timestamp(1690779639, 423),
			"t" : NumberLong(7)
		},
		"lastCommittedWallTime" : ISODate("2023-07-31T05:00:39.671Z"),
		"readConcernMajorityOpTime" : {
			"ts" : Timestamp(1690779639, 423),
			"t" : NumberLong(7)
		},
		"readConcernMajorityWallTime" : ISODate("2023-07-31T05:00:39.671Z"),
		"appliedOpTime" : {
			"ts" : Timestamp(1690779639, 425),
			"t" : NumberLong(7)
		},
		"durableOpTime" : {
			"ts" : Timestamp(1690779639, 410),
			"t" : NumberLong(7)
		},
		"lastAppliedWallTime" : ISODate("2023-07-31T05:00:39.674Z"),
		"lastDurableWallTime" : ISODate("2023-07-31T05:00:39.608Z")
	},
	"lastStableRecoveryTimestamp" : Timestamp(1690779603, 73),
	"electionCandidateMetrics" : {
		"lastElectionReason" : "priorityTakeover",
		"lastElectionDate" : ISODate("2023-07-22T05:14:35.184Z"),
		"electionTerm" : NumberLong(7),
		"lastCommittedOpTimeAtElection" : {
			"ts" : Timestamp(1690002875, 38),
			"t" : NumberLong(6)
		},
		"lastSeenOpTimeAtElection" : {
			"ts" : Timestamp(1690002875, 38),
			"t" : NumberLong(6)
		},
		"numVotesNeeded" : 3,
		"priorityAtElection" : 3,
		"electionTimeoutMillis" : NumberLong(10000),
		"priorPrimaryMemberId" : 0,
		"targetCatchupOpTime" : {
			"ts" : Timestamp(1690002875, 522),
			"t" : NumberLong(6)
		},
		"numCatchUpOps" : NumberLong(135),
		"newTermStartDate" : ISODate("2023-07-22T05:14:35.753Z"),
		"wMajorityWriteAvailabilityDate" : ISODate("2023-07-22T05:14:37.069Z")
	},
	"members" : [
		{
			"_id" : 0,
			"name" : "ip-172-31-12-111:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 172629,
			"optime" : {
				"ts" : Timestamp(1690779638, 432),
				"t" : NumberLong(7)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1690779638, 425),
				"t" : NumberLong(7)
			},
			"optimeDate" : ISODate("2023-07-31T05:00:38Z"),
			"optimeDurableDate" : ISODate("2023-07-31T05:00:38Z"),
			"lastHeartbeat" : ISODate("2023-07-31T05:00:38.637Z"),
			"lastHeartbeatRecv" : ISODate("2023-07-31T05:00:39.344Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "172.31.12.118:27017",
			"syncSourceId" : 4,
			"infoMessage" : "",
			"configVersion" : 20,
			"configTerm" : 7
		},
		{
			"_id" : 1,
			"name" : "172.31.12.57:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 172159,
			"optime" : {
				"ts" : Timestamp(1690779638, 158),
				"t" : NumberLong(7)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1690779638, 151),
				"t" : NumberLong(7)
			},
			"optimeDate" : ISODate("2023-07-31T05:00:38Z"),
			"optimeDurableDate" : ISODate("2023-07-31T05:00:38Z"),
			"lastHeartbeat" : ISODate("2023-07-31T05:00:38.203Z"),
			"lastHeartbeatRecv" : ISODate("2023-07-31T05:00:39.317Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "172.31.12.118:27017",
			"syncSourceId" : 4,
			"infoMessage" : "",
			"configVersion" : 20,
			"configTerm" : 7
		},
		{
			"_id" : 3,
			"name" : "172.31.12.181:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 172263,
			"optime" : {
				"ts" : Timestamp(1690779638, 105),
				"t" : NumberLong(7)
			},
			"optimeDurable" : {
				"ts" : Timestamp(1690779638, 105),
				"t" : NumberLong(7)
			},
			"optimeDate" : ISODate("2023-07-31T05:00:38Z"),
			"optimeDurableDate" : ISODate("2023-07-31T05:00:38Z"),
			"lastHeartbeat" : ISODate("2023-07-31T05:00:38.181Z"),
			"lastHeartbeatRecv" : ISODate("2023-07-31T05:00:38.149Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "172.31.12.118:27017",
			"syncSourceId" : 4,
			"infoMessage" : "",
			"configVersion" : 20,
			"configTerm" : 7
		},
		{
			"_id" : 4,
			"name" : "172.31.12.118:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 777328,
			"optime" : {
				"ts" : Timestamp(1690779639, 425),
				"t" : NumberLong(7)
			},
			"optimeDate" : ISODate("2023-07-31T05:00:39Z"),
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"electionTime" : Timestamp(1690002875, 518),
			"electionDate" : ISODate("2023-07-22T05:14:35Z"),
			"configVersion" : 20,
			"configTerm" : 7,
			"self" : true,
			"lastHeartbeatMessage" : ""
		},
		{
			"_id" : 5,
			"name" : "172.31.10.121:27017",
			"health" : 1,
			"state" : 7,
			"stateStr" : "ARBITER",
			"uptime" : 171250,
			"lastHeartbeat" : ISODate("2023-07-31T05:00:39.522Z"),
			"lastHeartbeatRecv" : ISODate("2023-07-31T05:00:39.318Z"),
			"pingMs" : NumberLong(0),
			"lastHeartbeatMessage" : "",
			"syncSourceHost" : "",
			"syncSourceId" : -1,
			"infoMessage" : "",
			"configVersion" : 20,
			"configTerm" : 7
		}
	],
	"ok" : 1,
	"$clusterTime" : {
		"clusterTime" : Timestamp(1690779639, 425),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	},
	"operationTime" : Timestamp(1690779639, 425)
}
#4

I am also noticing the output of db.serverStatus().metrics.ttl changing now:
{ "deletedDocuments" : NumberLong(118720859), "passes" : NumberLong(11) }

But I don’t see any output in logs for: grep -i ttl /var/log/syslog

#5

Hi @Mayank_Chaudhary,
Why are you searching this informations in syslog and not in mongod.log?

Regards

#6

My bad, I should have mentioned it earlier. I am using syslog as destination for system logs because of easy log rotation. This is my /etc/mongod.conf

# mongod.conf
  
# for documentation of all options, see:
#   http://docs.mongodb.org/manual/reference/configuration-options/

# Where and how to store data.
storage:
  dbPath: /data/mongodb
  journal:
    enabled: true
#  engine:
#  mmapv1:
#  wiredTiger:

# where to write logging data.
systemLog:
  destination: syslog
  logAppend: true

# network interfaces
net:
  port: 27017
  bindIp: 0.0.0.0

# how the process runs
processManagement:
  timeZoneInfo: /usr/share/zoneinfo

#security:

#operationProfiling:

replication:
  oplogSizeMB: 2048
  replSetName: "rs"

#sharding:

## Enterprise-Only Options:

#auditLog:

#snmp:
#7

I recommend upgrading to the latest 4.4 before looking into this much further.

4.4.3 is not recommended for production use due to WT-7995

I don’t see anything specific in the release notes for TTL but all jiras closed for release would have to be reviewed.