Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: 3.2.2
Component/s: Async
Labels:
None
Environment:
Java 8, Linux, AWS

This issue was originally reported in Java but was moved to support (as https://jira.mongodb.org/browse/SUPPORT-1538). Now I've been asked to re-open it in Java again:

We have a 3-node replica-set and some java clients connecting to it.

Servers are:

0001: development-trantor-rs01-0001 - ip-10-1-xxx-49.trantor-southwest-1.compute.internal
0002: development-trantor-rs01-0002 - ip-10-1-xxx-203.trantor-southwest-1.compute.internal
0003: development-trantor-rs01-0003 - ip-10-1-xxx-227.trantor-southwest-1.compute.internal

Something happened in our primary 0001:

2015-12-14T02:37:18.863+0000 I -        [conn517493] Assertion: 28537:Demoted from primary while removing from foo.bar
2015-12-14T02:37:18.990+0000 I QUERY    [conn320297] getmore local.oplog.rs query: { ts: { $gt: Timestamp 1449128999000|2 } } cursorid:6554465004290 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:7 nreturned:4 reslen:544 locks:{ Global: { acquireCount: { r: 20 }, acquireWaitCount: { r: 6 }, timeAcquiringMicros: { r: 90655565 } }, Database: { acquireCount: { r: 10 } }, oplog: { acquireCount: { r: 10 } } } user_key_comparison_count:618 block_cache_hit_count:14 block_read_count:0 block_read_byte:0 internal_key_skipped_count:11 internal_delete_skipped_count:0 get_from_memtable_count:0 seek_on_memtable_count:7 seek_child_seek_count:21 27265ms
2015-12-14T02:37:18.990+0000 I QUERY    [conn119] getmore local.oplog.rs query: { ts: { $gte: Timestamp 1447900202000|2 } } cursorid:6554135393530 ntoreturn:0 keyUpdates:0 writeConflicts:0 numYields:5 nreturned:4 reslen:544 locks:{ Global: { acquireCount: { r: 14 }, acquireWaitCount: { r: 6 }, timeAcquiringMicros: { r: 43403120 } }, Database: { acquireCount: { r: 7 } }, oplog: { acquireCount: { r: 7 } } } user_key_comparison_count:442 block_cache_hit_count:10 block_read_count:0 block_read_byte:0 internal_key_skipped_count:9 internal_delete_skipped_count:0 get_from_memtable_count:0 seek_on_memtable_count:5 seek_child_seek_count:15 15791ms
2015-12-14T02:37:19.005+0000 I NETWORK  [conn566148] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.208:54911]
2015-12-14T02:37:19.005+0000 I NETWORK  [conn566145] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.243:44347]
2015-12-14T02:37:19.015+0000 I NETWORK  [conn566146] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.84:36672]
2015-12-14T02:37:19.051+0000 I NETWORK  [conn566147] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.10:47207]
2015-12-14T02:37:19.066+0000 I -        [conn562910] Assertion: 28537:Demoted from primary while removing from foo.bar
2015-12-14T02:37:19.066+0000 I -        [conn517498] Assertion: 28537:Demoted from primary while removing from foo.bar
2015-12-14T02:37:19.091+0000 I -        [conn496978] Assertion: 28537:Demoted from primary while removing from foo.bar
2015-12-14T02:37:19.091+0000 I -        [conn497062] Assertion: 28537:Demoted from primary while removing from foo.bar
2015-12-14T02:37:19.253+0000 I NETWORK  [conn119] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.227:57257]
2015-12-14T02:37:19.253+0000 I NETWORK  [conn320297] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.1.xxx.176:42329]
2015-12-14T02:37:19.253+0000 I NETWORK  [conn566150] end connection 10.1.xxx.176:42718 (10 connections now open)
2015-12-14T02:37:19.630+0000 I QUERY    [conn566149] query local.oplog.rs planSummary: COLLSCAN ntoreturn:1 ntoskip:0 nscanned:0 nscannedObjects:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:117 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 43811 } }, oplog: { acquireCount: { r: 2 } } } user_key_comparison_count:110 block_cache_hit_count:3 block_read_count:1 block_read_byte:16106 internal_key_skipped_count:1 internal_delete_skipped_count:0 get_from_memtable_count:0 seek_on_memtable_count:2 seek_child_seek_count:6 197ms
2015-12-14T02:37:19.657+0000 I NETWORK  [initandlisten] connection accepted from 10.1.xxx.227:44285 #566151 (10 connections now open)
2015-12-14T02:37:19.778+0000 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:43518 #566152 (11 connections now open)
2015-12-14T02:37:19.787+0000 I NETWORK  [conn566152] end connection 127.0.0.1:43518 (10 connections now open)
2015-12-14T02:37:20.031+0000 I CONTROL  [conn517493]
 0x108a4a2 0x1027129 0x100ba6e 0x100bb1c 0xabae7c 0xc93603 0xc9378b 0xc93adb 0xc941bd 0xa6c563 0xa6ccb0 0xa6d366 0xa6fe9c 0xa91e31 0xa92e3c 0xa93b0b 0xc6128b 0xb74472 0x8b36d5 0x103bac9 0x7fef860d6df5 0x7fef84b881ad

after which 0002 became the new primary. 0001 recovered properly (with some rollbacks) and made a transition into a secondary.
mongod.log from 0001:

2015-12-14T02:38:07.456+0000 I REPL     [ReplicationExecutor] syncing from: ip-10-1-xxx-203.trantor-southeast-1.compute.internal:27017
2015-12-14T02:38:07.472+0000 I REPL     [rsBackgroundSync] replSet our last op time fetched: Dec 14 02:37:07:1
2015-12-14T02:38:07.472+0000 I REPL     [rsBackgroundSync] replset source's GTE: Dec 14 02:38:04:1
2015-12-14T02:38:07.473+0000 I REPL     [rsBackgroundSync] beginning rollback
2015-12-14T02:38:07.473+0000 I REPL     [rsBackgroundSync] rollback 0
2015-12-14T02:38:07.474+0000 I REPL     [ReplicationExecutor] transition to ROLLBACK
2015-12-14T02:38:07.474+0000 I REPL     [rsBackgroundSync] rollback 1
2015-12-14T02:38:07.475+0000 I REPL     [rsBackgroundSync] rollback 2 FindCommonPoint
2015-12-14T02:38:07.507+0000 I REPL     [SyncSourceFeedback] replset setting syncSourceFeedback to ip-10-1-xxx-203.trantor-southeast-1.compute.internal:27017
2015-12-14T02:38:07.569+0000 I REPL     [rsBackgroundSync] replSet info rollback our last optime:   Dec 14 02:37:07:1
2015-12-14T02:38:07.569+0000 I REPL     [rsBackgroundSync] replSet info rollback their last optime: Dec 14 02:38:04:1
2015-12-14T02:38:07.569+0000 I REPL     [rsBackgroundSync] replSet info rollback diff in end of log times: -57 seconds
2015-12-14T02:38:07.570+0000 I REPL     [rsBackgroundSync] replSet rollback found matching events at Dec 14 02:36:24:2
2015-12-14T02:38:07.570+0000 I REPL     [rsBackgroundSync] replSet rollback findcommonpoint scanned : 6
2015-12-14T02:38:07.570+0000 I REPL     [rsBackgroundSync] replSet rollback 3 fixup
2015-12-14T02:38:07.583+0000 I REPL     [rsBackgroundSync] rollback 3.5
2015-12-14T02:38:07.585+0000 I REPL     [rsBackgroundSync] rollback 4 n:4
2015-12-14T02:38:07.585+0000 I REPL     [rsBackgroundSync] replSet minvalid=Dec 14 02:38:04 566e2b8c:1
2015-12-14T02:38:07.616+0000 I REPL     [rsBackgroundSync] rollback 4.6
2015-12-14T02:38:07.616+0000 I REPL     [rsBackgroundSync] rollback 4.7
2015-12-14T02:38:07.668+0000 I REPL     [rsBackgroundSync] rollback 5 d:4 u:0
2015-12-14T02:38:07.668+0000 I REPL     [rsBackgroundSync] rollback 6
2015-12-14T02:38:07.711+0000 I REPL     [rsBackgroundSync] rollback done
2015-12-14T02:38:07.711+0000 I REPL     [ReplicationExecutor] transition to RECOVERING
2015-12-14T02:38:07.711+0000 I REPL     [rsBackgroundSync] rollback finished
2015-12-14T02:38:07.711+0000 I REPL     [ReplicationExecutor] syncing from: ip-10-1-xxx-203.trantor-southeast-1.compute.internal:27017
2015-12-14T02:38:07.711+0000 I REPL     [ReplicationExecutor] syncing from: ip-10-1-xxx-203.trantor-southeast-1.compute.internal:27017
2015-12-14T02:38:07.712+0000 I NETWORK  [conn566149] end connection 10.1.157.227:44284 (5 connections now open)
2015-12-14T02:38:07.717+0000 I NETWORK  [conn566151] end connection 10.1.157.227:44285 (4 connections now open)
2015-12-14T02:38:07.813+0000 I REPL     [ReplicationExecutor] transition to SECONDARY

But, after that, 0001 (now a secondary) was already unreachable by java:

[2015-12-14T02:37:25.235Z] [DEBUG] [cluster-ClusterId{value='566a2b1badbb126de1a555c2', description='null'}-ip-10-1-xxx-227.trantor-southeast-1.compute.internal:27017] org.mongodb.driver.cluster:? Updating cluster description to  {type=REPLICA_SET, servers=[{address=ip-10-1-xxx-203.trantor-southeast-1.compute.internal:27017, type=REPLICA_SET_PRIMARY, roundTripTime=4.8 ms, state=CONNECTED}, {address=ip-10-1-xxx-227.trantor-southeast-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, roundTripTime=2.0 ms, state=CONNECTED}, {address=ip-10-1-xxx-49.trantor-southeast-1.compute.internal:27017, type=UNKNOWN, state=CONNECTING}]

We raised rs.stepDown() on 0002, after which 0001 became primary again, but java still can't connect to it, we're getting messages like this in the java client:

[2015-12-15T06:28:39.451Z] [INFO] [Thread-5970] org.mongodb.driver.cluster:? No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, all=[ServerDescription{address=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, electionId=null, maxDocumentSize=16777216, roundTripTimeNanos=3210551, setName='rs01', canonicalAddress=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017', tagSet=TagSet{[]}}, ServerDescription{address=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, electionId=null, maxDocumentSize=16777216, roundTripTimeNanos=1189727, setName='rs01', canonicalAddress=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017', tagSet=TagSet{[]}}, ServerDescription{address=ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out

All nodes agree on master:

pdsh -w "development-trantor-mongo-rs01-000[1-3]" "mongo --eval 'printjson(db.isMaster().primary)'"
development-trantor-mongo-rs01-0001: MongoDB shell version: 3.0.5
development-trantor-mongo-rs01-0002: MongoDB shell version: 3.0.5
development-trantor-mongo-rs01-0003: MongoDB shell version: 3.0.5
development-trantor-mongo-rs01-0001: "ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017"
development-trantor-mongo-rs01-0002: "ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017"
development-trantor-mongo-rs01-0003: "ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017"

And we can connect with command-line client from the same host that runs the failing java code:

# mongo --host ip-10-1-xxx-49.trantor-southwest-1.compute.internal
MongoDB shell version: 3.0.4
connecting to: ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017/test
rs01:PRIMARY>

Connection string looks like:

mongodb://development-trantor-mongo-rs01-0001,development-trantor-mongo-rs01-0002,development-trantor-mongo-rs01-0003/?w=majority&journal=true

(these hostnames are just CNAMES for the real IP, we can connect to these too from the machine)

The stack-trace shows a thread like this:

"cluster-ClusterId{value='566a2b1badbb126de1a555c2', description='null'}-ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017" #107390 daemon prio=5 os_prio=0 tid=0x00007ff9f4243800 nid=0x5a41 waiting on condition [0x00007ff9ed8f7000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000efce9b88> (a java.util.concurrent.CountDownLatch$Sync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
    at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
    at com.mongodb.connection.netty.NettyStream$FutureAsyncCompletionHandler.get(NettyStream.java:330)
    at com.mongodb.connection.netty.NettyStream.read(NettyStream.java:160)
    at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491)
    at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221)
    at com.mongodb.connection.CommandHelper.receiveReply(CommandHelper.java:134)
    at com.mongodb.connection.CommandHelper.receiveCommandResult(CommandHelper.java:121)
    at com.mongodb.connection.CommandHelper.executeCommand(CommandHelper.java:32)
    at com.mongodb.connection.InternalStreamConnectionInitializer.initializeConnectionDescription(InternalStreamConnectionInitializer.java:83)
    at com.mongodb.connection.InternalStreamConnectionInitializer.initialize(InternalStreamConnectionInitializer.java:43)
    at com.mongodb.connection.InternalStreamConnection.open(InternalStreamConnection.java:115)
    at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:127)
    - locked <0x00000000efce9cb0> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
    at java.lang.Thread.run(Thread.java:745)

