[JAVA-4822] MongoInterruptedException incorrectly thrown from server monitor thread and logged Created: 01/Dec/22  Updated: 28/Oct/23  Resolved: 05/Dec/22

Status: Closed
Project: Java Driver
Component/s: Logging
Affects Version/s: 4.8.0
Fix Version/s: 4.8.1

Type: Bug Priority: Minor - P4
Reporter: Maxence Warzecha Assignee: Jeffrey Yemin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Documentation Changes: Not Needed

 Description   

Summary

Upgraded from 4.2.3 to 4.8.0 and this error is sometimes logged when we create the MongoClient:

Exception in thread "cluster-ClusterId{value='<valueremovedforissue>', description='null'}-localhost:27017" com.mongodb.MongoInterruptedException: Interrupted waiting for lock
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:49)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.BaseCluster.updateDescription(BaseCluster.java:247)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.updateDescription(AbstractMultiServerCluster.java:385)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.lambda$onChange$3(AbstractMultiServerCluster.java:214)
    at com.mongodb.internal.Locks.lambda$withLock$0(Locks.java:30)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:43)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.onChange(AbstractMultiServerCluster.java:164)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.updateDescription(DefaultSdamServerDescriptionManager.java:113)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.lambda$update$0(DefaultSdamServerDescriptionManager.java:75)
    at com.mongodb.internal.Locks.lambda$withLock$0(Locks.java:30)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:43)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.update(DefaultSdamServerDescriptionManager.java:60)
    at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:170)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
    at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:41)
    ... 25 more

 
Application work properly and all is fine except this exception on our startup (Playframework).

If we switch back to previous version all is back to normal. We are looking to migrate our production cluster (Atlas) to version 6.x so our first step is to upgrade the Java Driver.

URI : mongodb://localhost:27017,127.0.0.1:27018/?replicaSet=rs0

Please provide the version of the driver. If applicable, please provide the MongoDB server version and topology (standalone, replica set, or sharded cluster).

Impacted version : 4.8.0

How to Reproduce

Hard to tell



 Comments   
Comment by Githook User [ 05/Dec/22 ]

Author:

{'name': 'Jeff Yemin', 'email': 'jeff.yemin@mongodb.com', 'username': 'jyemin'}

