Closed ShaneHarvey closed 6 years ago
This is what is happening:
2018-03-08T21:35:16.137+0000 W NETWORK [mongosMain] Unable to reach primary for set 82477b90-45d1-4735-ac9d-716451b6de27
2018-03-08T21:35:16.137+0000 W SHARDING [mongosMain] Error initializing sharding state, sleeping for 2 seconds and trying again :: caused by :: FailedToSatisfyReadPreference: Error loading clusterID :: caused by :: Could not find host matching read preference { mode: "nearest" } for set 82477b90-45d1-4735-ac9d-716451b6de27
2018-03-08T21:35:17.637+0000 W NETWORK [monitoring keys for HMAC] Unable to reach primary for set 82477b90-45d1-4735-ac9d-716451b6de27
2018-03-08T21:30:20.155+0000 I CONTROL [initandlisten] MongoDB starting : pid=4356 port=1026 dbpath=c:\data\mci\e6b1ac2cfdd9de0d54190699bf232fa8\drivers-tools\.evergreen\orchestration\db\mongo-awz0ms 64-bit host=WIN-HS26LRPTD0B
2018-03-08T21:30:20.155+0000 I CONTROL [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2018-03-08T21:30:20.155+0000 I CONTROL [initandlisten] db version v3.7.2-336-g5246bebdbc
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] git version: 5246bebdbc9eead3420e5bef1a1687bab2c47399
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1u-fips 22 Sep 2016
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] allocator: tcmalloc
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] modules: enterprise
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] build environment:
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] distmod: windows-64
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] distarch: x86_64
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] target_arch: x86_64
2018-03-08T21:30:20.156+0000 I CONTROL [initandlisten] options: { config: "c:\data\mci\e6b1ac2cfdd9de0d54190699bf232fa8\drivers-tools\.evergreen\orchestration\db\mongo-j8ma5n", net: { bindIp: "127.0.0.1", compression: { compressors: "zlib,snappy,noop" }, port: 1026 }, replication: { enableMajorityReadConcern: true, oplogSizeMB: 100, replSet: "82477b90-45d1-4735-ac9d-716451b6de27" }, setParameter: { enableTestCommands: "1" }, sharding: { clusterRole: "configsvr" }, storage: { dbPath: "c:\data\mci\e6b1ac2cfdd9de0d54190699bf232fa8\drivers-tools\.evergreen\orchestration\db\mongo-awz0ms" }, systemLog: { destination: "file", path: "c:\data\mci\e6b1ac2cfdd9de0d54190699bf232fa8\drivers-tools\.evergreen\orchestration\db\mongo-awz0ms\mongod.log" } }
2018-03-08T21:30:20.157+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=3327M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten]
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten] ** NOTE: This is a development version (3.7.2-336-g5246bebdbc) of MongoDB.
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten] ** Not recommended for production.
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten]
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten]
2018-03-08T21:30:20.224+0000 I CONTROL [initandlisten]
2018-03-08T21:30:20.225+0000 I CONTROL [initandlisten] ** WARNING: The file system cache of this machine is configured to be greater than 40% of the total memory. This can lead to increased memory pressure and poor performance.
2018-03-08T21:30:20.225+0000 I CONTROL [initandlisten] See http://dochub.mongodb.org/core/wt-windows-system-file-cache
2018-03-08T21:30:20.225+0000 I CONTROL [initandlisten]
2018-03-08T21:30:20.230+0000 I STORAGE [initandlisten] createCollection: local.startup_log with generated UUID: 647d0ac1-9c79-49f6-ac31-ab365a0cff40
2018-03-08T21:30:21.366+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory 'c:/data/mci/e6b1ac2cfdd9de0d54190699bf232fa8/drivers-tools/.evergreen/orchestration/db/mongo-awz0ms/diagnostic.data'
2018-03-08T21:30:21.366+0000 I SHARDING [initandlisten] first cluster operation detected, adding sharding hook to enable versioning and authentication to remote servers
2018-03-08T21:30:21.367+0000 I SHARDING [thread1] creating distributed lock ping thread for process ConfigServer (sleeping for 30000ms)
2018-03-08T21:30:21.367+0000 I SHARDING [shard registry reload] Periodic reload of shard registry failed :: caused by :: ReadConcernMajorityNotAvailableYet: could not get updated shard list from config server :: caused by :: Read concern majority reads are currently not possible.; will retry after 30s
2018-03-08T21:30:21.368+0000 I STORAGE [initandlisten] createCollection: local.me with generated UUID: 2bbcf5b3-2810-42a1-b7c2-3026225f5a37
2018-03-08T21:30:21.377+0000 I STORAGE [initandlisten] createCollection: local.replset.oplogTruncateAfterPoint with generated UUID: 333a58ac-b829-4be5-97f5-729c471a4473
2018-03-08T21:30:21.387+0000 I STORAGE [initandlisten] createCollection: local.replset.minvalid with generated UUID: 3e52fba2-c5ca-480a-8d8c-f9c134514960
2018-03-08T21:30:21.398+0000 I STORAGE [initandlisten] createCollection: local.replset.checkpointTimestamp with generated UUID: a9057513-eaf9-40d9-969f-b62b955ee863
2018-03-08T21:30:21.406+0000 I REPL [initandlisten] Did not find local voted for document at startup.
2018-03-08T21:30:21.406+0000 I REPL [initandlisten] Did not find local Rollback ID document at startup. Creating one.
2018-03-08T21:30:21.406+0000 I STORAGE [initandlisten] createCollection: local.system.rollback.id with generated UUID: f697b780-6026-4c41-b393-be29758af92a
2018-03-08T21:30:21.419+0000 I REPL [initandlisten] Initialized the rollback ID to 1
2018-03-08T21:30:21.419+0000 I REPL [initandlisten] Did not find local replica set configuration document at startup; NoMatchingDocument: Did not find replica set configuration document in local.system.replset
2018-03-08T21:30:21.420+0000 I NETWORK [initandlisten] waiting for connections on port 1026
2018-03-08T21:30:21.432+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50728 #1 (1 connection now open)
2018-03-08T21:30:21.432+0000 I NETWORK [conn1] end connection 127.0.0.1:50728 (0 connections now open)
2018-03-08T21:30:21.434+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50729 #2 (1 connection now open)
2018-03-08T21:30:21.434+0000 I NETWORK [conn2] received client metadata from 127.0.0.1:50729 conn2: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.437+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50730 #3 (2 connections now open)
2018-03-08T21:30:21.437+0000 I NETWORK [conn3] received client metadata from 127.0.0.1:50730 conn3: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.438+0000 I NETWORK [conn3] end connection 127.0.0.1:50730 (1 connection now open)
2018-03-08T21:30:21.438+0000 I NETWORK [conn2] end connection 127.0.0.1:50729 (0 connections now open)
2018-03-08T21:30:21.439+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50731 #4 (1 connection now open)
2018-03-08T21:30:21.440+0000 I NETWORK [conn4] received client metadata from 127.0.0.1:50731 conn4: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.442+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50732 #5 (2 connections now open)
2018-03-08T21:30:21.442+0000 I NETWORK [conn5] received client metadata from 127.0.0.1:50732 conn5: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.443+0000 I NETWORK [conn5] end connection 127.0.0.1:50732 (1 connection now open)
2018-03-08T21:30:21.443+0000 I NETWORK [conn4] end connection 127.0.0.1:50731 (0 connections now open)
2018-03-08T21:30:21.445+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50733 #6 (1 connection now open)
2018-03-08T21:30:21.445+0000 I NETWORK [conn6] received client metadata from 127.0.0.1:50733 conn6: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.446+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50734 #7 (2 connections now open)
2018-03-08T21:30:21.446+0000 I NETWORK [conn7] received client metadata from 127.0.0.1:50734 conn7: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.447+0000 I REPL [conn7] replSetInitiate admin command received from client
2018-03-08T21:30:21.448+0000 I REPL [conn7] replSetInitiate config object with 1 members parses ok
2018-03-08T21:30:21.448+0000 I REPL [conn7] ******
2018-03-08T21:30:21.448+0000 I REPL [conn7] creating replication oplog of size: 100MB...
2018-03-08T21:30:21.448+0000 I STORAGE [conn7] createCollection: local.oplog.rs with generated UUID: de930573-3633-4144-a80d-1b0296239897
2018-03-08T21:30:21.454+0000 I STORAGE [conn7] Starting WiredTigerRecordStoreThread local.oplog.rs
2018-03-08T21:30:21.454+0000 I STORAGE [conn7] The size storer reports that the oplog contains 0 records totaling to 0 bytes
2018-03-08T21:30:21.454+0000 I STORAGE [conn7] Scanning the oplog to determine where to place markers for truncation
2018-03-08T21:30:21.490+0000 I REPL [conn7] ******
2018-03-08T21:30:21.490+0000 I STORAGE [conn7] createCollection: local.system.replset with generated UUID: 22b5364d-282f-47f5-9bb3-193cf064bf12
2018-03-08T21:30:21.602+0000 I STORAGE [conn7] createCollection: admin.system.version with provided UUID: 35aeb2a5-2eff-4034-bf70-8cfaf9a9804f
2018-03-08T21:30:21.622+0000 I COMMAND [conn7] setting featureCompatibilityVersion to 4.0
2018-03-08T21:30:21.622+0000 I NETWORK [conn7] Skip closing connection for connection # 7
2018-03-08T21:30:21.622+0000 I NETWORK [conn7] Skip closing connection for connection # 6
2018-03-08T21:30:21.622+0000 I REPL [conn7] New replica set config in use: { _id: "82477b90-45d1-4735-ac9d-716451b6de27", version: 1, configsvr: true, protocolVersion: 1, members: [ { _id: 0, host: "localhost:1026", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, catchUpTimeoutMillis: -1, catchUpTakeoverDelayMillis: 30000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('5aa1ab6d4d087b6c638cffe3') } }
2018-03-08T21:30:21.622+0000 I REPL [conn7] This node is localhost:1026 in the config
2018-03-08T21:30:21.622+0000 I REPL [conn7] transition to STARTUP2 from STARTUP
2018-03-08T21:30:21.622+0000 I REPL [conn7] Starting replication storage threads
2018-03-08T21:30:21.626+0000 I REPL [conn7] transition to RECOVERING from STARTUP2
2018-03-08T21:30:21.626+0000 I REPL [conn7] Starting replication fetcher thread
2018-03-08T21:30:21.626+0000 I REPL [conn7] Starting replication applier thread
2018-03-08T21:30:21.626+0000 I REPL [conn7] Starting replication reporter thread
2018-03-08T21:30:21.626+0000 I COMMAND [conn7] command local.system.replset command: replSetInitiate { replSetInitiate: { _id: "82477b90-45d1-4735-ac9d-716451b6de27", members: [ { host: "localhost:1026", _id: 0 } ] }, $readPreference: { mode: "secondaryPreferred" }, $db: "admin" } numYields:0 reslen:251 locks:{ Global: { acquireCount: { r: 15, w: 7, W: 2 }, acquireWaitCount: { W: 1 }, timeAcquiringMicros: { W: 47 } }, Database: { acquireCount: { r: 3, w: 4, W: 3 } }, Collection: { acquireCount: { r: 1, w: 2 } }, oplog: { acquireCount: { r: 2, w: 3 } } } protocol:op_query 179ms
2018-03-08T21:30:21.627+0000 I NETWORK [conn7] end connection 127.0.0.1:50734 (1 connection now open)
2018-03-08T21:30:21.627+0000 I NETWORK [conn6] end connection 127.0.0.1:50733 (0 connections now open)
2018-03-08T21:30:21.628+0000 I REPL [rsSync] transition to SECONDARY from RECOVERING
2018-03-08T21:30:21.628+0000 I REPL [rsSync] conducting a dry run election to see if we could be elected. current term: 0
2018-03-08T21:30:21.629+0000 I REPL [replexec-0] dry election run succeeded, running for election in term 1
2018-03-08T21:30:21.629+0000 I STORAGE [replexec-1] createCollection: local.replset.election with generated UUID: 95a5a630-0129-4246-86eb-7932e8fe67a3
2018-03-08T21:30:21.629+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50735 #8 (1 connection now open)
2018-03-08T21:30:21.630+0000 I NETWORK [conn8] received client metadata from 127.0.0.1:50735 conn8: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:21.646+0000 I REPL [replexec-1] election succeeded, assuming primary role in term 1
2018-03-08T21:30:21.646+0000 I REPL [replexec-1] transition to PRIMARY from SECONDARY
2018-03-08T21:30:21.647+0000 I REPL [replexec-1] Entering primary catch-up mode.
2018-03-08T21:30:21.647+0000 I REPL [replexec-1] Exited primary catch-up mode.
2018-03-08T21:30:23.629+0000 I STORAGE [rsSync] createCollection: config.chunks with generated UUID: d4378fb9-464f-45f7-b156-a98b7bafbd0e
2018-03-08T21:30:23.651+0000 I INDEX [rsSync] build index on: config.chunks properties: { v: 2, unique: true, key: { ns: 1, min: 1 }, name: "ns_1_min_1", ns: "config.chunks" }
2018-03-08T21:30:23.651+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.654+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.661+0000 I INDEX [rsSync] build index on: config.chunks properties: { v: 2, unique: true, key: { ns: 1, shard: 1, min: 1 }, name: "ns_1_shard_1_min_1", ns: "config.chunks" }
2018-03-08T21:30:23.661+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.665+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.670+0000 I INDEX [rsSync] build index on: config.chunks properties: { v: 2, unique: true, key: { ns: 1, lastmod: 1 }, name: "ns_1_lastmod_1", ns: "config.chunks" }
2018-03-08T21:30:23.670+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.673+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.673+0000 I STORAGE [rsSync] createCollection: config.migrations with generated UUID: 28b2844c-5a9a-49af-a26c-0430b2930175
2018-03-08T21:30:23.691+0000 I INDEX [rsSync] build index on: config.migrations properties: { v: 2, unique: true, key: { ns: 1, min: 1 }, name: "ns_1_min_1", ns: "config.migrations" }
2018-03-08T21:30:23.691+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.694+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.694+0000 I STORAGE [rsSync] createCollection: config.shards with generated UUID: 96b4d7d6-2f15-4e54-b373-520bfb48844f
2018-03-08T21:30:23.709+0000 I INDEX [rsSync] build index on: config.shards properties: { v: 2, unique: true, key: { host: 1 }, name: "host_1", ns: "config.shards" }
2018-03-08T21:30:23.709+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.710+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.710+0000 I STORAGE [rsSync] createCollection: config.locks with generated UUID: b30b523b-5466-4bca-ab96-7bc926132e1c
2018-03-08T21:30:23.729+0000 I INDEX [rsSync] build index on: config.locks properties: { v: 2, key: { ts: 1 }, name: "ts_1", ns: "config.locks" }
2018-03-08T21:30:23.729+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.731+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.737+0000 I INDEX [rsSync] build index on: config.locks properties: { v: 2, key: { state: 1, process: 1 }, name: "state_1_process_1", ns: "config.locks" }
2018-03-08T21:30:23.737+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.739+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.739+0000 I STORAGE [rsSync] createCollection: config.lockpings with generated UUID: f101a5cb-6d0d-48a2-8afd-31dffed7b936
2018-03-08T21:30:23.753+0000 I INDEX [rsSync] build index on: config.lockpings properties: { v: 2, key: { ping: 1 }, name: "ping_1", ns: "config.lockpings" }
2018-03-08T21:30:23.753+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.756+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.756+0000 I STORAGE [rsSync] createCollection: config.tags with generated UUID: 98ea6dad-acef-4db8-9af5-cc197ebdfce2
2018-03-08T21:30:23.775+0000 I INDEX [rsSync] build index on: config.tags properties: { v: 2, unique: true, key: { ns: 1, min: 1 }, name: "ns_1_min_1", ns: "config.tags" }
2018-03-08T21:30:23.775+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.777+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.783+0000 I INDEX [rsSync] build index on: config.tags properties: { v: 2, key: { ns: 1, tag: 1 }, name: "ns_1_tag_1", ns: "config.tags" }
2018-03-08T21:30:23.783+0000 I INDEX [rsSync] building index using bulk method; build may temporarily use up to 500 megabytes of RAM
2018-03-08T21:30:23.785+0000 I INDEX [rsSync] build index done. scanned 0 total records. 0 secs
2018-03-08T21:30:23.787+0000 I STORAGE [rsSync] createCollection: config.version with generated UUID: 58372532-0d91-4b45-99be-8196184b96e6
2018-03-08T21:30:23.800+0000 I SHARDING [Balancer] CSRS balancer is starting
2018-03-08T21:30:23.800+0000 I STORAGE [rsSync] createCollection: config.transactions with generated UUID: ef09bb36-b7e2-4790-aca1-c0f01a5f4f26
2018-03-08T21:30:23.815+0000 I STORAGE [rsSync] Triggering the first stable checkpoint. Initial Data: Timestamp(1520544621, 1) PrevStable: Timestamp(0, 0) CurrStable: Timestamp(1520544623, 10)
2018-03-08T21:30:23.815+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2018-03-08T21:30:23.832+0000 I SHARDING [Balancer] CSRS balancer thread is recovering
2018-03-08T21:30:23.832+0000 I SHARDING [Balancer] CSRS balancer thread is recovered
2018-03-08T21:30:23.832+0000 I STORAGE [monitoring keys for HMAC] createCollection: admin.system.keys with generated UUID: 4a8aa8db-df91-4197-9f4d-b3a77cd767ab
2018-03-08T21:30:24.133+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50736 #9 (2 connections now open)
2018-03-08T21:30:24.134+0000 I NETWORK [conn9] received client metadata from 127.0.0.1:50736 conn9: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.134+0000 I NETWORK [conn9] end connection 127.0.0.1:50736 (1 connection now open)
2018-03-08T21:30:24.134+0000 I NETWORK [conn8] end connection 127.0.0.1:50735 (0 connections now open)
2018-03-08T21:30:24.136+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50737 #10 (1 connection now open)
2018-03-08T21:30:24.136+0000 I NETWORK [conn10] received client metadata from 127.0.0.1:50737 conn10: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.139+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50738 #11 (2 connections now open)
2018-03-08T21:30:24.139+0000 I NETWORK [conn11] received client metadata from 127.0.0.1:50738 conn11: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.140+0000 I NETWORK [conn11] end connection 127.0.0.1:50738 (1 connection now open)
2018-03-08T21:30:24.140+0000 I NETWORK [conn10] end connection 127.0.0.1:50737 (0 connections now open)
2018-03-08T21:30:24.142+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50739 #12 (1 connection now open)
2018-03-08T21:30:24.142+0000 I NETWORK [conn12] received client metadata from 127.0.0.1:50739 conn12: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.144+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50740 #13 (2 connections now open)
2018-03-08T21:30:24.144+0000 I NETWORK [conn13] received client metadata from 127.0.0.1:50740 conn13: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.145+0000 I NETWORK [conn13] end connection 127.0.0.1:50740 (1 connection now open)
2018-03-08T21:30:24.145+0000 I NETWORK [conn12] end connection 127.0.0.1:50739 (0 connections now open)
2018-03-08T21:30:24.147+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50741 #14 (1 connection now open)
2018-03-08T21:30:24.147+0000 I NETWORK [conn14] received client metadata from 127.0.0.1:50741 conn14: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.148+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50742 #15 (2 connections now open)
2018-03-08T21:30:24.148+0000 I NETWORK [conn15] received client metadata from 127.0.0.1:50742 conn15: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.150+0000 I NETWORK [conn15] end connection 127.0.0.1:50742 (1 connection now open)
2018-03-08T21:30:24.150+0000 I NETWORK [conn14] end connection 127.0.0.1:50741 (0 connections now open)
2018-03-08T21:30:24.153+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50743 #16 (1 connection now open)
2018-03-08T21:30:24.153+0000 I NETWORK [conn16] received client metadata from 127.0.0.1:50743 conn16: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.156+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50744 #17 (2 connections now open)
2018-03-08T21:30:24.156+0000 I NETWORK [conn17] received client metadata from 127.0.0.1:50744 conn17: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.157+0000 I NETWORK [conn17] end connection 127.0.0.1:50744 (1 connection now open)
2018-03-08T21:30:24.157+0000 I NETWORK [conn16] end connection 127.0.0.1:50743 (0 connections now open)
2018-03-08T21:30:24.159+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50745 #18 (1 connection now open)
2018-03-08T21:30:24.159+0000 I NETWORK [conn18] received client metadata from 127.0.0.1:50745 conn18: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.160+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50746 #19 (2 connections now open)
2018-03-08T21:30:24.160+0000 I NETWORK [conn19] received client metadata from 127.0.0.1:50746 conn19: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.161+0000 I NETWORK [conn19] end connection 127.0.0.1:50746 (1 connection now open)
2018-03-08T21:30:24.161+0000 I NETWORK [conn18] end connection 127.0.0.1:50745 (0 connections now open)
2018-03-08T21:30:24.162+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50747 #20 (1 connection now open)
2018-03-08T21:30:24.162+0000 I NETWORK [conn20] received client metadata from 127.0.0.1:50747 conn20: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.165+0000 I NETWORK [listener] connection accepted from 127.0.0.1:50748 #21 (2 connections now open)
2018-03-08T21:30:24.165+0000 I NETWORK [conn21] received client metadata from 127.0.0.1:50748 conn21: { driver: { name: "PyMongo", version: "3.5.1" }, os: { type: "Windows", name: "Windows 2008ServerR2", architecture: "AMD64", version: "6.1.7601-SP1" }, platform: "CPython 2.7.3.final.0" }
2018-03-08T21:30:24.166+0000 I NETWORK [conn21] end connection 127.0.0.1:50748 (1 connection now open)
2018-03-08T21:30:24.166+0000 I NETWORK [conn20] end connection 127.0.0.1:50747 (0 connections now open)
2018-03-08T21:30:43.819+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:30:51.379+0000 W SHARDING [replSetDistLockPinger] pinging failed for distributed lock pinger :: caused by :: LockStateChangeFailed: findAndModify query predicate didn't match any lock document
2018-03-08T21:31:03.823+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:31:13.825+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:31:33.829+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:31:43.831+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:32:03.835+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:32:13.837+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:32:33.841+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:32:43.843+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:33:03.847+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:33:13.849+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:33:33.853+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:33:43.855+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:34:03.859+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:34:13.861+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:34:33.865+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:34:43.867+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:35:03.871+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:35:13.873+0000 I REPL [NoopWriter] Writing noop to oplog as there has been no writes to this replica set in over 10s
2018-03-08T21:35:21.480+0000 I CONTROL [thread23] Failed to create config.system.sessions: Cannot create config.system.sessions until there are shards, will try again at the next refresh interval
2018-03-08T21:35:21.480+0000 I CONTROL [thread23] Sessions collection is not set up; waiting until next sessions refresh interval: Cannot create config.system.sessions until there are shards
This looks like it could be a bug in the latest build of the server.
Here's mongos failing to connect to the config server with a higher log level:
3-09T11:51:39.979-0800 D NETWORK [monitoring keys for HMAC] Starting new refresh of replica set 561b1476-7e06-4a37-a2e0-5eedfa80d336
2018-03-09T11:51:39.980-0800 D NETWORK [monitoring keys for HMAC] creating new connection to:localhost:1026
2018-03-09T11:51:39.981-0800 D - [monitoring keys for HMAC] User Assertion: Location40356: connection pool: connect failed localhost:1026 : couldn't connect to server localhost:1026, connection attempt failed: SocketException: Connection refused src/mongo/client/connpool.cpp 394
2018-03-09T11:51:39.981-0800 W NETWORK [monitoring keys for HMAC] Unable to reach primary for set 561b1476-7e06-4a37-a2e0-5eedfa80d336
2018-03-09T11:51:40.049-0800 D NETWORK [mongosMain] Starting new refresh of replica set 561b1476-7e06-4a37-a2e0-5eedfa80d336
2018-03-09T11:51:40.049-0800 D NETWORK [mongosMain] creating new connection to:localhost:1026
2018-03-09T11:51:40.050-0800 D - [mongosMain] User Assertion: Location40356: connection pool: connect failed localhost:1026 : couldn't connect to server localhost:1026, connection attempt failed: SocketException: Connection refused src/mongo/client/connpool.cpp 394
2018-03-09T11:51:40.050-0800 W NETWORK [mongosMain] Unable to reach primary for set 561b1476-7e06-4a37-a2e0-5eedfa80d336
2018-03-09T11:51:40.050-0800 I NETWORK [mongosMain] Cannot reach any nodes for set 561b1476-7e06-4a37-a2e0-5eedfa80d336. Please check network connectivity and the status of the set. This has happened for 141 checks in a row.
Opened https://jira.mongodb.org/browse/SERVER-33790 as this looks like a server bug.
mongos 3.7 latest fails to start on Windows and Mac:
The full MO (and mongos) log is shown below: