[JAVA-3248] Why does Mongo driver not retry writes during ReplicaSet elections when retryWrites=true ? Created: 27/Mar/19  Updated: 11/Sep/19  Resolved: 29/Apr/19

Status: Closed
Project: Java Driver
Component/s: Write Operations
Affects Version/s: 3.8.2
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Satish Anupindi Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

MongoDB 3 member replica set running 4.0.5 enterprise



 Description   

We have a 3 member replica set in our lab environment. We have set retryWrites=true in the connection string in our Java client. 
The issue is when I stop the primary member (to force an election) I expect the write retries to start (once per failed write) and then the serverStatus command should give a number of the retry occurrences. We observe that some writes fail when the primary is taken down and db.serverStatus() shows retriedStatementsCount as 0

"transactions" : {
	"retriedCommandsCount" : NumberLong(0),
	"retriedStatementsCount" : NumberLong(0),
	"transactionsCollectionWriteCount" : NumberLong(0),
	"currentActive" : NumberLong(0),
	"currentInactive" : NumberLong(0),
	"currentOpen" : NumberLong(0),
	"totalAborted" : NumberLong(0),
	"totalCommitted" : NumberLong(0),
	"totalStarted" : NumberLong(0)
},

our connection string:

mongoClient = MongoClients.create("mongodb://"+config.getServers()+"/?readPreference=primary&retryWrites=true");

We see connection exceptions (as expected) when we shutdown the primary, but no evidence of retries.

2019-03-11 14:29:31.118  INFO 19804 --- [       thread-4] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:12, serverValue:7593}] to mrerh7mongodb1.phx.lab.aexp.com:27017 because there was a socket exception raised on another connection from this pool.
14:29:31 WARN  TestResource:415 - Exception! Thread: 4 Counter: 33073 Try: 2 uuid: 37ac2f43-0953-4a20-b420-9cde5c83f5e0 Message: com.mongodb.MongoQueryException Query failed with error code 11600 and error message 'Executor error during find command :: caused by :: interrupted at shutdown' on server mrerh7mongodb1.phx.lab.aexp.com:27017
[Ljava.lang.StackTraceElement;@44cccc6f
2019-03-11 14:29:31.120  INFO 19804 --- [       thread-2] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:11, serverValue:7592}] to mrerh7mongodb1.phx.lab.aexp.com:27017 because there was a socket exception raised on another connection from this pool.
14:29:31 WARN  TestResource:415 - Exception! Thread: 2 Counter: 33072 Try: 2 uuid: f8f41ba1-b450-4971-960b-845d5f97c11f Message: com.mongodb.MongoQueryException Query failed with error code 11600 and error message 'Executor error during find command :: caused by :: interrupted at shutdown' on server mrerh7mongodb1.phx.lab.aexp.com:27017
[Ljava.lang.StackTraceElement;@232f1aec
2019-03-11 14:29:31.121  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Exception in monitor thread while connecting to server mrerh7mongodb1.phx.lab.aexp.com:27017
 
com.mongodb.MongoNodeIsRecoveringException: Command failed with error 11600 (InterruptedAtShutdown): 'interrupted at shutdown' on server mrerh7mongodb1.phx.lab.aexp.com:27017. The full response is { "operationTime" : { "$timestamp" : { "t" : 1552339771, "i" : 8 } }, "ok" : 0.0, "errmsg" : "interrupted at shutdown", "code" : 11600, "codeName" : "InterruptedAtShutdown", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1552339771, "i" : 8 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }
	at com.mongodb.internal.connection.ProtocolHelper.createSpecialException(ProtocolHelper.java:246) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:175) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:293) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.CommandHelper.sendAndReceive(CommandHelper.java:83) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.CommandHelper.executeCommand(CommandHelper.java:38) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.lookupServerDescription(DefaultServerMonitor.java:180) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:124) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
 