whereas the one for the other two nodes look like this:

"cluster-ClusterId{value='566a2b1badbb126de1a555c2', description='null'}-ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017" #144394 daemon prio=5 os_prio=0 tid=0x00007ffa20cbb000 nid=0x3b0d waiting on condition [0x00007ff9ed9f8000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForNext(DefaultServerMonitor.java:225)
    at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:167)
    - locked <0x00000000eff7fc00> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
    at java.lang.Thread.run(Thread.java:745)

"cluster-ClusterId{value='566a2b1badbb126de1a555c2', description='null'}-ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017" #144373 daemon prio=5 os_prio=0 tid=0x00007ffa20e83000 nid=0x3ac9 waiting on condition [0x00007ff9e747a000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForNext(DefaultServerMonitor.java:225)
    at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:167)
    - locked <0x00000000eff19fc0> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
    at java.lang.Thread.run(Thread.java:745)

tcpdump shows no activity from the driver trying to connect (but it appears when we connect with command-line, so tcpdump args are ok).

ip addresses and host names are unchanged.

We upgraded to 3.2.2 and were hoping that would have fixed it, but it doesn't, just took a while but it happened again:

[2016-03-21T14:34:55.862Z] [INFO] [Thread-4870] org.mongodb.driver.cluster:? No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, all=[ServerDescription{address=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=2897612, setName='rs01', canonicalAddress=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017', tagSet=TagSet{[]}, electionId=null, setVersion=3}, ServerDescription{address=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=802719, setName='rs01', canonicalAddress=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017', tagSet=TagSet{[]}, electionId=null, setVersion=3}, ServerDescription{address=ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out

rs.status() in primary:

{
	"set" : "rs01",
	"date" : ISODate("2016-03-21T14:46:02.002Z"),
	"myState" : 1,
	"members" : [
		{
			"_id" : 0,
			"name" : "ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 1231298,
			"optime" : Timestamp(1458354484, 1),
			"optimeDate" : ISODate("2016-03-19T02:28:04Z"),
			"electionTime" : Timestamp(1458354624, 1),
			"electionDate" : ISODate("2016-03-19T02:30:24Z"),
			"configVersion" : 3,
			"self" : true
		},
		{
			"_id" : 1,
			"name" : "ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 216934,
			"optime" : Timestamp(1458354484, 1),
			"optimeDate" : ISODate("2016-03-19T02:28:04Z"),
			"lastHeartbeat" : ISODate("2016-03-21T14:46:01.081Z"),
			"lastHeartbeatRecv" : ISODate("2016-03-21T14:46:01.704Z"),
			"pingMs" : 2,
			"configVersion" : 3
		},
		{
			"_id" : 2,
			"name" : "ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 1230888,
			"optime" : Timestamp(1458354484, 1),
			"optimeDate" : ISODate("2016-03-19T02:28:04Z"),
			"lastHeartbeat" : ISODate("2016-03-21T14:46:01.659Z"),
			"lastHeartbeatRecv" : ISODate("2016-03-21T14:46:01.571Z"),
			"pingMs" : 3,
			"configVersion" : 3
		}
	],
	"ok" : 1
}

However, this time (3.2.2), it managed to recover after the stepDown():

[2016-03-21T14:48:26.914Z] [INFO] [Thread-5293] org.mongodb.driver.cluster:? No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, all=[ServerDescription{address=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=4268169, setName='rs01', canonicalAddress=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}, ServerDescription{address=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=739004, setName='rs01', canonicalAddress=ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}, ServerDescription{address=ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
[2016-03-21T14:48:26.997Z] [INFO] [cluster-ClusterId{value='56ea96e31847a572e963fa73', description='null'}-ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017] org.mongodb.driver.cluster:? Monitor thread successfully connected to server with description ServerDescription{address=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 5]}, minWireVersion=0, maxWireVersion=3, maxDocumentSize=16777216, roundTripTimeNanos=3998244, setName='rs01', canonicalAddress=ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, hosts=[ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017, ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017], passives=[], arbiters=[], primary='ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017', tagSet=TagSet{[]}, electionId=56f009baca60543a10792068, setVersion=3}
[2016-03-21T14:48:26.997Z] [INFO] [cluster-ClusterId{value='56ea96e31847a572e963fa73', description='null'}-ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017] org.mongodb.driver.cluster:? Setting max election id to 56f009baca60543a10792068 from replica set primary ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017
[2016-03-21T14:48:26.997Z] [INFO] [cluster-ClusterId{value='56ea96e31847a572e963fa73', description='null'}-ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017] org.mongodb.driver.cluster:? Discovered replica set primary ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017

and new status is:

rs01:SECONDARY> rs.status()
{
	"set" : "rs01",
	"date" : ISODate("2016-03-21T14:53:17.164Z"),
	"myState" : 2,
	"syncingTo" : "ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017",
	"members" : [
		{
			"_id" : 0,
			"name" : "ip-10-1-xxx-49.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 1231733,
			"optime" : Timestamp(1458571985, 1),
			"optimeDate" : ISODate("2016-03-21T14:53:05Z"),
			"syncingTo" : "ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017",
			"configVersion" : 3,
			"self" : true
		},
		{
			"_id" : 1,
			"name" : "ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 1,
			"stateStr" : "PRIMARY",
			"uptime" : 217370,
			"optime" : Timestamp(1458571985, 1),
			"optimeDate" : ISODate("2016-03-21T14:53:05Z"),
			"lastHeartbeat" : ISODate("2016-03-21T14:53:15.828Z"),
			"lastHeartbeatRecv" : ISODate("2016-03-21T14:53:16.861Z"),
			"pingMs" : 5,
			"electionTime" : Timestamp(1458571706, 1),
			"electionDate" : ISODate("2016-03-21T14:48:26Z"),
			"configVersion" : 3
		},
		{
			"_id" : 2,
			"name" : "ip-10-1-xxx-227.trantor-southwest-1.compute.internal:27017",
			"health" : 1,
			"state" : 2,
			"stateStr" : "SECONDARY",
			"uptime" : 1231323,
			"optime" : Timestamp(1458571985, 1),
			"optimeDate" : ISODate("2016-03-21T14:53:05Z"),
			"lastHeartbeat" : ISODate("2016-03-21T14:53:16.411Z"),
			"lastHeartbeatRecv" : ISODate("2016-03-21T14:53:15.957Z"),
			"pingMs" : 0,
			"syncingTo" : "ip-10-1-xxx-203.trantor-southwest-1.compute.internal:27017",
			"configVersion" : 3
		}
	],
	"ok" : 1
}

duplicates

JAVA-2302 Memory leak on Java async driver + Netty 4.1.x

Closed

Assignee:: Unassigned

Reporter:: Francisco Alejandro Lozano López

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Created:: Mar 22 2016 11:24:34 AM UTC

Updated:: Jun 03 2022 02:05:29 PM UTC

Resolved:: Oct 04 2016 01:29:14 AM UTC

Details

Description

Attachments

Issue Links

Activity

People

Dates