[SERVER-20856] During CSRS upgrade, config server gets stuck in STARTUP2 when restarted with --replSet and --configsvrMode=sccc set Created: 09/Oct/15  Updated: 25/Jan/17  Resolved: 28/Oct/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 3.1.9, 3.2.0-rc0
Fix Version/s: 3.2.0-rc2

Type: Bug Priority: Major - P3
Reporter: Timothy Olsen (Inactive) Assignee: Andy Schwerin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File configserver-post-restart.log     Text File configserver-pre-restart.log    
Issue Links:
Depends
Related
related to SERVER-21078 Segfault from race between getlasterr... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:
  1. Start up a 3.1.9 config server
  2. Do rs.initiate({_id: "csrs", version: 1, configsvr: true, members: [ {_id: 0, host: "HOSTNAME:PORT"}]})
  3. Stop config server
  4. Start config server with --replSet=csrs --configsvrMode=sccc also set
  5. Watch config server get stuck in STARTUP2
Sprint: Sharding B (10/30/15)
Participants:

 Description   

During the CSRS upgrade, the first restart of the first config server (with --replSet and --configsvrMode=sccc set) results in the first config server getting stuck in STARTUP2.

Log file of first config server:

/tmp/mms-automation/test//versions/mongodb-osx-x86_64-3.1.9/bin/mongod --dbpath=db1 --configsvr --replSet=csrs --configsvrMode=sccc
2015-10-09T17:18:02.287-0400 I -        [initandlisten] Detected data files in db1 created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2015-10-09T17:18:02.287-0400 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=9G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2015-10-09T17:18:03.316-0400 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.$main
2015-10-09T17:18:03.316-0400 I STORAGE  [initandlisten] Scanning the oplog to determine where to place markers for when to truncate
2015-10-09T17:18:03.317-0400 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-10-09T17:18:03.317-0400 I STORAGE  [initandlisten] Scanning the oplog to determine where to place markers for when to truncate
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] MongoDB starting : pid=28419 port=27019 dbpath=db1 64-bit host=neurofunk.local
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] 
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] ** NOTE: This is a development version (3.1.9) of MongoDB.
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] **       Not recommended for production.
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] 
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] 
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] db version v3.1.9
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] git version: 9c317d92145a77ab582acb215b3ed41af2f1b33c
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] allocator: system
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] modules: none
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] build environment:
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten]     distarch: x86_64
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten]     target_arch: x86_64
2015-10-09T17:18:03.327-0400 I CONTROL  [initandlisten] options: { replication: { replSet: "csrs" }, sharding: { clusterRole: "configsvr", configsvrMode: "sccc" }, storage: { dbPath: "db1" } }
2015-10-09T17:18:03.337-0400 I REPL     [initandlisten] Did not find local voted for document at startup;  NoMatchingDocument Did not find replica set lastVote document in local.replset.election
2015-10-09T17:18:03.338-0400 I FTDC     [initandlisten] Starting full-time diagnostic data capture with directory 'db1/diagnostic.data'
2015-10-09T17:18:03.338-0400 W REPL     [ReplicationExecutor] Failed to load timestamp of most recently applied operation; NoMatchingDocument Did not find any entries in local.oplog.rs
2015-10-09T17:18:03.338-0400 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "csrs", version: 1, configsvr: true, protocolVersion: 1, members: [ { _id: 0, host: "neurofunk.local:27019", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, electionTimeoutOffsetLimitMillis: 2000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 } } }
2015-10-09T17:18:03.338-0400 I REPL     [ReplicationExecutor] This node is neurofunk.local:27019 in the config
2015-10-09T17:18:03.338-0400 I REPL     [ReplicationExecutor] transition to STARTUP2
2015-10-09T17:18:03.339-0400 I REPL     [ReplicationExecutor] Starting replication applier threads
2015-10-09T17:18:03.340-0400 I NETWORK  [initandlisten] waiting for conne2015-10-09T17:18:03.340-0400 I REPL     [rsSync] no valid sync sources found in current replset to do an initial sync
2015-10-09T17:18:04.345-0400 I REPL     [rsSync] initial sync pending
2015-10-09T17:18:04.345-0400 I REPL     [rsSync] no valid sync sources found in current replset to do an initial sync
2015-10-09T17:18:05.350-0400 I REPL     [rsSync] initial sync pending
2015-10-09T17:18:05.350-0400 I REPL     [rsSync] no valid sync sources found in current replset to do an initial sync
2015-10-09T17:18:06.353-0400 I REPL     [rsSync] initial sync pending
2015-10-09T17:18:06.353-0400 I REPL     [rsSync] no valid sync sources found in current replset to do an initial sync
2015-10-09T17:18:07.358-0400 I REPL     [rsSync] initial sync pending
2015-10-09T17:18:07.359-0400 I REPL     [rsSync] no valid sync sources found in current replset to do an initial sync



 Comments   
Comment by Githook User [ 28/Oct/15 ]

Author:

{u'username': u'andy10gen', u'name': u'Andy Schwerin', u'email': u'schwerin@mongodb.com'}

Message: SERVER-20856 Atomically store the replica set config document and initiate the oplog.

Otherwise, if the server running replSetInitiate crashes between writing the
config to disk and creating the oplog, on restart it will get stuck in state
STARTUP2, believing that it must run an initial sync.
Branch: master
https://github.com/mongodb/mongo/commit/ac1d8c42a498c546fd4f67e19f063776c48ea00e

Comment by Timothy Olsen (Inactive) [ 22/Oct/15 ]

Problem appears to only occur if journaling is disabled. With journaling enabled, I was able to do 5 automated wiredTiger SCCC -> CSRS conversions without any problems.

Comment by Timothy Olsen (Inactive) [ 21/Oct/15 ]

btw, this is with commit dbbc9a2e3d8c4d7fe1748fa980ba7d01b9489dbe

Comment by Timothy Olsen (Inactive) [ 21/Oct/15 ]

logs attached

Comment by Timothy Olsen (Inactive) [ 21/Oct/15 ]

I am still seeing this happen, although now only about 60% of the time rather than 100% of the time. This only happens in an automated scenario. Efforts to reproduce this manually fail. This leads me to believe a race is being triggered in the automated situation because the shutdown of the config server happens so quickly after the rs.initiate().

Should we reopen this ticket or open a new one? Regardless, I will attach logs now

Comment by Githook User [ 13/Oct/15 ]

Author:

{u'username': u'andy10gen', u'name': u'Andy Schwerin', u'email': u'schwerin@mongodb.com'}

Message: SERVER-20856 Reset oplog subsystem during oplog creation.

This manual resetting allows creation of a replica set oplog while the
system is in the master mode of master/slave replication.
Branch: master
https://github.com/mongodb/mongo/commit/f4758493ee3803cdc7296ecedfcced98a5d3de35

Comment by Andy Schwerin [ 13/Oct/15 ]

Well, I found a way that we might be able to continue to use _logOp for initializing the oplog when you run replSetInitiate on a node started without --replSet. On the assumption that it doesn't happen all the time, we can just reset the oplog.cpp internal state that caches the Collection object for the oplog.

Comment by Andy Schwerin [ 13/Oct/15 ]

I think this problem arose because repl::_logOp should not be a publicly exposed method in oplog.h. It can only really be called by logOp(), and should be a private function inside of oplog.cpp.

Comment by Scott Hernandez (Inactive) [ 09/Oct/15 ]

nvm, repro'd it.

Both the oplog.rs and oplog.$main collections are created which means that the server is slightly confused about the "active" replication system.

To get around this issue one would need to copy all/the-last oplog entries from local.oplog.$main to local.oplog.rs before restarting as a replica set member.

Comment by Scott Hernandez (Inactive) [ 09/Oct/15 ]

Did you check the result of the rs.initiate() call to make it didn't error? If you have that log, please post it.

To answer your question, yes an oplog is created when you run rs.initiate() in non-replica-set-mode. There should be a single entry like this:

{
    "ts" : Timestamp(1444428860, 1),
    "t" : NumberLong(0),
    "h" : NumberLong("-7927359185622268299"), 
    "v" : 2, "op" : "n", "ns" : "", "o" : { "msg" : "initiating set"}
}

We will see if we can repro this.

Comment by Timothy Olsen (Inactive) [ 09/Oct/15 ]

This is during the CSRS upgrade procedure as outlined in https://docs.google.com/document/d/1Ic8NLIX-uiR_1_4HBdURFmhpgb3QsVH3gUdHoHmEVag/edit# . This happens during the step 'Restart “first” config server as a standalone replica set'

There are no other members nor do I believe there are expected to be any at this stage of the CSRS upgrade procedure.