2019-03-11 14:29:31.123  INFO 19804 --- [       thread-3] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:10, serverValue:7591}] to mrerh7mongodb1.phx.lab.aexp.com:27017 because there was a socket exception raised on another connection from this pool.
14:29:31 WARN  TestResource:415 - Exception! Thread: 3 Counter: 33071 Try: 2 uuid: 3fbc28a7-2a19-46b4-b01c-971844813fca Message: com.mongodb.MongoQueryException Query failed with error code 11600 and error message 'Executor error during find command :: caused by :: interrupted at shutdown' on server mrerh7mongodb1.phx.lab.aexp.com:27017
[Ljava.lang.StackTraceElement;@7e9c73ad
2019-03-11 14:29:31.125  INFO 19804 --- [       thread-1] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:8, serverValue:7590}] to mrerh7mongodb1.phx.lab.aexp.com:27017 because there was a socket exception raised on another connection from this pool.
14:29:31 WARN  TestResource:415 - Exception! Thread: 1 Counter: 33074 Try: 1 uuid: 7328dfcd-64f2-4a49-9e35-4cc044d2412d Message: com.mongodb.MongoQueryException Query failed with error code 11600 and error message 'Executor error during find command :: caused by :: interrupted at shutdown' on server mrerh7mongodb1.phx.lab.aexp.com:27017
[Ljava.lang.StackTraceElement;@2d1e42c1
2019-03-11 14:29:31.170  INFO 19804 --- [       thread-4] org.mongodb.driver.cluster               : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=482547, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:22 MST 2019, lastUpdateTimeNanos=14102993339268631}, ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=644952, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:22 MST 2019, lastUpdateTimeNanos=14102993340532632}]}. Waiting for 30000 ms before timing out
2019-03-11 14:29:31.171  INFO 19804 --- [       thread-2] org.mongodb.driver.cluster               : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=482547, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:22 MST 2019, lastUpdateTimeNanos=14102993339268631}, ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=644952, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:22 MST 2019, lastUpdateTimeNanos=14102993340532632}]}. Waiting for 30000 ms before timing out
2019-03-11 14:29:31.172  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=758063, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103002380566392}
2019-03-11 14:29:31.174  INFO 19804 --- [       thread-3] org.mongodb.driver.cluster               : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=758063, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103002380566392}, ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=748888, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103002379978826}]}. Waiting for 30000 ms before timing out
2019-03-11 14:29:31.178  INFO 19804 --- [       thread-1] org.mongodb.driver.cluster               : No server chosen by WritableServerSelector from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=758063, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103002380566392}, ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=748888, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb1.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103002379978826}]}. Waiting for 30000 ms before timing out
2019-03-11 14:29:31.624  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Exception in monitor thread while connecting to server mrerh7mongodb1.phx.lab.aexp.com:27017
 
com.mongodb.MongoSocketOpenException: Exception opening socket
	at com.mongodb.internal.connection.SocketChannelStream.open(SocketChannelStream.java:60) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:126) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:131) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: java.net.ConnectException: Connection refused
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[na:1.8.0_181]
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[na:1.8.0_181]
	at sun.nio.ch.SocketAdaptor.connect(SocketAdaptor.java:111) ~[na:1.8.0_181]
	at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:64) ~[mongodb-driver-core-3.8.2.jar!/:na]
	at com.mongodb.internal.connection.SocketChannelStream.open(SocketChannelStream.java:57) ~[mongodb-driver-core-3.8.2.jar!/:na]
	... 3 common frames omitted
 
2019-03-11 14:29:32.174  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=858686, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103003381993627}
2019-03-11 14:29:41.632  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:66, serverValue:11}] to mrerh7mongodb1.phx.lab.aexp.com:27017
2019-03-11 14:29:41.635  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=2805823, setName='rs_test', canonicalAddress=mrerh7mongodb1.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103012843688730}
2019-03-11 14:29:41.686  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=797898, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb3.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=7fffffff0000000000000006, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103012893818457}
2019-03-11 14:29:42.137  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb1.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=2427490, setName='rs_test', canonicalAddress=mrerh7mongodb1.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb3.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103013345289458}
2019-03-11 14:29:42.186  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb2.phx.lab.aexp.com:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=969137, setName='rs_test', canonicalAddress=mrerh7mongodb2.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb3.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=null, setVersion=2, lastWriteDate=Mon Mar 11 14:29:31 MST 2019, lastUpdateTimeNanos=14103013393877362}
2019-03-11 14:29:43.187  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=mrerh7mongodb3.phx.lab.aexp.com:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[4, 0, 5]}, minWireVersion=0, maxWireVersion=7, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=749316, setName='rs_test', canonicalAddress=mrerh7mongodb3.phx.lab.aexp.com:27017, hosts=[mrerh7mongodb3.phx.lab.aexp.com:27017, mrerh7mongodb1.phx.lab.aexp.com:27017, mrerh7mongodb2.phx.lab.aexp.com:27017], passives=[], arbiters=[], primary='mrerh7mongodb3.phx.lab.aexp.com:27017', tagSet=TagSet{[]}, electionId=7fffffff0000000000000006, setVersion=2, lastWriteDate=Mon Mar 11 14:29:43 MST 2019, lastUpdateTimeNanos=14103014395168298}
2019-03-11 14:29:43.187  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Setting max election id to 7fffffff0000000000000006 from replica set primary mrerh7mongodb3.phx.lab.aexp.com:27017
2019-03-11 14:29:43.187  INFO 19804 --- [.aexp.com:27017] org.mongodb.driver.cluster               : Discovered replica set primary mrerh7mongodb3.phx.lab.aexp.com:27017
2019-03-11 14:29:43.191  INFO 19804 --- [       thread-2] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:70, serverValue:60}] to mrerh7mongodb3.phx.lab.aexp.com:27017
2019-03-11 14:29:43.192  INFO 19804 --- [       thread-1] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:69, serverValue:59}] to mrerh7mongodb3.phx.lab.aexp.com:27017
2019-03-11 14:29:43.192  INFO 19804 --- [       thread-3] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:68, serverValue:58}] to mrerh7mongodb3.phx.lab.aexp.com:27017
14:29:43 INFO  TestResource:268 -  mongo spookreq SET Request took ### 12022 ### ms , UUID: 8d1dd443-91d1-46d5-9245-07230d553578
2019-03-11 14:29:43.193  INFO 19804 --- [       thread-4] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:71, serverValue:61}] to mrerh7mongodb3.phx.lab.aexp.com:27017
14:29:43 INFO  TestResource:275 - Cursor has 0 elements.

