[SERVER-14186] rs.stepDown during mapReduce causes fassert in logOp Created: 06/Jun/14  Updated: 11/Jul/16  Resolved: 27/Aug/14

Status: Closed
Project: Core Server
Component/s: MapReduce, Replication
Affects Version/s: 2.6.1
Fix Version/s: 2.6.2, 2.7.4

Type: Bug Priority: Critical - P2
Reporter: Bruce Lucas (Inactive) Assignee: Kaloian Manassiev
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Duplicate
is duplicated by SERVER-14185 Mongo Crashed after StepDown Closed
Related
related to SERVER-15308 Stepdown does not cancel active (back... Closed
Tested
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Participants:

 Description   
Issue Status as of Jun 10, 2014

ISSUE SUMMARY
When a server in a replica set steps down from its primary role while certain metadata commands are actively running, the server may shut down. Such commands include mapReduce, renameCollection, dropDatabase, drop, dropIndexes, emptyCapped, convertToCapped, collMod, and create.

USER IMPACT
Replica sets with a sufficient majority should continue to operate normally after a new primary is elected, but any metadata write operations in progress are lost and not replicated. The affected server can be restarted as a secondary.

WORKAROUNDS
N/A

AFFECTED VERSIONS
MongoDB 2.6.0 and 2.6.1 production releases are affected by this issue.

FIX VERSION
The fix is included in the 2.6.2 production release.

RESOLUTION DETAILS
Apply proper locking semantics around metacommands to synchronize with replica set stepdown.

Original description

Create a replica set, run mapReduce's in a tight loop:

function mr() {
    db.c.drop()
    db.c.insert({})
    while (true) {
        map = function() {}
        reduce = function() {}
        db.c.mapReduce(map, reduce, {out:'out'})
    }
}

Then do an rs.stepDown(); produces fassert in logOp:

2014-06-06T10:51:24.741-0400 [conn21] replSet error : logOp() but not primary
2014-06-06T10:51:24.742-0400 [conn21] test Fatal Assertion 17405
2014-06-06T10:51:24.752-0400 [conn21] test 0x1006ac7ab 0x1006642c2 0x100653e3e 0x1004692e8 0x10046cb0f 0x1001b83b9 0x1001b907c 0x1003cfc7f 0x1002a1050 0x100297b3f 0x100297e50 0x1000550d4 0x1000355ac 0x100297661 0x10003e802 0x1000318a6 0x100031fdf 0x1002a3c04 0x1001552c5 0x10015b854 
 0   mongod                              0x00000001006ac7ab _ZN5mongo15printStackTraceERSo + 43
 1   mongod                              0x00000001006642c2 _ZN5mongo10logContextEPKc + 114
 2   mongod                              0x0000000100653e3e _ZN5mongo13fassertFailedEi + 110
 3   mongod                              0x00000001004692e8 _ZN5mongoL8_logOpRSEPKcS1_S1_RKNS_7BSONObjEPS2_Pbb + 376
 4   mongod                              0x000000010046cb0f _ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_PbbPS3_ + 79
 5   mongod                              0x00000001001b83b9 _ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb + 2941
 6   mongod                              0x00000001001b907c _ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi + 1388
 7   mongod                              0x00000001003cfc7f _ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_ + 1615
 8   mongod                              0x00000001002a1050 _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 1968
 9   mongod                              0x0000000100297b3f _ZN5mongo14DBDirectClient4callERNS_7MessageES2_bPSs + 145
 10  mongod                              0x0000000100297e50 _ZThn136_N5mongo14DBDirectClient4callERNS_7MessageES2_bPSs + 16
 11  mongod                              0x00000001000550d4 _ZN5mongo14DBClientCursor4initEv + 346
 12  mongod                              0x00000001000355ac _ZN5mongo12DBClientBase5queryERKSsNS_5QueryEiiPKNS_7BSONObjEii + 180
 13  mongod                              0x0000000100297661 _ZN5mongo14DBDirectClient5queryERKSsNS_5QueryEiiPKNS_7BSONObjEii + 79
 14  mongod                              0x000000010003e802 _ZN5mongo17DBClientInterface5findNERSt6vectorINS_7BSONObjESaIS2_EERKSsNS_5QueryEiiPKS2_i + 156
 15  mongod                              0x00000001000318a6 _ZN5mongo17DBClientInterface7findOneERKSsRKNS_5QueryEPKNS_7BSONObjEi + 118
 16  mongod                              0x0000000100031fdf _ZN5mongo20DBClientWithCommands10runCommandERKSsRKNS_7BSONObjERS3_i + 891
 17  mongod                              0x00000001002a3c04 _ZN5mongo20DBClientWithCommands14dropCollectionERKSsPNS_7BSONObjE + 380
 18  mongod                              0x00000001001552c5 _ZN5mongo2mr5State19dropTempCollectionsEv + 75
 19  mongod                              0x000000010015b854 _ZN5mongo2mr16MapReduceCommand3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb + 5468



 Comments   
Comment by Githook User [ 16/Jul/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-14186 map/reduce check for ismaster under write lock

We need to check master-ness under a write lock before doing a logOp() or else
the server might shut down.

(PARTIAL cherry pick from commit f65ef0b5c272d94f500ea615e36023b45cdf088e)

Conflicts:
src/mongo/db/commands/mr.cpp
src/mongo/db/dbcommands.cpp
Branch: master
https://github.com/mongodb/mongo/commit/08d89a0054efcb3a5dbc17f6717ff742f06c5b9a

Comment by Eric Milkie [ 15/Jul/14 ]

Forward port from 2.6 is non-trivial, as the common place where commands take locks has been pushed down into the individual commands. I suspect the right solution here might be to do individual checking in each command's body after they grab their read or write lock?

Comment by Githook User [ 06/Jun/14 ]

Author:

{u'username': u'milkie', u'name': u'Eric Milkie', u'email': u'milkie@10gen.com'}

Message: SERVER-14186 check for ismaster under write lock

We need to check master-ness under a write lock before doing a logOp() or else
the server might shut down.
Branch: v2.6
https://github.com/mongodb/mongo/commit/f65ef0b5c272d94f500ea615e36023b45cdf088e

Comment by Eric Milkie [ 06/Jun/14 ]

For 2.6, we should amend execCommand() to call isMaster() only after obtaining a read or write lock. This will prevent the 6 or so commands that call logOp from running after primary demotion.

For master, we need to examine each of the logOpping commands and do an isMaster check after each gains a write lock. This is temporary until we have a common Recovery object to do this sort of checking.

Comment by Eric Milkie [ 06/Jun/14 ]

Note that prior to SERVER-12516, this error did not shut down the server. Instead, it would log that message and then continue processing. This would mean that data changed on the stepping-down primary that was not replicated, thus leaving the replica set with inconsistent data between the members.

The error itself occurs because for commands, we check primaryness outside a dblock, so there is no synchronization between itself and another connection doing a stepDown.

Comment by J Rassi [ 06/Jun/14 ]

The server must have yielded the database write lock between the drop of the temp collection and the logOp for the drop. Bruce, can you re-test with 2.6.2-rc0? That has a fix for SERVER-13981 applied, which may resolve this issue. But note that that fix may be hiding the underlying issue (i.e. does mapReduce have issues elsewhere where it yields its lock between inserting to the "out" collection and the corresponding logOp calls?).

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