I did not explicitly delete the oplog. I do not know if it is expected that there not be an oplog at this part of the upgrade procedure.

Log file before the restart:

2015-10-09T17:40:38.629-0400 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=9G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] MongoDB starting : pid=29149 port=27019 dbpath=db1 master=1 64-bit host=neurofunk.local
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] 
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] ** NOTE: This is a development version (3.1.9) of MongoDB.
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] **       Not recommended for production.
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] 
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] 
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] db version v3.1.9
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] git version: 9c317d92145a77ab582acb215b3ed41af2f1b33c
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] allocator: system
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] modules: none
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] build environment:
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten]     distarch: x86_64
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten]     target_arch: x86_64
2015-10-09T17:40:38.891-0400 I CONTROL  [initandlisten] options: { sharding: { clusterRole: "configsvr" }, storage: { dbPath: "db1" } }
2015-10-09T17:40:38.911-0400 I REPL     [initandlisten] ******
2015-10-09T17:40:38.912-0400 I REPL     [initandlisten] creating replication oplog of size: 5MB...
2015-10-09T17:40:38.921-0400 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.$main
2015-10-09T17:40:38.921-0400 I STORAGE  [initandlisten] Scanning the oplog to determine where to place markers for when to truncate
2015-10-09T17:40:38.992-0400 I REPL     [initandlisten] ******
2015-10-09T17:40:38.993-0400 I FTDC     [initandlisten] Starting full-time diagnostic data capture with directory 'db1/diagnostic.data'
2015-10-09T17:40:39.086-0400 I NETWORK  [initandlisten] waiting for connections on port 27019
2015-10-09T17:40:43.666-0400 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:54256 #1 (1 connection now open)
2015-10-09T17:41:02.441-0400 I REPL     [conn1] replSetInitiate admin command received from client
2015-10-09T17:41:02.441-0400 I REPL     [conn1] replSetInitiate config object with 1 members parses ok
2015-10-09T17:41:02.465-0400 I REPL     [conn1] ******
2015-10-09T17:41:02.465-0400 I REPL     [conn1] creating replication oplog of size: 5MB...
2015-10-09T17:41:02.477-0400 I STORAGE  [conn1] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-10-09T17:41:02.478-0400 I STORAGE  [conn1] Scanning the oplog to determine where to place markers for when to truncate
2015-10-09T17:41:02.594-0400 I REPL     [conn1] ******
2015-10-09T17:41:02.594-0400 I COMMAND  [conn1] command local.oplog.rs command: replSetInitiate { replSetInitiate: { _id: "csrs", version: 1.0, configsvr: true, members: [ { _id: 0.0, host: "neurofunk.local:27019" } ] } } ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:0 reslen:37 locks:{ Global: { acquireCount: { r: 7, w: 3, W: 2 }, acquireWaitCount: { W: 1 }, timeAcquiringMicros: { W: 29 } }, Database: { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { r: 1 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_query 153ms
^C2015-10-09T17:41:08.240-0400 I CONTROL  [signalProcessingThread] got signal 2 (Interrupt: 2), will terminate after current cmd ends
2015-10-09T17:41:08.240-0400 I FTDC     [signalProcessingThread] Stopping full-time diagnostic data capture
2015-10-09T17:41:08.242-0400 I CONTROL  [signalProcessingThread] now exiting
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] closing listening socket: 5
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] closing listening socket: 6
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] removing socket file: /tmp/mongodb-27019.sock
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] shutdown: going to flush diaglog...
2015-10-09T17:41:08.242-0400 I NETWORK  [signalProcessingThread] shutdown: going to close sockets...
2015-10-09T17:41:08.242-0400 I STORAGE  [signalProcessingThread] WiredTigerKVEngine shutting down
2015-10-09T17:41:08.242-0400 I NETWORK  [conn1] end connection 127.0.0.1:54256 (0 connections now open)
2015-10-09T17:41:08.315-0400 I STORAGE  [signalProcessingThread] shutdown: removing fs lock...
2015-10-09T17:41:08.315-0400 I CONTROL  [signalProcessingThread] dbexit:  rc: 0

Comment by Scott Hernandez (Inactive) [ 09/Oct/15 ]

Please upload all logs from this node, like before this restart.

Are there other members of this replica set, because the config doesn't show them? If so, can you provide those logs as well?

This node seems to not have an oplog, is that expected? Was it deleted?

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