Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Duplicate
Priority: Major - P3
Fix Version/s: None
Affects Version/s: None
Component/s: Cluster Management, Error Handling
Labels:
None
Environment:
Running against MongoDB 3.0.9

My assumptions about how the (java) driver is modeled

Creating a MongoClient that connects to a replica set, a shared state object is created which contains all of the seeded/discovered members and the last known state of each member.

The state for each member is monitored by a thread e.g:

"cluster-ClusterId{value='57bdbb382f53757a079b2616', description='scrubbedReplName'}-scrubbedHostname:scrubbedPort" #96 daemon prio=5 os_prio=0 tid=0x00007f73cd07f800 nid=0x7a8a waiting on condition [0x00007f7321248000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000003c04d48e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
	at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForSignalOrTimeout(DefaultServerMonitor.java:238)
	at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.waitForNext(DefaultServerMonitor.java:219)
	at com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:168)
	- locked <0x00000003c04d4408> (a com.mongodb.connection.DefaultServerMonitor$ServerMonitorRunnable)
	at java.lang.Thread.run(Thread.java:745)

If one of those threads were to exit, that member's state would no longer be updated on replica set object's state.

What we observed

While our java application was running, the following log appeared:

2016-08-26T03:25:33.561+0000 [scrubbedThreadName] WARN  org.mongodb.driver.connection [SLF4JLogger.java.warn:86] - Got socket exception on connection [connectionId{localValue:3565883, serverValue:689402}] to scubbedHostname:scrubbedPort. All connections to scrubbedHostname:scrubbedPort will be closed.

That was immediately followed by some threads receiving the error:

com.mongodb.MongoSocketReadException: Prematurely reached end of stream
	at com.mongodb.connection.SocketStream.read(SocketStream.java:88) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:297) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:54) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na]
	at <ourcode> ~[classes/:na]
java.lang.IllegalThreadStateException: null
	at java.lang.Thread.start(Thread.java:705) ~[na:1.8.0_25]
	at com.mongodb.connection.DefaultServerMonitor.invalidate(DefaultServerMonitor.java:88) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.invalidate(DefaultServer.java:120) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.handleThrowable(DefaultServer.java:150) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.access$500(DefaultServer.java:38) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:161) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na]
	at <our code>
com.mongodb.MongoSocketReadException: Prematurely reached end of stream
	at com.mongodb.connection.SocketStream.read(SocketStream.java:88) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:297) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.QueryProtocol.execute(QueryProtocol.java:54) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na]
	at <our code>
java.lang.IllegalThreadStateException: null
	at java.lang.Thread.start(Thread.java:705) ~[na:1.8.0_25]
	at com.mongodb.connection.DefaultServerMonitor.invalidate(DefaultServerMonitor.java:88) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.invalidate(DefaultServer.java:120) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.handleThrowable(DefaultServer.java:150) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer.access$500(DefaultServer.java:38) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:161) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.DefaultServerConnection.query(DefaultServerConnection.java:209) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:496) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation$1.call(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:239) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:212) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:482) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.FindOperation.execute(FindOperation.java:79) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo.execute(Mongo.java:772) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo$2.execute(Mongo.java:759) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.initializeCursor(DBCursor.java:851) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCursor.hasNext(DBCursor.java:152) ~[mongo-java-driver-3.2.2.jar:na]
	at <our code>

Subsequent attempts to reach the primary resulted in the following:

com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=REPLICA_SET, servers=[{address=scrubbedProblemHost:scrubbedPort, type=UNKNOWN, state=CONNECTING}, {address=scrubbedArbiter, type=REPLICA_SET_ARBITER, roundTripTime=7.8 ms, state=CONNECTED}, {address=scrubbedWorkingHost, type=REPLICA_SET_SECONDARY, roundTripTime=1.0 ms, state=CONNECTED}, {address=scrubbedWorkingHost, type=REPLICA_SET_SECONDARY, roundTripTime=0.9 ms, state=CONNECTED}]
	at com.mongodb.connection.BaseCluster.createTimeoutException(BaseCluster.java:369) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:101) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:68) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:219) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:111) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:66) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo.execute(Mongo.java:781) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.Mongo$2.execute(Mongo.java:764) ~[mongo-java-driver-3.2.2.jar:na]
	at com.mongodb.DBCollection.createIndex(DBCollection.java:1541) ~[mongo-java-driver-3.2.2.jar:na]

Server logs at the time of the first error shows:

2016-08-26T03:25:26.527+0000 I QUERY    [conn689402] assertion 13435 not master and slaveOk=false <query information>
2016-08-26T03:25:26.528+0000 I NETWORK  [conn689402] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.20.0.204:48093]

Before restarting the application we got a thread dump which does not seem to show any threads for the problem host. We're conjecturing that server monitoring thread allowed an exception to escape, causing it to die and it was not replaced.

I can provide fuller logs upon request.

duplicates

JAVA-2238 Connection and thread leakage in DefaultServerMonitor

Closed

Assignee:: Unassigned

Reporter:: Daniel Gottlieb (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Created:: Aug 26 2016 09:01:36 PM UTC

Updated:: Nov 11 2017 04:43:59 AM UTC

Resolved:: Aug 26 2016 10:12:17 PM UTC

Details

Description

My assumptions about how the (java) driver is modeled

What we observed

Attachments

Issue Links

Activity

People

Dates