Why don't we see a >0 number of retry statements in the transactions subdocument in the db.severStatus() command? 



 Comments   
Comment by Jeffrey Yemin [ 06/Apr/19 ]

Looking at the document for serverStatus here, it seems that these counts are only of writes retried by the client where the first attempt actually succeeded but the client retries because it did not successfully receive the response (due to a networking issue, for example). In your case, the first attempt did not succeed, as evidenced by the MongoNodeIsRecoveringException exception, so from the server's perspective it's not a retried write (since it didn't even attempt to perform the first attempt, it doesn't remember anything about it).

Comment by Satish Anupindi [ 05/Apr/19 ]

Thanks Jeff. Yes, we see this. 

[root@mrerh7opsman6 tmp]# cat mongo-spring_retry_debug.log | grep -i retry
2019-04-05 10:36:03.524 DEBUG 23273 --- [nio-8080-exec-3] org.mongodb.driver.operation             : retryWrites set but one or more writeRequests do not support retryable writes
2019-04-05 10:43:50.499 DEBUG 23273 --- [       thread-2] org.mongodb.driver.operation             : Retrying operation INSERT due to an error "com.mongodb.MongoNodeIsRecoveringException: Command failed with error 11600 (InterruptedAtShutdown): 'interrupted at shutdown' on server mrerh7mongodb2.phx.lab.aexp.com:27017. The full response is { "operationTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "ok" : 0.0, "errmsg" : "interrupted at shutdown", "code" : 11600, "codeName" : "InterruptedAtShutdown", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }"
2019-04-05 10:43:50.499 DEBUG 23273 --- [       thread-4] org.mongodb.driver.operation             : Retrying operation INSERT due to an error "com.mongodb.MongoNodeIsRecoveringException: Command failed with error 11600 (InterruptedAtShutdown): 'interrupted at shutdown' on server mrerh7mongodb2.phx.lab.aexp.com:27017. The full response is { "operationTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "ok" : 0.0, "errmsg" : "interrupted at shutdown", "code" : 11600, "codeName" : "InterruptedAtShutdown", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }"
2019-04-05 10:43:50.500 DEBUG 23273 --- [       thread-1] org.mongodb.driver.operation             : Retrying operation INSERT due to an error "com.mongodb.MongoNodeIsRecoveringException: Command failed with error 11600 (InterruptedAtShutdown): 'interrupted at shutdown' on server mrerh7mongodb2.phx.lab.aexp.com:27017. The full response is { "operationTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "ok" : 0.0, "errmsg" : "interrupted at shutdown", "code" : 11600, "codeName" : "InterruptedAtShutdown", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1554486230, "i" : 40 } }, "signature" : { "hash" : { "$binary" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "$type" : "00" }, "keyId" : { "$numberLong" : "0" } } } }"

 

Comment by Jeffrey Yemin [ 27/Mar/19 ]

In scope of JAVA-2964 we added client-side logging of retry attempts.  It was released in the 3.10 driver.  Can you run your test again against 3.10.1 with DEBUG logging enabled for org.mongodb.driver.operation, and confirm that the driver is attempting to retry?

I also don't see any evidence of a failed write.  Do any of the writes actually throw an exception?  If so, can you include the stack trace?

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