Uploaded image for project: 'Java Driver'
  1. Java Driver
  2. JAVA-2290

Server monitor thread dies

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • 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.

            Assignee:
            Unassigned Unassigned
            Reporter:
            daniel.gottlieb@mongodb.com Daniel Gottlieb (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: