[JAVA-4453] ClientSession.withTransaction doesn't respect serverSelectionTimeout when no eligible servers detected Created: 26/Jan/22  Updated: 27/Oct/23  Resolved: 26/Jan/22

Status: Closed
Project: Java Driver
Component/s: Transaction Management
Affects Version/s: None
Fix Version/s: None

Type: Question Priority: Major - P3
Reporter: Alex Bevilacqua Assignee: Jeffrey Yemin
Resolution: Works as Designed Votes: 0
Labels: internal-user
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to DRIVERS-2185 withTransaction should not retry afte... Backlog
Case:

 Description   

When using the ClientSession.withTransaction helper the MongoClient's serverSelectionTimeout value is not respected.

This same behavior does not happen if the transaction is manually created using ClientSession.startTransaction() and committed using ClientSession.commitTransaction

# setup
mlaunch init --replicaset --nodes 3 --hostname 192.168.2.13 --bind_ip_all --binarypath $(m bin 5.0.5-ent)

pom.xml

Show all

1
<?xml version="1.0" encoding="UTF-8"?>
2
 
3
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
4
  <modelVersion>4.0.0</modelVersion>
5
 
6
  <groupId>com.example</groupId>
7
  <artifactId>demo</artifactId>
8
  <version>1.0-SNAPSHOT</version>
9
 
10
  <name>demo</name>
11
  <!-- FIXME change it to the project's website -->
12
  <url>http://www.example.com</url>
13
 
14
  <properties>
15
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
16
    <maven.compiler.source>1.8</maven.compiler.source>
17
    <maven.compiler.target>1.8</maven.compiler.target>
18
  </properties>
19
 
20
  <dependencies>
21
    <dependency>
22
      <groupId>org.mongodb</groupId>
23
      <artifactId>mongodb-driver-sync</artifactId>
24
      <version>4.4.0</version>
25
    </dependency>
26
  </dependencies>
27
 
28
  <build>
29
    <pluginManagement>
30
      <!-- lock down plugins versions to avoid using Maven defaults (may be moved to parent pom) -->
31
      <plugins>
32
        <!-- clean lifecycle, see https://maven.apache.org/ref/current/maven-core/lifecycles.html#clean_Lifecycle -->
33
        <plugin>
34
          <artifactId>maven-clean-plugin</artifactId>
35
          <version>3.1.0</version>
36
        </plugin>
37
        <!-- default lifecycle, jar packaging: see https://maven.apache.org/ref/current/maven-core/default-bindings.html#Plugin_bindings_for_jar_packaging -->
38
        <plugin>
39
          <artifactId>maven-resources-plugin</artifactId>
40
          <version>3.0.2</version>
41
        </plugin>
42
        <plugin>
43
          <artifactId>maven-compiler-plugin</artifactId>
44
          <version>3.8.0</version>
45
        </plugin>
46
        <plugin>
47
          <artifactId>maven-surefire-plugin</artifactId>
48
          <version>2.22.1</version>
49
        </plugin>
50
        <plugin>
51
          <artifactId>maven-jar-plugin</artifactId>
52
          <version>3.0.2</version>
53
        </plugin>
54
        <plugin>
55
          <artifactId>maven-install-plugin</artifactId>
56
          <version>2.5.2</version>
57
        </plugin>
58
        <plugin>
59
          <artifactId>maven-deploy-plugin</artifactId>
60
          <version>2.8.2</version>
61
        </plugin>
62
        <!-- site lifecycle, see https://maven.apache.org/ref/current/maven-core/lifecycles.html#site_Lifecycle -->
63
        <plugin>
64
          <artifactId>maven-site-plugin</artifactId>
65
          <version>3.7.1</version>
66
        </plugin>
67
        <plugin>
68
          <artifactId>maven-project-info-reports-plugin</artifactId>
69
          <version>3.0.0</version>
70
        </plugin>
71
      </plugins>
72
    </pluginManagement>
73
  </build>
74
</project>

EmptyServerSelector.java

Show all

1
package com.example;
2
 
3
import java.util.ArrayList;
4
import java.util.List;
5
import java.util.logging.Logger;
6
 
7
import com.mongodb.connection.ClusterDescription;
8
import com.mongodb.connection.ServerDescription;
9
import com.mongodb.selector.ServerSelector;
10
 
