[SERVER-9053] TTL index asserts on 2.4 secondary Created: 21/Mar/13  Updated: 04/Feb/15  Resolved: 04/Dec/13

Status: Closed
Project: Core Server
Component/s: Index Maintenance
Affects Version/s: 2.4.0
Fix Version/s: 2.4.2, 2.5.5

Type: Bug Priority: Major - P3
Reporter: Steve Briskin (Inactive) Assignee: Scott Hernandez (Inactive)
Resolution: Done Votes: 0
Labels: ttl
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File run.log    
Issue Links:
Depends
Duplicate
is duplicated by SERVER-11976 ns:local.replset.minvalid and 13312 r... Closed
is duplicated by SERVER-9261 [TTLMonitor] error processing ttl log... Closed
Related
related to SERVER-9184 Cleanup TTL logic/locking Closed
is related to SERVER-9188 Revert isMaster behavior wrt godScope Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

Seeing these asserts after upgrading a secondary from 2.2.3 to 2.4. Looks like it's trying to delete records on the secondary.

Thu Mar 21 09:56:26.212 [TTLMonitor] Assertion: 13312:replSet error : logOp() but not primary?
0xdcae01 0xd8c4cb 0xa66b33 0xa63df9 0xa75e64 0xc40351 0xc415b5 0xd8f0c3 0xd8fb74 0xe13709 0x3ee8407851 0x3ee80e811d
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo15printStackTraceERSo+0x21) [0xdcae01]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x9b) [0xd8c4cb]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod() [0xa66b33]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_Pbb+0x49) [0xa63df9]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo13deleteObjectsEPKcNS_7BSONObjEbbbPNS_11RemoveSaverE+0x10d4) [0xa75e64]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo10TTLMonitor10doTTLForDBERKSs+0xfe1) [0xc40351]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo10TTLMonitor3runEv+0x345) [0xc415b5]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5mongo13BackgroundJob7jobBodyEN5boost10shared_ptrINS0_9JobStatusEEE+0xc3) [0xd8f0c3]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod(_ZN5boost6detail11thread_dataINS_3_bi6bind_tIvNS_4_mfi3mf1IvN5mongo13BackgroundJobENS_10shared_ptrINS7_9JobStatusEEEEENS2_5list2INS2_5valueIPS7_EENSD_ISA_EEEEEEE3runEv+0x74) [0xd8fb74]
/data/dist/mongodb-linux-x86_64-2.4.0/bin/mongod() [0xe13709]
/lib64/libpthread.so.0() [0x3ee8407851]
/lib64/libc.so.6(clone+0x6d) [0x3ee80e811d]
Thu Mar 21 09:56:26.215 [TTLMonitor] ERROR: error processing ttl for db: 4d3874ade528c81a1fcdd511 13312 replSet error : logOp() but not primary?



 Comments   
Comment by auto [ 29/Mar/13 ]

Author:

{u'date': u'2013-03-29T21:14:38Z', u'name': u'Scott Hernandez', u'email': u'scotthernandez@gmail.com'}

Message: SERVER-9053: ttl: don't delete on non-primaries
Branch: v2.4
https://github.com/mongodb/mongo/commit/198c577fe4dc2d35a829fac99a97f9e9b03e4ffd

Comment by auto [ 29/Mar/13 ]

Author:

{u'date': u'2013-03-29T21:14:38Z', u'name': u'Scott Hernandez', u'email': u'scotthernandez@gmail.com'}

Message: SERVER-9053: ttl: don't delete on non-primaries
Branch: master
https://github.com/mongodb/mongo/commit/939e91aed13ecb55d2e9a43f5ea92bf4bf64a1c1

Comment by Steve Briskin (Inactive) [ 21/Mar/13 ]

Still doing this. Log file attached.
This is running on brs3.sl.10gen.cc:27017.

isdb:SECONDARY> db.isMaster()
{
	"setName" : "isdb",
	"ismaster" : false,
	"secondary" : true,
	"hosts" : [
		"brs3.sl.10gen.cc:27017",
		"cbibrs2.ny.10gen.cc:27017",
		"cbibrs1.ny.10gen.cc:27017"
	],
	"arbiters" : [
		"isdb1.brs.10gen.cc:27017"
	],
	"primary" : "cbibrs1.ny.10gen.cc:27017",
	"me" : "brs3.sl.10gen.cc:27017",
	"maxBsonObjectSize" : 16777216,
	"maxMessageSizeBytes" : 48000000,
	"localTime" : ISODate("2013-03-21T16:13:57.434Z"),
	"ok" : 1
}
 
isdb:SECONDARY> rs.status()
{
	"set" : "isdb",
	"date" : ISODate("2013-03-21T16:14:16Z"),
	"myState" : 2,
	"syncingTo" : "cbibrs1.ny.10gen.cc:27017",
	"members" : [
		{
			"_id" : 4,
			"name" : "cbibrs1.ny.10gen.cc:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 9173,
			"optime" : Timestamp(1363882455000, 4),
			"optimeDate" : ISODate("2013-03-21T16:14:15Z"),
			"lastHeartbeat" : ISODate("2013-03-21T16:14:15Z"),
			"lastHeartbeatRecv" : ISODate("1970-01-01T00:00:00Z"),
			"pingMs" : 7
		},
		{
			"_id" : 6,
			"name" : "cbibrs2.ny.10gen.cc:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 9171,
			"optime" : Timestamp(1363882455000, 10),
			"optimeDate" : ISODate("2013-03-21T16:14:15Z"),
			"lastHeartbeat" : ISODate("2013-03-21T16:14:16Z"),
			"lastHeartbeatRecv" : ISODate("1970-01-01T00:00:00Z"),
			"pingMs" : 6
		},
		{
			"_id" : 7,
			"name" : "isdb1.brs.10gen.cc:27017",
			"health" : 1,
			"state" : 7,
			"stateStr" : "ARBITER",
			"uptime" : 9171,
			"lastHeartbeat" : ISODate("2013-03-21T16:14:15Z"),
			"lastHeartbeatRecv" : ISODate("2013-03-21T16:14:15Z"),
			"pingMs" : 2
		},
		{
			"_id" : 8,
			"name" : "brs3.sl.10gen.cc:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 9183,
			"optime" : Timestamp(1363882455000, 10),
			"optimeDate" : ISODate("2013-03-21T16:14:15Z"),
			"self" : true
		}
	],
	"ok" : 1
}

Comment by Scott Hernandez (Inactive) [ 21/Mar/13 ]

Steve, is it still doing this? If so, can you get db.isMaster() and rs.getStatus() from that member?

Can you please also post the full logs covering this time period?

Generated at Thu Feb 08 03:19:13 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.