[SERVER-19231] Enabling user authentication with keyfile and WT engine causes mongo instance crash randomly Created: 30/Jun/15  Updated: 09/Jul/15  Resolved: 09/Jul/15

Status: Closed
Project: Core Server
Component/s: Replication, Security
Affects Version/s: 3.0.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Justin Liu Assignee: Andreas Nilsson
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

1. deploy 3.0.4 with WiredTiger storage engine
2. setup a 3-nodes replicas
3. enable the user authentication using keyfile
4. login mongo with db.auth("root","root-password")
5. after that, if we type a wrong command or trying to do anything, the mongo instance will crash randomly.

Sprint: Security 6 07/17/15
Participants:

 Description   

The user authentication works correctly on 2.6.1.
But, the mongo instance will crash randomly on 3.0.4 with wiredTiger storage engine when I enable the user authentication with keyfile on 3-nodes replica set. With wrong command or invalid user passoword, the mongo instance will crash.
If I disable the user authentication, the mongo cluster will work correctly again.



 Comments   
Comment by Andreas Nilsson [ 09/Jul/15 ]

Hi Justin,

I'm sorry but I am unable to reproduce this problem. I will go ahead and close the ticket.

Feel free to file a ticket in the MongoDB user group https://groups.google.com/forum/#!forum/mongodb-user or our Commercial Support project to get further assistance!

Regards,
Andreas

Comment by Justin Liu [ 02/Jul/15 ]

1. we are using the "service mongodb start/stop/restart" to start or stop the mongod.
2. I remove the --rest flag from the config file. But the problem is still the same unless I remove the keyfile entry.

Comment by Andreas Nilsson [ 02/Jul/15 ]

justin.liu@turner.com looking closer at the logs it seems that the server is being terminated and restarted on a "regular" basis. This looks a little suspicious. See for instance the log line:

2015-07-01T14:02:13.397+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends

Apparently the server repeatedly receives a SIGTERM for some reason. Could you provide the script you are using to start the servers.

Another observation is that the server is started with the rest interface enabled, this shouldn't affect the stability of the server but it could be interesting to do an attempt without the --rest flag.

Thanks for your patience.
Andreas

Comment by Justin Liu [ 01/Jul/15 ]

1. Here is the log of 10.60.184.177
2. Yes, if I remove the keyFile entry from the config file, everything works correctly.

Thanks
Justin
-------------------
2015-07-01T14:01:01.270+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:01.270+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:01.271+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:01.271+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:01.272+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:01.272+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:03.274+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:03.274+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:03.274+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:03.275+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:03.275+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:03.275+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:03.562+0000 I NETWORK [conn5] end connection 10.60.188.80:37228 (0 connections now open)
2015-07-01T14:01:03.562+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37234 #7 (1 connection now open)
2015-07-01T14:01:03.575+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:01:05.276+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:05.276+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:05.277+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:05.277+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:05.278+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:05.278+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:07.279+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:07.279+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:07.280+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:07.280+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:07.281+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:01:07.281+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:01:07.632+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:21965 #8 (2 connections now open)
2015-07-01T14:01:07.645+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:01:07.647+0000 I NETWORK [conn8] end connection 10.60.186.180:21965 (1 connection now open)
2015-07-01T14:01:07.664+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:21967 #9 (2 connections now open)
2015-07-01T14:01:07.678+0000 I ACCESS [conn9] Successfully authenticated as principal __system on local
2015-07-01T14:01:08.024+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:01:08.024+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:01:08.043+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:01:08.210+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:01:08.210+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:01:08.210+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:01:08.210+0000 I NETWORK [conn9] end connection 10.60.186.180:21967 (1 connection now open)
2015-07-01T14:01:08.210+0000 I NETWORK [conn7] end connection 10.60.188.80:37234 (1 connection now open)
2015-07-01T14:01:08.431+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:01:08.431+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:01:08.535+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:01:08.535+0000 I CONTROL ** enabling http interface
2015-07-01T14:01:08.570+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:01:14.422+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] MongoDB starting : pid=25866 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten]
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten]
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten]
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten]
2015-07-01T14:01:14.472+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:01:14.473+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:01:14.473+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:01:14.473+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:01:14.473+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:01:14.473+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:01:14.475+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:01:14.475+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:01:14.506+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:01:14.506+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:01:14.506+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:01:14.506+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:01:14.507+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:01:14.507+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:01:14.522+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:01:14.523+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:01:14.524+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.186.180:27017 is already primary and more up-to-date'
2015-07-01T14:01:14.524+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:01:14.528+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state PRIMARY
2015-07-01T14:01:15.588+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37254 #1 (1 connection now open)
2015-07-01T14:01:15.602+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:01:15.698+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:21977 #2 (2 connections now open)
2015-07-01T14:01:15.711+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:01:15.759+0000 I NETWORK [initandlisten] connection accepted from 127.0.0.1:46595 #3 (3 connections now open)
2015-07-01T14:01:15.761+0000 I ACCESS [conn3] Unauthorized not authorized on admin to execute command

{ getLog: "startupWarnings" }

2015-07-01T14:01:15.762+0000 I ACCESS [conn3] Unauthorized not authorized on admin to execute command

{ replSetGetStatus: 1.0, forShell: 1.0 }

2015-07-01T14:01:28.151+0000 I ACCESS [conn3] Successfully authenticated as principal root on admin
2015-07-01T14:01:34.532+0000 I NETWORK [ReplExecNetThread-2] DBClientCursor::init call() failed
2015-07-01T14:01:34.532+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:01:34.538+0000 I NETWORK [ReplExecNetThread-0] Socket recv() errno:104 Connection reset by peer 10.60.188.80:27017
2015-07-01T14:01:34.538+0000 I NETWORK [ReplExecNetThread-0] SocketException: remote: 10.60.188.80:27017 error: 9001 socket exception [RECV_ERROR] server [10.60.188.80:27017]
2015-07-01T14:01:34.538+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:01:34.538+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: local.$cmd query:

{ saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D5F5F73797374656D2C723D4B745464787243625630544D762B7043753042616A7968446456666C45353265) }