11
public class EmptyServerSelector implements ServerSelector {
12
  private static Logger LOGGER = null;
13
  static {
14
    System.setProperty("java.util.logging.SimpleFormatter.format", "[%1$tF %1$tT] [%4$-7s] %5$s %n");
15
    LOGGER = Logger.getLogger(EmptyServerSelector.class.getName());
16
  }
17
 
18
  @Override
19
  public List<ServerDescription> select(ClusterDescription clusterDescription) {
20
    LOGGER.info("Returning empty list of server descriptions");
21
    return new ArrayList<>();
22
  }
23
}

ServerSelectionTxnLoopTest.java

Show all

1
package com.example;
2
 
3
import java.util.Arrays;
4
import java.util.List;
5
import java.util.concurrent.TimeUnit;
6
 
7
import com.mongodb.*;
8
import com.mongodb.client.*;
9
import com.mongodb.client.result.UpdateResult;
10
 
11
import org.bson.Document;
12
import org.bson.conversions.Bson;
13
 
14
import static com.mongodb.client.model.Updates.inc;
15
import static com.mongodb.client.model.Filters.*;
16
 
17
public class ServerSelectionTxnLoopTest {
18
  private static Bson _filter = eq("_id", 1);
19
  private static Bson _update = inc("items.$.quantity", 2);
20
  private static MongoCollection<Document> _coll;
21
 
22
  private static void usingManualTransaction(ClientSession session) {
23
    session.startTransaction(TransactionOptions.builder().writeConcern(WriteConcern.MAJORITY).build());
24
    _coll.updateOne(session, _filter, _update);
25
    session.commitTransaction();
26
  }
27
 
28
  private static void usingWithTransaction(ClientSession session) {
29
    TransactionBody<UpdateResult> txnUpdateBody = () -> _coll.updateOne(session, _filter, _update);
30
    session.withTransaction(txnUpdateBody);
31
  }
32
 
33
  public static void main(final String[] args) {
34
    List<ServerAddress> hosts = Arrays.asList(
35
        new ServerAddress("192.168.2.13:27017"),
36
        new ServerAddress("192.168.2.13:27018"),
37
        new ServerAddress("192.168.2.13:27019"));
38
 
39
    MongoClient client = MongoClients.create(
40
        MongoClientSettings.builder()
41
            .applyToClusterSettings(builder -> builder
42
                .hosts(hosts)
43
                .serverSelector(new EmptyServerSelector())
44
                .serverSelectionTimeout(2, TimeUnit.SECONDS))
45
            .build());
46
 
47
    System.out.println("MongoClient created with a serverSelectionTimeout of 2 seconds");
48
 
49
    MongoDatabase db = client.getDatabase("test");
50
    _coll = db.getCollection("foo");
51
 
52
    ClientSession session = client.startSession();
53
    try {
54
      // usingManualTransaction(session); // this one will work
55
      usingWithTransaction(session); // this one will FAIL
56
 
57
    } catch (MongoCommandException | MongoWriteException e) {
58
      session.abortTransaction();
59
    } finally {
60
      session.close();
61
    }
62
  }
63
}

If the above code is run with usingManualTransaction(session) uncommented, the application will exit with a MongoTimeoutException being raised after 2 seconds (as expected)

MongoClient created with a serverSelectionTimeout of 2 seconds
[2022-01-26 14:54:05] [INFO   ] Returning empty list of server descriptions 
... 
[2022-01-26 14:54:07] [INFO   ] Returning empty list of server descriptions 
Exception in thread "main" com.mongodb.MongoTimeoutException: Timed out after 2000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=SHARDED, servers=[{address=192.168.2.13:27019, type=SHARD_ROUTER, roundTripTime=34.5 ms, state=CONNECTED}, {address=192.168.2.13:27017, type=SHARD_ROUTER, roundTripTime=32.0 ms, state=CONNECTED}, {address=192.168.2.13:27018, type=SHARD_ROUTER, roundTripTime=34.8 ms, state=CONNECTED}]
        at com.mongodb.internal.connection.BaseCluster.createTimeoutException(BaseCluster.java:414)
        at com.mongodb.internal.connection.BaseCluster.selectServer(BaseCluster.java:122)
        at com.mongodb.internal.connection.AbstractMultiServerCluster.selectServer(AbstractMultiServerCluster.java:50)
        at com.mongodb.internal.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:128)
        at com.mongodb.client.internal.ClientSessionBinding.getPinnedConnectionSource(ClientSessionBinding.java:133) 
        at com.mongodb.client.internal.ClientSessionBinding.getWriteConnectionSource(ClientSessionBinding.java:102)  
        at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:581)
        at com.mongodb.internal.operation.OperationHelper.withSourceAndConnection(OperationHelper.java:562)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.lambda$execute$3(MixedBulkWriteOperation.java:232) 
        at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:65)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:268)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:84)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:212)
        at com.mongodb.client.internal.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:1010)  
        at com.mongodb.client.internal.MongoCollectionImpl.executeUpdate(MongoCollectionImpl.java:994)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:591)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:584)
        at com.example.App.usingManualTransaction(App.java:24)
        at com.example.App.main(App.java:54)

If however this is run with the usingWithTransaction(session) call uncommented the application will loop for 2 minutes and then exit, though the MongoTimeoutException that is thrown indicates the configured 2 second value:

MongoClient created with a serverSelectionTimeout of 2 seconds
[2022-01-26 14:07:53] [INFO   ] Returning empty list of server descriptions 
...
[2022-01-26 14:09:54] [INFO   ] Returning empty list of server descriptions
Exception in thread "main" com.mongodb.MongoTimeoutException: Timed out after 2000 ms while waiting for a server that matches WritableServerSelector. Client view of cluster state is {type=SHARDED, servers=[{address=192.168.2.13:27019, type=SHARD_ROUTER, roundTripTime=7.7 ms, state=CONNECTED}, {address=192.168.2.13:27017, type=SHARD_ROUTER, roundTripTime=7.7 ms, state=CONNECTED}, {address=192.168.2.13:27018, type=SHARD_ROUTER, roundTripTime=7.6 ms, state=CONNECTED}]
        at com.mongodb.internal.connection.BaseCluster.createTimeoutException(BaseCluster.java:414)
        at com.mongodb.internal.connection.BaseCluster.selectServer(BaseCluster.java:122)
        at com.mongodb.internal.connection.AbstractMultiServerCluster.selectServer(AbstractMultiServerCluster.java:50)
        at com.mongodb.internal.binding.ClusterBinding.getWriteConnectionSource(ClusterBinding.java:128)
        at com.mongodb.client.internal.ClientSessionBinding.getPinnedConnectionSource(ClientSessionBinding.java:133) 
        at com.mongodb.client.internal.ClientSessionBinding.getWriteConnectionSource(ClientSessionBinding.java:102)  
        at com.mongodb.internal.operation.OperationHelper.withSuppliedResource(OperationHelper.java:581)
        at com.mongodb.internal.operation.OperationHelper.withSourceAndConnection(OperationHelper.java:562)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.lambda$execute$3(MixedBulkWriteOperation.java:232) 
        at com.mongodb.internal.async.function.RetryingSyncSupplier.get(RetryingSyncSupplier.java:65)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:268)
        at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:84)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:212)
        at com.mongodb.client.internal.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:1010)  
        at com.mongodb.client.internal.MongoCollectionImpl.executeUpdate(MongoCollectionImpl.java:994)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:591)
        at com.mongodb.client.internal.MongoCollectionImpl.updateOne(MongoCollectionImpl.java:584)
        at com.example.App.lambda$0(App.java:29)
        at com.mongodb.client.internal.ClientSessionImpl.withTransaction(ClientSessionImpl.java:211)
        at com.mongodb.client.internal.ClientSessionImpl.withTransaction(ClientSessionImpl.java:199)
        at com.example.App.usingWithTransaction(App.java:30)
        at com.example.App.main(App.java:55)



 Comments   
Comment by Kenneth Robinson [ 27/Jan/22 ]

Ok, thanks for the explanation.  This is obviously a very contrived scenario where no servers are available, and clearly I have bigger issues at that point than an incorrect error message, but I didn't want it to get completely swept under the rug.

Comment by Jeffrey Yemin [ 27/Jan/22 ]

kroc8@allstate.com Works as Designed is a bit of a catch-all resolution. It just means that the code is doing what we intended it to do based on the specification. We can still consider changes to the specification to improve the user experience, and we are discussing that possibility.

Comment by Kenneth Robinson [ 26/Jan/22 ]

Surely it can't be as designed to throw an exception that indicates you've hit the server selection timeout when in fact you've hit the overall transaction timeout?  If nothing else, I'd hope for a clearer message for my logs.

Thanks!

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