Message: Improve logging in server monitor (#1060)

Log as error any exception except MongoInterruptedException in server monitor
before exiting monitor thread

JAVA-4822
Branch: 4.8.x
https://github.com/mongodb/mongo-java-driver/commit/a749ba3fc04d2cd05db3fbb2c28bce7d4880f7b9

Comment by Githook User [ 05/Dec/22 ]

Author:

{'name': 'Jeff Yemin', 'email': 'jeff.yemin@mongodb.com', 'username': 'jyemin'}

Message: Improve logging in server monitor (#1060)

Log as error any exception except MongoInterruptedException in server monitor
before exiting monitor thread

JAVA-4822
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/774f4c0ed4483b926f8ce2fdd80681577a5a0dc0

Comment by Maxence Warzecha [ 01/Dec/22 ]

Your hypothesis looks correct. I replaced in the connection string the localhost with 127.0.0.1 and the driver do not show the exception in logs anymore. We are now on 4.8.0 version

Keep good work.

Comment by Jeffrey Yemin [ 01/Dec/22 ]

I think we should address this confusion by not logging interruption-related exceptions in the server monitor.

Comment by Jeffrey Yemin [ 01/Dec/22 ]

OK, that supported my hypothesis. What's happening is that you're using the connection string mongodb://localhost:27017,127.0.0.1:27018/?replicaSet=rs0. The replica set is configured to use the IP address 127.0.0.1 as the host name, not localhost. So the driver eventually notices this and replaces the monitor of localhost:27017 with 127.0.0.1:27017, interrupting the former's monitor and causing this exception to be thrown and logged before the monitor exits.

Try testing with mongodb://127.0.0.1:27017,127.0.0.1:27018/?replicaSet=rs0 and I would bet that the exception will no longer be thrown.

Comment by Maxence Warzecha [ 01/Dec/22 ]

Hi Jeffrey,

Thank you for the quick support.

Here is the rs.status() (local cluster) :

{  set: 'rs0',  date: 2022-12-01T15:05:40.812Z,  myState: 1,  term: Long("2108"),  syncSourceHost: '',  syncSourceId: -1,  heartbeatIntervalMillis: Long("2000"),  majorityVoteCount: 2,  writeMajorityCount: 2,  votingMembersCount: 3,  writableVotingMembersCount: 2,  optimes: {    lastCommittedOpTime: { ts: Timestamp({ t: 1669907133, i: 1 }), t: Long("2108") },    lastCommittedWallTime: 2022-12-01T15:05:33.287Z,    readConcernMajorityOpTime: { ts: Timestamp({ t: 1669907133, i: 1 }), t: Long("2108") },    appliedOpTime: { ts: Timestamp({ t: 1669907133, i: 1 }), t: Long("2108") },    durableOpTime: { ts: Timestamp({ t: 1669907133, i: 1 }), t: Long("2108") },    lastAppliedWallTime: 2022-12-01T15:05:33.287Z,    lastDurableWallTime: 2022-12-01T15:05:33.287Z  },  lastStableRecoveryTimestamp: Timestamp({ t: 1669907083, i: 1 }),  electionCandidateMetrics: {    lastElectionReason: 'priorityTakeover',    lastElectionDate: 2022-12-01T12:19:58.946Z,    electionTerm: Long("2108"),    lastCommittedOpTimeAtElection: { ts: Timestamp({ t: 1669897197, i: 1 }), t: Long("2107") },    lastSeenOpTimeAtElection: { ts: Timestamp({ t: 1669897197, i: 1 }), t: Long("2107") },    numVotesNeeded: 2,    priorityAtElection: 100,    electionTimeoutMillis: Long("10000"),    priorPrimaryMemberId: 1,    numCatchUpOps: Long("0"),    newTermStartDate: 2022-12-01T12:19:59.035Z,    wMajorityWriteAvailabilityDate: 2022-12-01T12:20:00.009Z  },  electionParticipantMetrics: {    votedForCandidate: true,    electionTerm: Long("2107"),    lastVoteDate: 2022-12-01T12:19:47.683Z,    electionCandidateMemberId: 1,    voteReason: '',    lastAppliedOpTimeAtElection: { ts: Timestamp({ t: 1669897177, i: 1 }), t: Long("2106") },    maxAppliedOpTimeInSet: { ts: Timestamp({ t: 1669897177, i: 1 }), t: Long("2106") },    priorityAtElection: 100  },  members: [    {      _id: 0,      name: '127.0.0.1:27017',      health: 1,      state: 1,      stateStr: 'PRIMARY',      uptime: 1114780,      optime: [Object],      optimeDate: 2022-12-01T15:05:33.000Z,      lastAppliedWallTime: 2022-12-01T15:05:33.287Z,      lastDurableWallTime: 2022-12-01T15:05:33.287Z,      syncSourceHost: '',      syncSourceId: -1,      infoMessage: '',      electionTime: Timestamp({ t: 1669897198, i: 1 }),      electionDate: 2022-12-01T12:19:58.000Z,      configVersion: 1,      configTerm: 2108,      self: true,      lastHeartbeatMessage: ''    },    {      _id: 1,      name: '127.0.0.1:27018',      health: 1,      state: 2,      stateStr: 'SECONDARY',      uptime: 9963,      optime: [Object],      optimeDurable: [Object],      optimeDate: 2022-12-01T15:05:33.000Z,      optimeDurableDate: 2022-12-01T15:05:33.000Z,      lastAppliedWallTime: 2022-12-01T15:05:33.287Z,      lastDurableWallTime: 2022-12-01T15:05:33.287Z,      lastHeartbeat: 2022-12-01T15:05:39.691Z,      lastHeartbeatRecv: 2022-12-01T15:05:40.398Z,      pingMs: Long("0"),      lastHeartbeatMessage: '',      syncSourceHost: '127.0.0.1:27017',      syncSourceId: 0,      infoMessage: '',      configVersion: 1,      configTerm: 2108    },    {      _id: 2,      name: '127.0.0.1:27019',      health: 1,      state: 7,      stateStr: 'ARBITER',      uptime: 9963,      lastHeartbeat: 2022-12-01T15:05:39.691Z,      lastHeartbeatRecv: 2022-12-01T15:05:39.416Z,      pingMs: Long("0"),      lastHeartbeatMessage: '',      syncSourceHost: '',      syncSourceId: -1,      infoMessage: '',      configVersion: 1,      configTerm: 2108    }  ],  ok: 1,  '$clusterTime': {    clusterTime: Timestamp({ t: 1669907133, i: 1 }),    signature: {      hash: Binary(Buffer.from("0000000000000000000000000000000000000000", "hex"), 0),      keyId: Long("0")    }  },  operationTime: Timestamp({ t: 1669907133, i: 1 })} 

Debug from the diver (org.mongo) : 

2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Adding discovered server 127.0.0.1:27018 to client view of cluster
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Adding discovered server localhost:27017 to client view of cluster
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.cluster  Updating cluster description to  {type=REPLICA_SET, servers=[{address=localhost:27017, type=UNKNOWN, state=CONNECTING}, {address=127.0.0.1:27018, type=UNKNOWN, state=CONNECTING}]
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:1, serverValue:3359}] to localhost:27017
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:3, serverValue:3812}] to 127.0.0.1:27018
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:4, serverValue:3360}] to localhost:27017
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:2, serverValue:3813}] to 127.0.0.1:27018
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Monitor thread successfully connected to server with description ServerDescription{address=localhost:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=77683719, setName='rs0', canonicalAddress=127.0.0.1:27017, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=7fffffff000000000000083c, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02881867a66f6c2b5f5, counter=1056}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942136167388}
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27018, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=77747506, setName='rs0', canonicalAddress=127.0.0.1:27018, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6377c029d83b658f8610ef42, counter=904}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942136167433}
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.client  MongoClient with metadata {"driver": {"name": "mongo-java-driver|sync", "version": "4.8.0"}, "os": {"type": "Darwin", "name": "Mac OS X", "architecture": "x86_64", "version": "10.16"}, "platform": "Java/AdoptOpenJDK/1.8.0_292-b10"} created with settings MongoClientSettings{readPreference=primary, writeConcern=WriteConcern{w=null, wTimeout=null ms, journal=null}, retryWrites=true, retryReads=true, readConcern=ReadConcern{level=null}, credential=null, streamFactoryFactory=null, commandListeners=[], codecRegistry=ProvidersCodecRegistry{codecProviders=[ProvidersCodecRegistry{codecProviders=[ValueCodecProvider{}, BsonValueCodecProvider{}, DBRefCodecProvider{}, DBObjectCodecProvider{}, DocumentCodecProvider{}, CollectionCodecProvider{}, IterableCodecProvider{}, MapCodecProvider{}, GeoJsonCodecProvider{}, GridFSFileCodecProvider{}, Jsr310CodecProvider{}, JsonObjectCodecProvider{}, BsonCodecProvider{}, EnumCodecProvider{}, com.mongodb.Jep395RecordCodecProvider@31866cc0]}, ProvidersCodecRegistry{codecProviders=[org.bson.codecs.pojo.PojoCodecProvider@16a39e9e]}]}, clusterSettings={hosts=[127.0.0.1:27018, localhost:27017], srvServiceName=mongodb, mode=MULTIPLE, requiredClusterType=REPLICA_SET, requiredReplicaSetName='rs0', serverSelector='null', clusterListeners='[]', serverSelectionTimeout='30000 ms', localThreshold='30000 ms'}, socketSettings=SocketSettings{connectTimeoutMS=10000, readTimeoutMS=0, receiveBufferSize=0, sendBufferSize=0}, heartbeatSocketSettings=SocketSettings{connectTimeoutMS=10000, readTimeoutMS=10000, receiveBufferSize=0, sendBufferSize=0}, connectionPoolSettings=ConnectionPoolSettings{maxSize=100, minSize=0, maxWaitTimeMS=120000, maxConnectionLifeTimeMS=0, maxConnectionIdleTimeMS=0, maintenanceInitialDelayMS=0, maintenanceFrequencyMS=60000, connectionPoolListeners=[], maxConnecting=2}, serverSettings=ServerSettings{heartbeatFrequencyMS=10000, minHeartbeatFrequencyMS=500, serverListeners='[]', serverMonitorListeners='[]'}, sslSettings=SslSettings{enabled=false, invalidHostNameAllowed=false, context=null}, applicationName='null', compressorList=[], uuidRepresentation=UNSPECIFIED, serverApi=null, autoEncryptionSettings=null, contextProvider=null}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Marking the connection pool for ServerId{clusterId=ClusterId{value='6388c5767b7dc612df9baf70', description='null'}, address=127.0.0.1:27018} as 'ready'
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Pruning pooled connections to 127.0.0.1:27018
2022-12-01 16:17:10 [TRACE] org.mongodb.driver.cluster  Handling description changed event for server 127.0.0.1:27018 with description ServerDescription{address=127.0.0.1:27018, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=77747506, setName='rs0', canonicalAddress=127.0.0.1:27018, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6377c029d83b658f8610ef42, counter=904}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942136167433}
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Adding discovered server 127.0.0.1:27017 to client view of cluster
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Adding discovered server 127.0.0.1:27019 to client view of cluster
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.cluster  Updating cluster description to  {type=REPLICA_SET, servers=[{address=localhost:27017, type=UNKNOWN, state=CONNECTING}, {address=127.0.0.1:27019, type=UNKNOWN, state=CONNECTING}, {address=127.0.0.1:27018, type=REPLICA_SET_SECONDARY, roundTripTime=77.7 ms, state=CONNECTED}, {address=127.0.0.1:27017, type=UNKNOWN, state=CONNECTING}]
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.cluster  Checking status of 127.0.0.1:27018
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Marking the connection pool for ServerId{clusterId=ClusterId{value='6388c5767b7dc612df9baf70', description='null'}, address=localhost:27017} as 'ready'
2022-12-01 16:17:10 [TRACE] org.mongodb.driver.cluster  Handling description changed event for server localhost:27017 with description ServerDescription{address=localhost:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=77683719, setName='rs0', canonicalAddress=127.0.0.1:27017, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=7fffffff000000000000083c, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02881867a66f6c2b5f5, counter=1056}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942136167388}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Pruning pooled connections to localhost:27017
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Server localhost:27017 is no longer a member of the replica set.  Removing from client view of cluster.
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:5, serverValue:3361}] to 127.0.0.1:27017
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=6488519, setName='rs0', canonicalAddress=127.0.0.1:27017, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=7fffffff000000000000083c, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02881867a66f6c2b5f5, counter=1056}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942154046105}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:7, serverValue:1471}] to 127.0.0.1:27019
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Closing connection connectionId{localValue:4, serverValue:3360}
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Monitor thread successfully connected to server with description ServerDescription{address=127.0.0.1:27019, type=REPLICA_SET_ARBITER, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=6084508, setName='rs0', canonicalAddress=127.0.0.1:27019, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02afd13471e0a632423, counter=392}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942154578202}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:6, serverValue:3362}] to 127.0.0.1:27017
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Closing connection connectionId{localValue:1, serverValue:3359}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Opened connection [connectionId{localValue:8, serverValue:1472}] to 127.0.0.1:27019
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Discovered replica set primary localhost:27017 with max election id 7fffffff000000000000083c and max set version 1
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Marking the connection pool for ServerId{clusterId=ClusterId{value='6388c5767b7dc612df9baf70', description='null'}, address=127.0.0.1:27017} as 'ready'
2022-12-01 16:17:10 [TRACE] org.mongodb.driver.cluster  Handling description changed event for server 127.0.0.1:27017 with description ServerDescription{address=127.0.0.1:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=6488519, setName='rs0', canonicalAddress=127.0.0.1:27017, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=7fffffff000000000000083c, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02881867a66f6c2b5f5, counter=1056}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942154046105}
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.connection  Pruning pooled connections to 127.0.0.1:27017
2022-12-01 16:17:10 [INFO ] org.mongodb.driver.cluster  Discovered replica set primary 127.0.0.1:27017 with max election id 7fffffff000000000000083c and max set version 1
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.cluster  Updating cluster description to  {type=REPLICA_SET, servers=[{address=127.0.0.1:27019, type=UNKNOWN, state=CONNECTING}, {address=127.0.0.1:27018, type=REPLICA_SET_SECONDARY, roundTripTime=77.7 ms, state=CONNECTED}, {address=127.0.0.1:27017, type=REPLICA_SET_PRIMARY, roundTripTime=6.5 ms, state=CONNECTED}]
2022-12-01 16:17:10 [DEBUG] org.mongodb.driver.cluster  Checking status of 127.0.0.1:27017
2022-12-01 16:17:11 [TRACE] org.mongodb.driver.cluster  Handling description changed event for server 127.0.0.1:27019 with description ServerDescription{address=127.0.0.1:27019, type=REPLICA_SET_ARBITER, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=6084508, setName='rs0', canonicalAddress=127.0.0.1:27019, hosts=[127.0.0.1:27017, 127.0.0.1:27018], passives=[], arbiters=[127.0.0.1:27019], primary='127.0.0.1:27017', tagSet=TagSet{[]}, electionId=null, setVersion=1, topologyVersion=TopologyVersion{processId=6377c02afd13471e0a632423, counter=392}, lastWriteDate=Thu Dec 01 15:17:03 UTC 2022, lastUpdateTimeNanos=303942154578202}
2022-12-01 16:17:11 [DEBUG] org.mongodb.driver.cluster  Updating cluster description to  {type=REPLICA_SET, servers=[{address=127.0.0.1:27019, type=REPLICA_SET_ARBITER, roundTripTime=6.1 ms, state=CONNECTED}, {address=127.0.0.1:27018, type=REPLICA_SET_SECONDARY, roundTripTime=77.7 ms, state=CONNECTED}, {address=127.0.0.1:27017, type=REPLICA_SET_PRIMARY, roundTripTime=6.5 ms, state=CONNECTED}]
2022-12-01 16:17:11 [DEBUG] org.mongodb.driver.cluster  Checking status of 127.0.0.1:27019
Exception in thread "cluster-ClusterId{value='6388c5767b7dc612df9baf70', description='null'}-localhost:27017" com.mongodb.MongoInterruptedException: Interrupted waiting for lock
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:49)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.BaseCluster.updateDescription(BaseCluster.java:247)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.updateDescription(AbstractMultiServerCluster.java:385)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.lambda$onChange$3(AbstractMultiServerCluster.java:214)
    at com.mongodb.internal.Locks.lambda$withLock$0(Locks.java:30)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:43)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.onChange(AbstractMultiServerCluster.java:164)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.updateDescription(DefaultSdamServerDescriptionManager.java:113)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.lambda$update$0(DefaultSdamServerDescriptionManager.java:75)
    at com.mongodb.internal.Locks.lambda$withLock$0(Locks.java:30)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:43)
    at com.mongodb.internal.Locks.withLock(Locks.java:36)
    at com.mongodb.internal.Locks.withLock(Locks.java:29)
    at com.mongodb.internal.connection.BaseCluster.withLock(BaseCluster.java:275)
    at com.mongodb.internal.connection.AbstractMultiServerCluster.withLock(AbstractMultiServerCluster.java:54)
    at com.mongodb.internal.connection.DefaultSdamServerDescriptionManager.update(DefaultSdamServerDescriptionManager.java:60)
    at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:170)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.InterruptedException
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
    at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
    at com.mongodb.internal.Locks.checkedWithLock(Locks.java:41)
    ... 25 more 

Good to hear that you are already on the virtual threads topic

Feel free to ask more.

Regards,

Comment by Jeffrey Yemin [ 01/Dec/22 ]

I think this is harmless, but can you provide the following information so I can check a hypothesis:

  1. The output of rs.status() from the mongo shell
  2. The output of debug level logging for the org.mongodb.driver.cluster component

(It's normal for the server monitor to be interrupted in some cases. The difference in 4.8.0 is that we replaced a synchronized block with a ReentrantLock in a few places in order to provide better interoperability with virtual threads. A synchronized block is not interruptible, but a ReentrantLock is.).

Comment by Maxence Warzecha [ 01/Dec/22 ]

Above exception visible in logs is shown only once when we init our application. After this exception all looks OK and no additional error are visible in logs.

Until we know if this is critical for us or not we switch to version `4.7.2` as this version does not show any exception (like version `4.2.3` before). 

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