2015-07-01T14:01:34.538+0000 I NETWORK [conn1] end connection 10.60.188.80:37254 (2 connections now open)
2015-07-01T14:01:34.539+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:34.539+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:36.540+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:36.541+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:36.541+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:36.541+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:36.542+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:36.542+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:36.678+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37270 #4 (3 connections now open)
2015-07-01T14:01:36.692+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:01:36.693+0000 I NETWORK [conn4] end connection 10.60.188.80:37270 (2 connections now open)
2015-07-01T14:01:36.710+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37272 #5 (3 connections now open)
2015-07-01T14:01:36.734+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:01:38.557+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:01:45.727+0000 I NETWORK [conn2] end connection 10.60.186.180:21977 (2 connections now open)
2015-07-01T14:01:45.728+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:21982 #6 (3 connections now open)
2015-07-01T14:01:45.742+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:02:03.678+0000 I NETWORK [conn6] end connection 10.60.186.180:21982 (2 connections now open)
2015-07-01T14:02:04.569+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:02:04.570+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:02:04.571+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:04.571+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:04.571+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:04.571+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:04.572+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:02:04.572+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.186.180:27017 is already primary and more up-to-date'
2015-07-01T14:02:04.572+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:02:04.803+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:02:06.571+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:06.572+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:06.572+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:02:06.572+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:06.572+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:06.573+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:06.573+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:06.749+0000 I NETWORK [conn5] end connection 10.60.188.80:37272 (1 connection now open)
2015-07-01T14:02:06.749+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37278 #7 (2 connections now open)
2015-07-01T14:02:06.763+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:02:08.574+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:08.574+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:08.575+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:08.575+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:08.577+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:02:08.577+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:02:10.367+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22000 #8 (3 connections now open)
2015-07-01T14:02:10.381+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:02:10.382+0000 I NETWORK [conn8] end connection 10.60.186.180:22000 (2 connections now open)
2015-07-01T14:02:10.398+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22002 #9 (3 connections now open)
2015-07-01T14:02:10.423+0000 I ACCESS [conn9] Successfully authenticated as principal __system on local
2015-07-01T14:02:10.593+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:02:13.397+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:02:13.397+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:02:13.438+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:02:13.514+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:02:13.514+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:02:13.514+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:02:13.514+0000 I NETWORK [conn7] end connection 10.60.188.80:37278 (2 connections now open)
2015-07-01T14:02:13.514+0000 I NETWORK [conn3] end connection 127.0.0.1:46595 (1 connection now open)
2015-07-01T14:02:13.515+0000 I NETWORK [conn9] end connection 10.60.186.180:22002 (0 connections now open)
2015-07-01T14:02:13.779+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:02:13.779+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:02:13.908+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:02:13.908+0000 I CONTROL ** enabling http interface
2015-07-01T14:02:13.943+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:02:18.121+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] MongoDB starting : pid=26004 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten]
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten]
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten]
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten]
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:02:18.166+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:02:18.168+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:02:18.169+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:02:18.200+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:02:18.200+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:02:18.200+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:02:18.200+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:02:18.200+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:02:18.201+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:02:18.217+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:02:18.226+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:02:18.431+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22009 #1 (1 connection now open)
2015-07-01T14:02:18.445+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:02:18.774+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37291 #2 (2 connections now open)
2015-07-01T14:02:18.787+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:02:37.717+0000 I NETWORK [conn2] end connection 10.60.188.80:37291 (1 connection now open)
2015-07-01T14:02:38.227+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:02:38.227+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:02:38.228+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:02:38.228+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:02:38.229+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:02:38.229+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:02:38.229+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:02:38.230+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:02:38.230+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:02:38.236+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:02:38.237+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:02:38.237+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:02:39.291+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.186.180:27017 (1)
2015-07-01T14:02:40.013+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37307 #3 (2 connections now open)
2015-07-01T14:02:40.026+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:02:40.027+0000 I NETWORK [conn3] end connection 10.60.188.80:37307 (1 connection now open)
2015-07-01T14:02:40.044+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37309 #4 (2 connections now open)
2015-07-01T14:02:40.068+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:02:40.237+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state PRIMARY
2015-07-01T14:02:40.247+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:02:48.458+0000 I NETWORK [conn1] end connection 10.60.186.180:22009 (1 connection now open)
2015-07-01T14:02:48.459+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22014 #5 (2 connections now open)
2015-07-01T14:02:48.472+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:03:06.265+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:03:06.265+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:03:06.425+0000 I NETWORK [ReplExecNetThread-1] Socket recv() errno:104 Connection reset by peer 10.60.186.180:27017
2015-07-01T14:03:06.425+0000 I NETWORK [ReplExecNetThread-1] SocketException: remote: 10.60.186.180:27017 error: 9001 socket exception [RECV_ERROR] server [10.60.186.180:27017]
2015-07-01T14:03:06.425+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:03:06.425+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: local.$cmd query:

{ saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D5F5F73797374656D2C723D73345A46354F30586767355647735639336B44736959585558667673546B6A56) }

2015-07-01T14:03:06.425+0000 I NETWORK [conn5] end connection 10.60.186.180:22014 (1 connection now open)
2015-07-01T14:03:06.426+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:06.426+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:06.780+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.188.80:27017; voted for 10.60.186.180:27017 27 secs ago
2015-07-01T14:03:07.853+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.188.80:27017; voted for 10.60.186.180:27017 28 secs ago
2015-07-01T14:03:08.427+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:08.428+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:08.428+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:08.428+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:08.429+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:08.429+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:08.742+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.188.80:27017; voted for 10.60.186.180:27017 29 secs ago
2015-07-01T14:03:10.043+0000 I NETWORK [conn4] end connection 10.60.188.80:37309 (0 connections now open)
2015-07-01T14:03:10.044+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37317 #6 (1 connection now open)
2015-07-01T14:03:10.057+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:03:10.058+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:03:10.274+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:03:10.430+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:10.430+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:10.431+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:10.431+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:10.432+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:10.432+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:12.433+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:12.433+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:12.434+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:12.434+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:12.435+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:03:12.435+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:03:13.589+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22030 #7 (2 connections now open)
2015-07-01T14:03:13.602+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:03:13.603+0000 I NETWORK [conn7] end connection 10.60.186.180:22030 (1 connection now open)
2015-07-01T14:03:13.620+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22032 #8 (2 connections now open)
2015-07-01T14:03:13.644+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:03:14.451+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:03:18.005+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:03:18.006+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:03:18.091+0000 I STORAGE [conn6] got request after shutdown()
2015-07-01T14:03:18.138+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:03:18.208+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:03:18.208+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:03:18.208+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:03:18.208+0000 I NETWORK [conn8] end connection 10.60.186.180:22032 (0 connections now open)
2015-07-01T14:03:18.561+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:03:18.561+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:03:18.918+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:03:18.918+0000 I CONTROL ** enabling http interface
2015-07-01T14:03:18.953+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:03:24.950+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] MongoDB starting : pid=26128 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten]
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten]
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten]
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten]
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:03:25.028+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:03:25.031+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:03:25.031+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:03:25.064+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:03:25.064+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:03:25.064+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:03:25.064+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:03:25.065+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:03:25.082+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:03:25.091+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:03:25.091+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:03:25.091+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:03:25.092+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:03:25.092+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:03:25.657+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22044 #1 (1 connection now open)
2015-07-01T14:03:25.671+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:03:26.220+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37337 #2 (2 connections now open)
2015-07-01T14:03:26.233+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:03:41.052+0000 I NETWORK [conn2] end connection 10.60.188.80:37337 (1 connection now open)
2015-07-01T14:03:41.099+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:03:41.100+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:03:41.100+0000 I NETWORK [ReplExecNetThread-0] Socket closed remotely, no longer connected (idle 16 secs, remote host 10.60.188.80:27017)
2015-07-01T14:03:41.100+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:41.100+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:41.101+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:41.101+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:41.101+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:03:41.102+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:03:41.102+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:03:41.779+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.186.180:27017 (1)
2015-07-01T14:03:43.101+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state PRIMARY
2015-07-01T14:03:43.102+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:43.102+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:43.103+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:43.103+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:43.104+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:43.104+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:43.330+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37352 #3 (2 connections now open)
2015-07-01T14:03:43.344+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:03:43.345+0000 I NETWORK [conn3] end connection 10.60.188.80:37352 (1 connection now open)
2015-07-01T14:03:43.363+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37354 #4 (2 connections now open)
2015-07-01T14:03:43.387+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:03:45.120+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:03:55.686+0000 I NETWORK [conn1] end connection 10.60.186.180:22044 (1 connection now open)
2015-07-01T14:03:55.687+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22049 #5 (2 connections now open)
2015-07-01T14:03:55.700+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:04:09.129+0000 I NETWORK [ReplExecNetThread-2] DBClientCursor::init call() failed
2015-07-01T14:04:09.130+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:04:09.650+0000 I NETWORK [conn5] end connection 10.60.186.180:22049 (1 connection now open)
2015-07-01T14:04:09.650+0000 I NETWORK [ReplExecNetThread-2] Socket recv() errno:104 Connection reset by peer 10.60.186.180:27017
2015-07-01T14:04:09.650+0000 I NETWORK [ReplExecNetThread-2] SocketException: remote: 10.60.186.180:27017 error: 9001 socket exception [RECV_ERROR] server [10.60.186.180:27017]
2015-07-01T14:04:09.651+0000 I NETWORK [ReplExecNetThread-2] DBClientCursor::init call() failed
2015-07-01T14:04:09.651+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: local.$cmd query:

{ saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D5F5F73797374656D2C723D67624A47642B4B45765372783956693556486350575A4B4C6D4F6A6A5234706E) }

2015-07-01T14:04:09.651+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:09.651+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:11.652+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:11.653+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:11.653+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:11.653+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:11.654+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:11.654+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:12.236+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:04:13.133+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:04:13.403+0000 I NETWORK [conn4] end connection 10.60.188.80:37354 (0 connections now open)
2015-07-01T14:04:13.404+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37363 #6 (1 connection now open)
2015-07-01T14:04:13.417+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:04:13.655+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:13.655+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:13.656+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:13.656+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:13.656+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:13.656+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:15.657+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:15.657+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:15.658+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:15.658+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:15.659+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:04:15.659+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:04:17.109+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22062 #7 (2 connections now open)
2015-07-01T14:04:17.122+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:04:17.123+0000 I NETWORK [conn7] end connection 10.60.186.180:22062 (1 connection now open)
2015-07-01T14:04:17.142+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22065 #8 (2 connections now open)
2015-07-01T14:04:17.170+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:04:17.675+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:04:22.849+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:04:22.849+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:04:22.966+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:04:23.088+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:04:23.088+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:04:23.088+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:04:23.088+0000 I NETWORK [conn6] end connection 10.60.188.80:37363 (1 connection now open)
2015-07-01T14:04:23.088+0000 I NETWORK [conn8] end connection 10.60.186.180:22065 (0 connections now open)
2015-07-01T14:04:23.333+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:04:23.333+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:04:23.760+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:04:23.760+0000 I CONTROL ** enabling http interface
2015-07-01T14:04:23.795+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:04:29.481+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] MongoDB starting : pid=26266 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten]
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten]
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten]
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten]
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:04:35.985+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:04:35.986+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:04:35.995+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:04:36.026+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:04:36.026+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:04:36.026+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:04:36.026+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:04:36.027+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:04:36.041+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:04:36.052+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:04:36.052+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:04:36.053+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:04:36.053+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:04:36.053+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:04:37.194+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22093 #1 (1 connection now open)
2015-07-01T14:04:37.208+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:04:37.441+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37392 #2 (2 connections now open)
2015-07-01T14:04:37.454+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:04:43.394+0000 I NETWORK [conn2] end connection 10.60.188.80:37392 (1 connection now open)
2015-07-01T14:04:44.056+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:04:44.056+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:04:44.056+0000 I NETWORK [ReplExecNetThread-2] Socket closed remotely, no longer connected (idle 8 secs, remote host 10.60.188.80:27017)
2015-07-01T14:04:44.057+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:44.057+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:44.058+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:44.058+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:44.058+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:04:44.059+0000 I REPL [ReplicationExecutor] not electing self, 10.60.186.180:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.188.80:27017 is already primary and more up-to-date'
2015-07-01T14:04:44.059+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:04:45.351+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.186.180:27017 (1)
2015-07-01T14:04:46.057+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state PRIMARY
2015-07-01T14:04:46.059+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:46.059+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:46.060+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:46.060+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:46.061+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:46.061+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:46.454+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37407 #3 (2 connections now open)
2015-07-01T14:04:46.468+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:04:46.469+0000 I NETWORK [conn3] end connection 10.60.188.80:37407 (1 connection now open)
2015-07-01T14:04:46.486+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37409 #4 (2 connections now open)
2015-07-01T14:04:46.499+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:04:48.077+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:05:07.220+0000 I NETWORK [conn1] end connection 10.60.186.180:22093 (1 connection now open)
2015-07-01T14:05:07.220+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22097 #5 (2 connections now open)
2015-07-01T14:05:07.234+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:05:16.514+0000 I NETWORK [conn4] end connection 10.60.188.80:37409 (1 connection now open)
2015-07-01T14:05:16.515+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37413 #6 (2 connections now open)
2015-07-01T14:05:16.534+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:05:23.149+0000 I NETWORK [conn5] end connection 10.60.186.180:22097 (1 connection now open)
2015-07-01T14:05:24.090+0000 I NETWORK [ReplExecNetThread-2] Socket closed remotely, no longer connected (idle 6 secs, remote host 10.60.186.180:27017)
2015-07-01T14:05:24.091+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:24.091+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:24.092+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:24.092+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:24.093+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:24.093+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:24.093+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:24.094+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.186.180:27017 is already primary and more up-to-date'
2015-07-01T14:05:24.094+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:05:24.108+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:24.108+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.184.177:27017 is trying to elect itself but 10.60.186.180:27017 is already primary and more up-to-date'
2015-07-01T14:05:24.108+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:05:25.238+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:05:26.094+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:26.095+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:26.095+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:26.095+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:26.096+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:26.096+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:26.109+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:05:28.097+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:28.097+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:28.098+0000 W NETWORK [ReplExecNetThread-2] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:28.098+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:28.099+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:05:28.099+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:05:29.101+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:05:29.101+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:05:29.495+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:05:30.049+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:05:30.049+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:05:30.049+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:05:30.049+0000 I NETWORK [conn6] end connection 10.60.188.80:37413 (0 connections now open)
2015-07-01T14:05:30.325+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:05:30.325+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:05:30.414+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:05:30.414+0000 I CONTROL ** enabling http interface
2015-07-01T14:05:30.449+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:05:36.341+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten] MongoDB starting : pid=26395 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten]
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten]
2015-07-01T14:05:36.378+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten]
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten]
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:05:36.379+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:05:36.381+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:05:36.381+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:05:36.412+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:05:36.412+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:05:36.412+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:05:36.412+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:05:36.413+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:05:36.415+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:05:36.438+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:05:36.439+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:05:36.550+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37433 #1 (1 connection now open)
2015-07-01T14:05:36.564+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:05:38.223+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22130 #2 (2 connections now open)
2015-07-01T14:05:38.236+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:05:46.442+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:05:46.442+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] Socket recv() errno:104 Connection reset by peer 10.60.188.80:27017
2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] SocketException: remote: 10.60.188.80:27017 error: 9001 socket exception [RECV_ERROR] server [10.60.188.80:27017]
2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:05:46.506+0000 I NETWORK [conn1] end connection 10.60.188.80:37433 (1 connection now open)
2015-07-01T14:05:46.506+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: local.$cmd query:

{ saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D5F5F73797374656D2C723D48697571734E5341627732665161764F377470514A3443667261685970466A4E) }

2015-07-01T14:05:46.507+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:46.507+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:46.507+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:46.508+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:46.509+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:46.509+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:46.509+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:47 2015 before standing for election again
2015-07-01T14:05:47.437+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:47.438+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:47.439+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:47.439+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:47.439+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:48 2015 before standing for election again
2015-07-01T14:05:48.105+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:48.106+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:48.107+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:48.107+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:48.107+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:49 2015 before standing for election again
2015-07-01T14:05:48.508+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.508+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.509+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.509+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.510+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.510+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.739+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37449 #3 (2 connections now open)
2015-07-01T14:05:48.752+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:05:48.755+0000 I NETWORK [conn3] end connection 10.60.188.80:37449 (1 connection now open)
2015-07-01T14:05:48.774+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37452 #4 (2 connections now open)
2015-07-01T14:05:48.791+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37453 #5 (3 connections now open)
2015-07-01T14:05:48.791+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:05:48.805+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:05:49.010+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:49.011+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:49.012+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:49.012+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:49.012+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:49 2015 before standing for election again
2015-07-01T14:05:49.601+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:49.602+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:49.602+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:49.602+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:49.602+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:50 2015 before standing for election again
2015-07-01T14:05:50.088+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:50.089+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:05:50.090+0000 I REPL [ReplicationExecutor] received vote: 0 votes from 10.60.186.180:27017
2015-07-01T14:05:50.090+0000 I REPL [ReplicationExecutor] replSet couldn't elect self, only received 1 votes, but needed at least 2
2015-07-01T14:05:50.090+0000 I REPL [ReplicationExecutor] waiting until Wed Jul 1 14:05:50 2015 before standing for election again
2015-07-01T14:05:50.526+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:05:50.848+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:05:52.527+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:06:08.253+0000 I NETWORK [conn2] end connection 10.60.186.180:22130 (2 connections now open)
2015-07-01T14:06:08.254+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22137 #6 (3 connections now open)
2015-07-01T14:06:08.268+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:06:18.813+0000 I NETWORK [conn5] end connection 10.60.188.80:37453 (2 connections now open)
2015-07-01T14:06:18.813+0000 I NETWORK [conn4] end connection 10.60.188.80:37452 (2 connections now open)
2015-07-01T14:06:18.813+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37456 #7 (2 connections now open)
2015-07-01T14:06:18.827+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:06:26.208+0000 I NETWORK [conn6] end connection 10.60.186.180:22137 (1 connection now open)
2015-07-01T14:06:26.479+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:06:26.479+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location10276 DBClientBase::findN: transport error: 10.60.186.180:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:06:26.480+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:26.480+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:26.481+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:26.481+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:28.482+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:28.482+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:28.483+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:28.483+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:28.484+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:28.484+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:30.485+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:30.486+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:30.486+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:30.486+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:30.487+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:30.487+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:32.488+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:32.488+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:32.489+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:32.489+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:32.489+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.186.180:27017, reason: errno:111 Connection refused
2015-07-01T14:06:32.490+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.186.180:27017; Location18915 Failed attempt to connect to 10.60.186.180:27017; couldn't connect to server 10.60.186.180:27017 (10.60.186.180), connection attempt failed
2015-07-01T14:06:33.143+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22154 #8 (2 connections now open)
2015-07-01T14:06:33.156+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:06:33.157+0000 I NETWORK [conn8] end connection 10.60.186.180:22154 (1 connection now open)
2015-07-01T14:06:33.174+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22156 #9 (2 connections now open)
2015-07-01T14:06:33.200+0000 I ACCESS [conn9] Successfully authenticated as principal __system on local
2015-07-01T14:06:34.506+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:06:35.161+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:06:35.161+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:06:35.202+0000 I STORAGE [conn9] got request after shutdown()
2015-07-01T14:06:35.356+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:06:35.421+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:06:35.421+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:06:35.422+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:06:35.422+0000 I NETWORK [conn7] end connection 10.60.188.80:37456 (0 connections now open)
2015-07-01T14:06:35.656+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:06:35.656+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:06:36.073+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:06:36.073+0000 I CONTROL ** enabling http interface
2015-07-01T14:06:36.111+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:06:42.342+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] MongoDB starting : pid=26531 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-184-177
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten]
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten]
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten]
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten]
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:06:42.446+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:06:42.447+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:06:42.447+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:06:42.447+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:06:42.447+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:06:42.449+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:06:42.449+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:06:42.480+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:06:42.480+0000 I REPL [ReplicationExecutor] This node is 10.60.184.177:27017 in the config
2015-07-01T14:06:42.480+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:06:42.480+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:06:42.480+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:06:42.482+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:06:42.506+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:06:42.507+0000 I REPL [ReplicationExecutor] Member 10.60.186.180:27017 is now in state SECONDARY
2015-07-01T14:06:42.845+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37479 #1 (1 connection now open)
2015-07-01T14:06:42.859+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:06:43.434+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22170 #2 (2 connections now open)
2015-07-01T14:06:43.447+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:06:49.779+0000 I NETWORK [conn1] end connection 10.60.188.80:37479 (1 connection now open)
2015-07-01T14:06:50.509+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:06:50.509+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.184.177:27017", fromId: 0, checkEmpty: false }

2015-07-01T14:06:50.510+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:06:50.510+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:06:50.511+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:06:50.511+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:06:50.511+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:06:50.512+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:06:50.513+0000 I REPL [ReplicationExecutor] received vote: 1 votes from 10.60.186.180:27017
2015-07-01T14:06:50.513+0000 I REPL [ReplicationExecutor] replSet election succeeded, assuming primary role
2015-07-01T14:06:50.513+0000 I REPL [ReplicationExecutor] transition to PRIMARY
2015-07-01T14:06:51.483+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2015-07-01T14:06:52.043+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37494 #3 (2 connections now open)
2015-07-01T14:06:52.057+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:06:52.058+0000 I NETWORK [conn3] end connection 10.60.188.80:37494 (1 connection now open)
2015-07-01T14:06:52.077+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37497 #4 (2 connections now open)
2015-07-01T14:06:52.095+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37498 #5 (3 connections now open)
2015-07-01T14:06:52.095+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:06:52.108+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:06:52.527+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:07:13.465+0000 I NETWORK [conn2] end connection 10.60.186.180:22170 (2 connections now open)
2015-07-01T14:07:13.465+0000 I NETWORK [initandlisten] connection accepted from 10.60.186.180:22177 #6 (3 connections now open)
2015-07-01T14:07:13.479+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:07:22.124+0000 I NETWORK [conn5] end connection 10.60.188.80:37498 (2 connections now open)
2015-07-01T14:07:22.124+0000 I NETWORK [conn4] end connection 10.60.188.80:37497 (2 connections now open)
2015-07-01T14:07:22.124+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:37501 #7 (2 connections now open)
2015-07-01T14:07:22.138+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:07:29.199+0000 I NETWORK [conn6] end connection 10.60.186.180:22177 (1 connection now open)

Comment by Andreas Nilsson [ 01/Jul/15 ]

This doesn't look like an authentication problem, it looks like the node simply cannot connect to 10.60.184.177.

Do you have the logs for 10.60.184.177 as well?
Also does this work cleanly if you simply remove the keyFile entry from the config file?

Comment by Justin Liu [ 01/Jul/15 ]

root@srd-10-60-186-180:/var/log/mongodb# date
Wed Jul 1 14:01:58 UTC 2015
root@srd-10-60-186-180:/var/log/mongodb# mongo
MongoDB shell version: 3.0.4
connecting to: test
mongo3-auth-debug-dev:PRIMARY> use admin
switched to db admin
2015-07-01T14:02:03.714+0000 I NETWORK DBClientCursor::init call() failed
>

This mongo instance was a primary and I logged into it and then type "use admin", I get a error " I NETWORK DBClientCursor::init call() failed" and the instance was becoming a "secondary". All 3 mongo replicas keep doing "election process."

Comment by Andreas Nilsson [ 01/Jul/15 ]

I dont see any crash in the log file above, only failed heartbeat requests. Is there a crash as well?

Comment by Justin Liu [ 01/Jul/15 ]

I have attached the mongodb.log for your review.

This problem will only happen with 3.0.4 WT engine and user authentiation enabled. On the same cluster, if I install 2.6.1 with user authentication enabled, everything is working correctly.

thanks
Justin


root@srd-10-60-186-180:/var/log/mongodb# date
Wed Jul 1 14:01:58 UTC 2015
root@srd-10-60-186-180:/var/log/mongodb# mongo
MongoDB shell version: 3.0.4
connecting to: test
mongo3-auth-debug-dev:PRIMARY> use admin
switched to db admin
2015-07-01T14:02:03.714+0000 I NETWORK DBClientCursor::init call() failed
>
-------------------
mongodb.log

2015-07-01T13:59:56.965+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T13:59:57.378+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T13:59:57.466+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T13:59:57.466+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T13:59:57.466+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T13:59:57.466+0000 I NETWORK [conn6] end connection 10.60.184.177:6441 (1 connection now open)
2015-07-01T13:59:57.466+0000 I NETWORK [conn5] end connection 10.60.188.80:21506 (1 connection now open)
2015-07-01T13:59:57.792+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T13:59:57.792+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T13:59:57.877+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T13:59:57.877+0000 I CONTROL ** enabling http interface
2015-07-01T13:59:57.911+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:00:04.271+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:00:04.360+0000 I CONTROL [initandlisten] MongoDB starting : pid=25333 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:00:04.360+0000 I CONTROL [initandlisten]
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten]
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten]
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten]
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:00:04.361+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:00:04.363+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:00:04.363+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:00:04.395+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:00:04.395+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:00:04.395+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:00:04.395+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:00:04.411+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:00:04.411+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state PRIMARY
2015-07-01T14:00:04.412+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:00:04.427+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:00:04.760+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6451 #1 (1 connection now open)
2015-07-01T14:00:04.774+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:00:04.900+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21520 #2 (2 connections now open)
2015-07-01T14:00:04.914+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:00:05.692+0000 I NETWORK [conn1] end connection 10.60.184.177:6451 (1 connection now open)
2015-07-01T14:00:06.412+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:00:06.412+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location10276 DBClientBase::findN: transport error: 10.60.184.177:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:00:06.413+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:06.413+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:06.414+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:06.414+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:06.414+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:00:06.415+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.186.180:27017 is trying to elect itself but 10.60.184.177:27017 is already primary and more up-to-date'
2015-07-01T14:00:06.415+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:00:06.428+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:00:06.429+0000 I REPL [ReplicationExecutor] not electing self, 10.60.188.80:27017 would veto with '10.60.186.180:27017 is trying to elect itself but 10.60.184.177:27017 is already primary and more up-to-date'
2015-07-01T14:00:06.429+0000 I REPL [ReplicationExecutor] not electing self, we are not freshest
2015-07-01T14:00:07.674+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:00:08.415+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:08.416+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:08.416+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:08.416+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:08.417+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:08.417+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:08.430+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:00:10.418+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:10.418+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:10.418+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:10.419+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:10.419+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:10.419+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:12.420+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:12.420+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:12.421+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:12.421+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:12.422+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:00:12.422+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:00:13.161+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6469 #3 (2 connections now open)
2015-07-01T14:00:13.175+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:00:13.176+0000 I NETWORK [conn3] end connection 10.60.184.177:6469 (1 connection now open)
2015-07-01T14:00:13.201+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6471 #4 (2 connections now open)
2015-07-01T14:00:13.229+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:00:14.438+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:00:31.866+0000 I NETWORK [conn2] end connection 10.60.188.80:21520 (1 connection now open)
2015-07-01T14:00:32.444+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:00:32.444+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:00:32.445+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:00:32.445+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:00:32.446+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:00:32.446+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:00:33.242+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 25 secs ago
2015-07-01T14:00:33.501+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21550 #5 (2 connections now open)
2015-07-01T14:00:33.518+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:00:33.519+0000 I NETWORK [conn5] end connection 10.60.188.80:21550 (1 connection now open)
2015-07-01T14:00:33.522+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21552 #6 (2 connections now open)
2015-07-01T14:00:33.547+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:00:33.551+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21553 #7 (3 connections now open)
2015-07-01T14:00:33.569+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:00:33.763+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 26 secs ago
2015-07-01T14:00:33.999+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 26 secs ago
2015-07-01T14:00:34.447+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state PRIMARY
2015-07-01T14:00:34.463+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:00:43.245+0000 I NETWORK [conn4] end connection 10.60.184.177:6471 (2 connections now open)
2015-07-01T14:00:43.245+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6478 #8 (3 connections now open)
2015-07-01T14:00:43.259+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:00:59.667+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:00:59.667+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:01:00.290+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:01:00.419+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:01:00.420+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:01:00.420+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:01:00.420+0000 I NETWORK [conn6] end connection 10.60.188.80:21552 (2 connections now open)
2015-07-01T14:01:00.420+0000 I NETWORK [conn7] end connection 10.60.188.80:21553 (2 connections now open)
2015-07-01T14:01:00.420+0000 I NETWORK [conn8] end connection 10.60.184.177:6478 (2 connections now open)
2015-07-01T14:01:00.911+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:01:00.911+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:01:00.979+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:01:00.979+0000 I CONTROL ** enabling http interface
2015-07-01T14:01:01.013+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:01:07.528+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] MongoDB starting : pid=25464 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten]
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten]
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten]
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten]
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:01:07.627+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:01:07.628+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:01:07.630+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:01:07.631+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:01:07.662+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:01:07.662+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:01:07.662+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:01:07.662+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:01:07.669+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:01:07.670+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:01:07.687+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state PRIMARY
2015-07-01T14:01:07.691+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:01:09.572+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21567 #1 (1 connection now open)
2015-07-01T14:01:09.586+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:01:09.687+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:01:09.687+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location10276 DBClientBase::findN: transport error: 10.60.184.177:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:01:09.688+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:09.689+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:09.689+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:09.690+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:09.690+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:01:09.691+0000 I REPL [ReplicationExecutor] replSet possible election tie; sleeping 881ms until 2015-07-01T14:01:10.571+0000
2015-07-01T14:01:10.571+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:01:10.572+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:01:10.573+0000 I REPL [ReplicationExecutor] received vote: 1 votes from 10.60.188.80:27017
2015-07-01T14:01:10.573+0000 I REPL [ReplicationExecutor] replSet election succeeded, assuming primary role
2015-07-01T14:01:10.573+0000 I REPL [ReplicationExecutor] transition to PRIMARY
2015-07-01T14:01:10.670+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2015-07-01T14:01:11.691+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:11.692+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:11.692+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:11.693+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:11.693+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:11.693+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:13.694+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:13.695+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:13.695+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:13.695+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:13.696+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:01:13.696+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:01:14.476+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6506 #2 (2 connections now open)
2015-07-01T14:01:14.489+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:01:14.491+0000 I NETWORK [conn2] end connection 10.60.184.177:6506 (1 connection now open)
2015-07-01T14:01:14.509+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6509 #3 (2 connections now open)
2015-07-01T14:01:14.523+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6510 #4 (3 connections now open)
2015-07-01T14:01:14.526+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:01:14.552+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:01:15.712+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:01:34.538+0000 I NETWORK [conn1] end connection 10.60.188.80:21567 (2 connections now open)
2015-07-01T14:01:35.703+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:01:35.704+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:01:35.705+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:35.705+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:35.706+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:01:35.706+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:01:36.693+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21594 #5 (3 connections now open)
2015-07-01T14:01:36.707+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:01:36.708+0000 I NETWORK [conn5] end connection 10.60.188.80:21594 (2 connections now open)
2015-07-01T14:01:36.711+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21596 #6 (3 connections now open)
2015-07-01T14:01:36.734+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:01:36.741+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21597 #7 (4 connections now open)
2015-07-01T14:01:36.754+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:01:37.722+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:01:44.544+0000 I NETWORK [conn4] end connection 10.60.184.177:6510 (3 connections now open)
2015-07-01T14:01:44.545+0000 I NETWORK [conn3] end connection 10.60.184.177:6509 (2 connections now open)
2015-07-01T14:01:44.545+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6519 #8 (3 connections now open)
2015-07-01T14:01:44.558+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:02:00.822+0000 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64109 #9 (4 connections now open)
2015-07-01T14:02:00.824+0000 I ACCESS [conn9] Unauthorized not authorized on admin to execute command

{ getLog: "startupWarnings" }

2015-07-01T14:02:00.825+0000 I ACCESS [conn9] Unauthorized not authorized on admin to execute command

{ replSetGetStatus: 1.0, forShell: 1.0 }

2015-07-01T14:02:02.753+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:02:02.754+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:02:03.545+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:02:03.676+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:02:03.677+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:02:03.677+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:02:03.677+0000 I NETWORK [conn6] end connection 10.60.188.80:21596 (3 connections now open)
2015-07-01T14:02:03.677+0000 I NETWORK [conn8] end connection 10.60.184.177:6519 (3 connections now open)
2015-07-01T14:02:03.677+0000 I NETWORK [conn7] end connection 10.60.188.80:21597 (3 connections now open)
2015-07-01T14:02:03.677+0000 I NETWORK [conn9] end connection 127.0.0.1:64109 (0 connections now open)
2015-07-01T14:02:03.945+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:02:03.945+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:02:04.067+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:02:04.067+0000 I CONTROL ** enabling http interface
2015-07-01T14:02:04.102+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:02:10.252+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:02:10.362+0000 I CONTROL [initandlisten] MongoDB starting : pid=25754 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:02:10.362+0000 I CONTROL [initandlisten]
2015-07-01T14:02:10.362+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten]
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten]
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten]
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:02:10.363+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:02:10.365+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:02:10.365+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:02:10.396+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:02:10.396+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:02:10.396+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:02:10.396+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:02:10.397+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:02:10.417+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:02:10.423+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:02:10.423+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:02:10.578+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6529 #1 (1 connection now open)
2015-07-01T14:02:10.591+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:02:10.757+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21608 #2 (2 connections now open)
2015-07-01T14:02:10.771+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:02:13.514+0000 I NETWORK [conn1] end connection 10.60.184.177:6529 (1 connection now open)
2015-07-01T14:02:14.424+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:02:14.424+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location10276 DBClientBase::findN: transport error: 10.60.184.177:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:02:14.425+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:02:14.425+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:02:14.426+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:02:14.426+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:02:16.427+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:02:16.427+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:02:16.428+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:02:16.428+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:02:16.429+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:02:16.429+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:02:18.169+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6544 #3 (2 connections now open)
2015-07-01T14:02:18.183+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:02:18.184+0000 I NETWORK [conn3] end connection 10.60.184.177:6544 (1 connection now open)
2015-07-01T14:02:18.201+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6546 #4 (2 connections now open)
2015-07-01T14:02:18.225+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:02:18.445+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:02:37.717+0000 I NETWORK [conn2] end connection 10.60.188.80:21608 (1 connection now open)
2015-07-01T14:02:38.436+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:02:38.436+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:02:38.437+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:02:38.437+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:02:38.438+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:02:38.438+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:02:38.438+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:02:38.439+0000 I REPL [ReplicationExecutor] replSet possible election tie; sleeping 850ms until 2015-07-01T14:02:39.289+0000
2015-07-01T14:02:39.289+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:02:39.290+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:02:39.291+0000 I REPL [ReplicationExecutor] received vote: 1 votes from 10.60.184.177:27017
2015-07-01T14:02:39.291+0000 I REPL [ReplicationExecutor] replSet election succeeded, assuming primary role
2015-07-01T14:02:39.291+0000 I REPL [ReplicationExecutor] transition to PRIMARY
2015-07-01T14:02:39.420+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2015-07-01T14:02:40.028+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21631 #5 (2 connections now open)
2015-07-01T14:02:40.041+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:02:40.042+0000 I NETWORK [conn5] end connection 10.60.188.80:21631 (1 connection now open)
2015-07-01T14:02:40.044+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21633 #6 (2 connections now open)
2015-07-01T14:02:40.067+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:02:40.454+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:02:48.240+0000 I NETWORK [conn4] end connection 10.60.184.177:6546 (1 connection now open)
2015-07-01T14:02:48.241+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6554 #7 (2 connections now open)
2015-07-01T14:02:48.254+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:03:05.858+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:03:05.859+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:03:06.083+0000 I STORAGE [conn6] got request after shutdown()
2015-07-01T14:03:06.264+0000 I STORAGE [conn7] got request after shutdown()
2015-07-01T14:03:06.268+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:03:06.424+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:03:06.424+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:03:06.424+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:03:06.876+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:03:06.876+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:03:07.172+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:03:07.172+0000 I CONTROL ** enabling http interface
2015-07-01T14:03:07.207+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:03:13.468+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] MongoDB starting : pid=25872 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten]
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten]
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten]
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten]
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:03:13.584+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:03:13.587+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:03:13.587+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:03:13.618+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:03:13.618+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:03:13.618+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:03:13.618+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:03:13.620+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:03:13.643+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:03:13.644+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:03:13.645+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:03:14.436+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21647 #1 (1 connection now open)
2015-07-01T14:03:14.436+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6567 #2 (2 connections now open)
2015-07-01T14:03:14.449+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:03:14.450+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:03:18.208+0000 I NETWORK [conn2] end connection 10.60.184.177:6567 (1 connection now open)
2015-07-01T14:03:19.647+0000 I NETWORK [ReplExecNetThread-0] Socket closed remotely, no longer connected (idle 6 secs, remote host 10.60.184.177:27017)
2015-07-01T14:03:19.647+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:19.648+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:19.648+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:19.648+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:19.649+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:19.649+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:21.650+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:21.650+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:21.651+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:21.651+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:21.652+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:21.652+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:23.653+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:23.653+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:23.654+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:23.654+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:23.655+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:03:23.655+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:03:25.033+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6583 #3 (2 connections now open)
2015-07-01T14:03:25.047+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:03:25.048+0000 I NETWORK [conn3] end connection 10.60.184.177:6583 (1 connection now open)
2015-07-01T14:03:25.065+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6585 #4 (2 connections now open)
2015-07-01T14:03:25.089+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:03:25.672+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:03:41.052+0000 I NETWORK [conn1] end connection 10.60.188.80:21647 (1 connection now open)
2015-07-01T14:03:41.658+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:03:41.658+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:03:41.659+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:41.659+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:41.660+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:03:41.660+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:03:41.660+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:03:41.661+0000 I REPL [ReplicationExecutor] replSet possible election tie; sleeping 116ms until 2015-07-01T14:03:41.777+0000
2015-07-01T14:03:41.777+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:03:41.778+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:03:41.779+0000 I REPL [ReplicationExecutor] received vote: 1 votes from 10.60.184.177:27017
2015-07-01T14:03:41.779+0000 I REPL [ReplicationExecutor] replSet election succeeded, assuming primary role
2015-07-01T14:03:41.779+0000 I REPL [ReplicationExecutor] transition to PRIMARY
2015-07-01T14:03:42.646+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2015-07-01T14:03:43.345+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21676 #5 (2 connections now open)
2015-07-01T14:03:43.359+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:03:43.361+0000 I NETWORK [conn5] end connection 10.60.188.80:21676 (1 connection now open)
2015-07-01T14:03:43.362+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21678 #6 (2 connections now open)
2015-07-01T14:03:43.388+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:03:43.389+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21679 #7 (3 connections now open)
2015-07-01T14:03:43.403+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:03:43.676+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:03:55.107+0000 I NETWORK [conn4] end connection 10.60.184.177:6585 (2 connections now open)
2015-07-01T14:03:55.107+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6595 #8 (3 connections now open)
2015-07-01T14:03:55.121+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:04:08.974+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:04:08.975+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:04:09.128+0000 I STORAGE [conn8] got request after shutdown()
2015-07-01T14:04:09.401+0000 I STORAGE [conn7] got request after shutdown()
2015-07-01T14:04:09.402+0000 I STORAGE [conn6] got request after shutdown()
2015-07-01T14:04:09.484+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:04:09.649+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:04:09.649+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:04:09.649+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:04:09.650+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:04:09.650+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:04:09.650+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:04:09.650+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:04:09.650+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:04:09.650+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:04:10.250+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:04:10.250+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:04:10.689+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:04:10.689+0000 I CONTROL ** enabling http interface
2015-07-01T14:04:10.724+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:04:16.971+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:04:17.103+0000 I CONTROL [initandlisten] MongoDB starting : pid=26001 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:04:17.103+0000 I CONTROL [initandlisten]
2015-07-01T14:04:17.103+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:04:17.103+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten]
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten]
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten]
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:04:17.104+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:04:17.106+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:04:17.107+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:04:17.139+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:04:17.139+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:04:17.139+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:04:17.139+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:04:17.140+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:04:17.141+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:04:17.157+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:04:17.171+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:04:17.660+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6608 #1 (1 connection now open)
2015-07-01T14:04:17.661+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21693 #2 (2 connections now open)
2015-07-01T14:04:17.673+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:04:17.674+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:04:23.088+0000 I NETWORK [conn1] end connection 10.60.184.177:6608 (1 connection now open)
2015-07-01T14:04:23.172+0000 I NETWORK [ReplExecNetThread-0] Socket closed remotely, no longer connected (idle 6 secs, remote host 10.60.184.177:27017)
2015-07-01T14:04:23.173+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:23.173+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:23.174+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:23.174+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:23.175+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:23.175+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:25.176+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:25.177+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:25.177+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:25.177+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:25.178+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:25.178+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:27.179+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:27.179+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:27.180+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:27.180+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:27.180+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:27.181+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:29.182+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:29.182+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:29.183+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:29.183+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:29.184+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:29.184+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:31.185+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:31.185+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:31.186+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:31.186+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:31.187+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:31.187+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:33.188+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:33.188+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:33.189+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:33.189+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:33.190+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:33.190+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:35.191+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:35.192+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:35.192+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:35.193+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:35.193+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:04:35.193+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:04:35.996+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6624 #3 (2 connections now open)
2015-07-01T14:04:36.009+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:04:36.010+0000 I NETWORK [conn3] end connection 10.60.184.177:6624 (1 connection now open)
2015-07-01T14:04:36.027+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6626 #4 (2 connections now open)
2015-07-01T14:04:36.050+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:04:37.208+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:04:43.393+0000 I NETWORK [conn2] end connection 10.60.188.80:21693 (1 connection now open)
2015-07-01T14:04:45.172+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:04:45.172+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:04:45.173+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:45.173+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:45.174+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:04:45.174+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:04:45.174+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:04:45.175+0000 I REPL [ReplicationExecutor] replSet possible election tie; sleeping 174ms until 2015-07-01T14:04:45.349+0000
2015-07-01T14:04:45.350+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:04:45.350+0000 I REPL [ReplicationExecutor] replSet info electSelf
2015-07-01T14:04:45.351+0000 I REPL [ReplicationExecutor] received vote: 1 votes from 10.60.184.177:27017
2015-07-01T14:04:45.351+0000 I REPL [ReplicationExecutor] replSet election succeeded, assuming primary role
2015-07-01T14:04:45.351+0000 I REPL [ReplicationExecutor] transition to PRIMARY
2015-07-01T14:04:46.144+0000 I REPL [rsSync] transition to primary complete; database writes are now permitted
2015-07-01T14:04:46.469+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21731 #5 (2 connections now open)
2015-07-01T14:04:46.483+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:04:46.484+0000 I NETWORK [conn5] end connection 10.60.188.80:21731 (1 connection now open)
2015-07-01T14:04:46.491+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21733 #6 (2 connections now open)
2015-07-01T14:04:46.501+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21734 #7 (3 connections now open)
2015-07-01T14:04:46.504+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local
2015-07-01T14:04:46.519+0000 I ACCESS [conn7] Successfully authenticated as principal __system on local
2015-07-01T14:04:47.190+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:05:06.066+0000 I NETWORK [conn4] end connection 10.60.184.177:6626 (2 connections now open)
2015-07-01T14:05:06.067+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6636 #8 (3 connections now open)
2015-07-01T14:05:06.080+0000 I ACCESS [conn8] Successfully authenticated as principal __system on local
2015-07-01T14:05:16.522+0000 I NETWORK [conn7] end connection 10.60.188.80:21734 (2 connections now open)
2015-07-01T14:05:16.522+0000 I NETWORK [conn6] end connection 10.60.188.80:21733 (2 connections now open)
2015-07-01T14:05:16.522+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21737 #9 (2 connections now open)
2015-07-01T14:05:16.536+0000 I ACCESS [conn9] Successfully authenticated as principal __system on local
2015-07-01T14:05:22.777+0000 I CONTROL [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2015-07-01T14:05:22.777+0000 I REPL [signalProcessingThread] Stopping replication applier threads
2015-07-01T14:05:23.001+0000 I STORAGE [WiredTigerRecordStoreThread for local.oplog.rs] shutting down
2015-07-01T14:05:23.148+0000 I CONTROL [signalProcessingThread] now exiting
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] shutdown: going to close listening sockets...
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] closing listening socket: 5
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] closing listening socket: 6
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] closing listening socket: 7
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] shutdown: going to flush diaglog...
2015-07-01T14:05:23.148+0000 I NETWORK [signalProcessingThread] shutdown: going to close sockets...
2015-07-01T14:05:23.148+0000 I STORAGE [signalProcessingThread] WiredTigerKVEngine shutting down
2015-07-01T14:05:23.148+0000 I NETWORK [conn8] end connection 10.60.184.177:6636 (1 connection now open)
2015-07-01T14:05:23.148+0000 I NETWORK [conn9] end connection 10.60.188.80:21737 (0 connections now open)
2015-07-01T14:05:23.373+0000 I STORAGE [signalProcessingThread] shutdown: removing fs lock...
2015-07-01T14:05:23.373+0000 I CONTROL [signalProcessingThread] dbexit: rc: 0
2015-07-01T14:05:23.690+0000 I CONTROL ** WARNING: --rest is specified without --httpinterface,
2015-07-01T14:05:23.690+0000 I CONTROL ** enabling http interface
2015-07-01T14:05:23.725+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=1G,session_max=20000,eviction=(threads_max=4),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-07-01T14:05:30.123+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] MongoDB starting : pid=26143 port=27017 dbpath=/mnt/mongodb 64-bit host=srd-10-60-186-180
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten]
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten]
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten]
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 31545 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten]
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] db version v3.0.4
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] git version: 0481c958daeb2969800511e7475dc66986fa9ed5
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1f 6 Jan 2014
2015-07-01T14:05:30.167+0000 I CONTROL [initandlisten] build info: Linux ip-10-146-31-239 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2015-07-01T14:05:30.168+0000 I CONTROL [initandlisten] allocator: tcmalloc
2015-07-01T14:05:30.168+0000 I CONTROL [initandlisten] options: { config: "/etc/mongodb.conf", net: { http:

{ RESTInterfaceEnabled: true, enabled: true }

, port: 27017 }, processManagement:

{ fork: false }

, replication:

{ replSet: "mongo3-auth-debug-dev" }

, security:

{ keyFile: "/etc/mongodb.key" }

, storage:

{ dbPath: "/mnt/mongodb", engine: "wiredTiger" }

, systemLog:

{ logAppend: true }

}
2015-07-01T14:05:30.170+0000 I NETWORK [initandlisten] waiting for connections on port 27017
2015-07-01T14:05:30.170+0000 I NETWORK [websvr] admin web console waiting for connections on port 28017
2015-07-01T14:05:30.171+0000 W NETWORK [ReplicationExecutor] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:30.198+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "mongo3-auth-debug-dev", version: 4, members: [ { _id: 0, host: "10.60.184.177:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "10.60.186.180:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "10.60.188.80:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatTimeoutSecs: 10, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

} }
2015-07-01T14:05:30.198+0000 I REPL [ReplicationExecutor] This node is 10.60.186.180:27017 in the config
2015-07-01T14:05:30.198+0000 I REPL [ReplicationExecutor] transition to STARTUP2
2015-07-01T14:05:30.198+0000 I REPL [ReplicationExecutor] Starting replication applier threads
2015-07-01T14:05:30.199+0000 I REPL [ReplicationExecutor] transition to RECOVERING
2015-07-01T14:05:30.199+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:30.199+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:30.201+0000 I REPL [ReplicationExecutor] transition to SECONDARY
2015-07-01T14:05:30.207+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:30.208+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:30.213+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:30.213+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:30.214+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:05:30.548+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21749 #1 (1 connection now open)
2015-07-01T14:05:30.562+0000 I ACCESS [conn1] Successfully authenticated as principal __system on local
2015-07-01T14:05:32.214+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:32.214+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:32.215+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:32.215+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:32.215+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:05:32.215+0000 I REPL [ReplicationExecutor] Standing for election
2015-07-01T14:05:32.216+0000 I REPL [ReplicationExecutor] replSet possible election tie; sleeping 484ms until 2015-07-01T14:05:32.700+0000
2015-07-01T14:05:32.216+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:32.216+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:32.638+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:05:34.216+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:34.216+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:05:34.217+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:34.217+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:34.217+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:34.218+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:34.218+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:36.219+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:36.219+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:36.220+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:36.220+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:36.221+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.184.177:27017, reason: errno:111 Connection refused
2015-07-01T14:05:36.221+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.184.177:27017; Location18915 Failed attempt to connect to 10.60.184.177:27017; couldn't connect to server 10.60.184.177:27017 (10.60.184.177), connection attempt failed
2015-07-01T14:05:36.382+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6662 #2 (2 connections now open)
2015-07-01T14:05:36.395+0000 I ACCESS [conn2] Successfully authenticated as principal __system on local
2015-07-01T14:05:36.397+0000 I NETWORK [conn2] end connection 10.60.184.177:6662 (1 connection now open)
2015-07-01T14:05:36.413+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6664 #3 (2 connections now open)
2015-07-01T14:05:36.437+0000 I ACCESS [conn3] Successfully authenticated as principal __system on local
2015-07-01T14:05:38.237+0000 I REPL [ReplicationExecutor] Member 10.60.184.177:27017 is now in state SECONDARY
2015-07-01T14:05:46.222+0000 I NETWORK [ReplExecNetThread-1] DBClientCursor::init call() failed
2015-07-01T14:05:46.222+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: admin.$cmd query:

{ replSetHeartbeat: "mongo3-auth-debug-dev", pv: 1, v: 4, from: "10.60.186.180:27017", fromId: 1, checkEmpty: false }

2015-07-01T14:05:46.506+0000 I NETWORK [conn1] end connection 10.60.188.80:21749 (1 connection now open)
2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] Socket recv() errno:104 Connection reset by peer 10.60.188.80:27017
2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] SocketException: remote: 10.60.188.80:27017 error: 9001 socket exception [RECV_ERROR] server [10.60.188.80:27017]
2015-07-01T14:05:46.506+0000 I NETWORK [ReplExecNetThread-0] DBClientCursor::init call() failed
2015-07-01T14:05:46.506+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location10276 DBClientBase::findN: transport error: 10.60.188.80:27017 ns: local.$cmd query:

{ saslStart: 1, mechanism: "SCRAM-SHA-1", payload: BinData(0, 6E2C2C6E3D5F5F73797374656D2C723D5A784A6B4A6D7A7A773134554F77587539757A57616C504256797A6E62464539) }

2015-07-01T14:05:46.507+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:46.507+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:46.508+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 13 secs ago
2015-07-01T14:05:47.438+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 14 secs ago
2015-07-01T14:05:48.106+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 15 secs ago
2015-07-01T14:05:48.508+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.509+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.509+0000 W NETWORK [ReplExecNetThread-0] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.509+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.510+0000 W NETWORK [ReplExecNetThread-1] Failed to connect to 10.60.188.80:27017, reason: errno:111 Connection refused
2015-07-01T14:05:48.510+0000 I REPL [ReplicationExecutor] Error in heartbeat request to 10.60.188.80:27017; Location18915 Failed attempt to connect to 10.60.188.80:27017; couldn't connect to server 10.60.188.80:27017 (10.60.188.80), connection attempt failed
2015-07-01T14:05:48.755+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21773 #4 (2 connections now open)
2015-07-01T14:05:48.769+0000 I ACCESS [conn4] Successfully authenticated as principal __system on local
2015-07-01T14:05:48.770+0000 I NETWORK [conn4] end connection 10.60.188.80:21773 (1 connection now open)
2015-07-01T14:05:48.771+0000 I NETWORK [initandlisten] connection accepted from 10.60.188.80:21774 #5 (2 connections now open)
2015-07-01T14:05:48.788+0000 I ACCESS [conn5] Successfully authenticated as principal __system on local
2015-07-01T14:05:49.011+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 16 secs ago
2015-07-01T14:05:49.601+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 16 secs ago
2015-07-01T14:05:50.089+0000 I REPL [ReplicationExecutor] replSet voting no for 10.60.184.177:27017; voted for 10.60.188.80:27017 17 secs ago
2015-07-01T14:05:50.526+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state SECONDARY
2015-07-01T14:05:50.847+0000 I REPL [ReplicationExecutor] replSetElect voting yea for 10.60.188.80:27017 (2)
2015-07-01T14:05:52.527+0000 I REPL [ReplicationExecutor] Member 10.60.188.80:27017 is now in state PRIMARY
2015-07-01T14:06:06.454+0000 I NETWORK [conn3] end connection 10.60.184.177:6664 (1 connection now open)
2015-07-01T14:06:06.454+0000 I NETWORK [initandlisten] connection accepted from 10.60.184.177:6672 #6 (2 connections now open)
2015-07-01T14:06:06.468+0000 I ACCESS [conn6] Successfully authenticated as principal __system on local

Comment by Justin Liu [ 30/Jun/15 ]

by the way, we are running on ubuntu 14.04 64 bit OS

Comment by Justin Liu [ 30/Jun/15 ]

1. This is a new system.
2. this is a new 3.0.4 mongo engine.
3. I will get the crash log of the mongod later.
4. /etc/mongodb.conf
dbpath = /mnt/mongodb
fork = false
keyFile = /etc/mongodb.key
logappend = true
port = 27017
replSet = mss-corporate-db-dev
rest = true
storageEngine="wiredTiger"
5. this is what I did. a) I disable the user security and then create root user on admin db. b) enable the security on all 3 replicas c) login into the primary, use admn, db_auth("root",''password"). So far so good, but after that, the mongo instance will crash randomly with wrong command or anything.

Comment by Andreas Nilsson [ 30/Jun/15 ]

Hi justin.liu@turner.com, thanks for your report.

In order to facilitate reproduction could you please provide us with the following answers and information:

  • Are there are existing users on the server?
  • Is it in upgraded instance or a new clean?
  • The crash log of the mongod
  • The config file or command line parameters used to start the mongod server.
  • Any user management commands issued prior to attempting to authenticate.

Regards,
Andreas Nilsson

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