[JAVA-4150] Singleton ClientEncryption object cause JVM crash after long idle time of application Created: 11/May/21  Updated: 27/Oct/23  Resolved: 02/Jun/21

Status: Closed
Project: Java Driver
Component/s: Client Side Encryption
Affects Version/s: 4.2.2
Fix Version/s: None

Type: Task Priority: Unknown
Reporter: Rahul Harinkhede Assignee: Jeffrey Yemin
Resolution: Gone away Votes: 0
Labels: external-user
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Java


Attachments: Text File mongo-error.txt    
Issue Links:
Related
Backwards Compatibility: Fully Compatible

 Description   

We have implemented field-level encryption using Mongo DB in our Spring boot application.

As per documentation, We need to create a ClientEncryption object to encrypt and decrypt any document field.

In the documentation create The suggested way to create ClientEncryption using ClientEncryptions.create() method .  

What problem we will face

  1. As we are creating ClientEncryption object every time. The application will have multiple open instances. Solution- We should use try with resources to get it close automatically.
  2. As the application will create object w.r to fields we have, i.e One encrypted filed one ClientEncryption object. Then we will face performance issue, as the creation of ClientEncryption is a heavy I/O operation. The suggested solution is to make it a singleton.
  3. we tried with making the singleton object for ClientEncryption, Initially the application works fine with improvement in performance, but after a certain amount of ideal time, once we try to call encrypt or decrypt method over a singleton instance, The object tries to add a new connection in the pool and then the application crash with attached error file(mongo-error.txt).

 

What solution we have applied. 

We have to create a new ClientEncryption object every time with a try with resources so that it should close automatically. 
But again we are facing slowness of response as is heavy I/O call, please check below logs.

 

2021-05-08 04:31:10.579  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Cluster created with settings {hosts=[127.0.0.1:27017], srvHost=xxxxxxxxxxxxxxxxx, mode=MULTIPLE, requiredClusterType=REPLICA_SET, serverSelectionTimeout='30000 ms', requiredReplicaSetName='atlas-elnpc1-shard-0'}
2021-05-08 04:31:10.591  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Cluster description not yet available. Waiting for 30000 ms before timing out
2021-05-08 04:31:10.624  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx:27017 to client view of cluster
2021-05-08 04:31:10.641  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx:27017 to client view of cluster
2021-05-08 04:31:10.651  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx.net:27017 to client view of cluster
2021-05-08 04:31:10.659  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : No server chosen by com.mongodb.client.internal.MongoClientDelegate$1@5f7c9808 from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx.net:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
2021-05-08 04:31:10.777  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:25, serverValue:332905}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.778  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=33980692, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969400603095094}
2021-05-08 04:31:10.780  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:26, serverValue:332906}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.788  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:27, serverValue:329529}] to xxxxxxxxxxxxxxxxx.net:27017
2021-05-08 04:31:10.788  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx.net:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=8409045, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx.net:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969400613779306}
2021-05-08 04:31:10.789  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx.net:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=8409045, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx.net:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969400613779306}]}. Waiting for 30000 ms before timing out
2021-05-08 04:31:10.797  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:24, serverValue:351595}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.805  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:23, serverValue:351596}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.817  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=90054030, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=7fffffff0000000000000032, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969400630936307}
2021-05-08 04:31:10.817  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Setting max election id to 7fffffff0000000000000032 from replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.818  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Setting max set version to 4 from replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.818  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Discovered replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:10.823  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:28, serverValue:329528}] to xxxxxxxxxxxxxxxxx.net:27017
2021-05-08 04:31:10.918  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.connection            [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Opened connection [connectionId{localValue:29, serverValue:351597}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.513  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Cluster created with settings {hosts=[127.0.0.1:27017], srvHost=xxxxxxxxxxxxxxxxx, mode=MULTIPLE, requiredClusterType=REPLICA_SET, serverSelectionTimeout='30000 ms', requiredReplicaSetName='atlas-elnpc1-shard-0'}
2021-05-08 04:31:11.518  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Cluster description not yet available. Waiting for 30000 ms before timing out
2021-05-08 04:31:11.519  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx:27017 to client view of cluster
2021-05-08 04:31:11.524  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx:27017 to client view of cluster
2021-05-08 04:31:11.538  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:30, serverValue:351598}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.539  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=12029551, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=7fffffff0000000000000032, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969401364173016}
2021-05-08 04:31:11.542  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:31, serverValue:351599}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.543  INFO 1 --- [ure.mongodb.net] org.mongodb.driver.cluster                : Adding discovered server xxxxxxxxxxxxxxxxx.net:27017 to client view of cluster
2021-05-08 04:31:11.580  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:32, serverValue:332907}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.594  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=34219299, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969401405451521}
2021-05-08 04:31:11.595  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.cluster               [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : No server chosen by com.mongodb.client.internal.MongoClientDelegate$1@1ca02847 from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=xxxxxxxxxxxxxxxxx.net:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
2021-05-08 04:31:11.597  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Setting max election id to 7fffffff0000000000000032 from replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.597  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Setting max set version to 4 from replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.597  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Discovered replica set primary xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.611  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:33, serverValue:332908}] to xxxxxxxxxxxxxxxxx:27017
2021-05-08 04:31:11.613  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:34, serverValue:329532}] to xxxxxxxxxxxxxxxxx.net:27017
2021-05-08 04:31:11.613  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.cluster                : Monitor thread successfully connected to server with description ServerDescription{address=xxxxxxxxxxxxxxxxx.net:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=8, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=35595539, setName='atlas-elnpc1-shard-0', canonicalAddress=xxxxxxxxxxxxxxxxx.net:27017, hosts=[xxxxxxxxxxxxxxxxx:27017, xxxxxxxxxxxxxxxxx.net:27017, xxxxxxxxxxxxxxxxx:27017], passives=[], arbiters=[], primary='xxxxxxxxxxxxxxxxx:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='US_EAST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=4, topologyVersion=null, lastWriteDate=Sat May 08 04:31:10 UTC 2021, lastUpdateTimeNanos=6969401438883197}
2021-05-08 04:31:11.617  INFO 1 --- [ngodb.net:27017] org.mongodb.driver.connection             : Opened connection [connectionId{localValue:35, serverValue:329533}] to xxxxxxxxxxxxxxxxx.net:27017
2021-05-08 04:31:11.691  INFO 1 --- [nio-8090-exec-3] org.mongodb.driver.connection            [e1a0ea7c-93b9-4faf-bc0d-a46cc5eb7019] : Opened connection [connectionId{localValue:36, serverValue:351600}] to xxxxxxxxxxxxxxxxx:27017

 

 

Step to reproduce

  1. Create Spring boot application
  2. Add mongo below jar
    1. 'mongodb-crypt', version: '1.1.0'
    2. 'mongodb-driver-core', version: '4.2.0'
    3. 'bson', version: '4.2.0'
    4. 'mongodb-driver-sync', version: '4.2.0'
  3. Follow this guide
  4. Create ClientEncryption object singleton.
  5. Have an API that performs encryption and description of the field.
  6. Hit the same API for 10-12 time
  7. Kept the application ideal for some time i.e 10-12 hr(We have observed this behaviour after 2-3 hr)
  8. Then hit the same API, the JVM will crash with the error attached in the file i.e (mongo-error.txt)

 

Actual Behaviour

With the singleton object of ClientEncryption, The JVM crash after 10-12 hr.

Expected Behaviour 

**Singleton Design pattern should be supported by ClientEncryption.

 

 

 



 Comments   
Comment by Backlog - Core Eng Program Management Team [ 02/Jun/21 ]

There hasn't been any recent activity on this ticket, so we're resolving it. Thanks for reaching out! Please feel free to comment on this if you're able to provide more information.

Comment by Jeffrey Yemin [ 14/May/21 ]

Please post the contents of /home/jboss/hs_err_pid1.log. I'd like to see that before we attempt to reproduce it.

Also, please let us know the JDK release you are using by running java -version.

Thanks,
Jeff

Comment by Rahul Harinkhede [ 14/May/21 ]

We have tried with both stable and lower versions of JDK, the behavior is the same. 
You are able to reproduce it if you follow the steps mentioned in the description.

With the singleton object, we have observed the issue.

If we are creating a new object every time it's working fine but we will run with a performance impact.

 

Please refer to the below code snippet, wherein we are creating ClientEncryption singleton.

 

private static ClientEncryption clientEncryption;
 
//We can call this method once the class load.
private void createClientEncryption(){
  String keyVaultNamespace = KEY_VAULT_DATABASE+"."+KEY_VAULT_COLLECTION;  ClientEncryptionSettings clientEncryptionSettings =   ClientEncryptionSettings.builder().keyVaultMongoClientSettings(MongoClientSettings.builder()  .applyConnectionString(new ConnectionString(DB_CONNECTION)).build()).keyVaultNamespace(keyVaultNamespace)  .kmsProviders(this.getKMSMap()).build();   clientEncryption = ClientEncryptions.create(clientEncryptionSettings);}
 
public ClientEncryption getClientEncryption() {
 return clientEncryption;
}

 

 

Comment by Jeffrey Yemin [ 13/May/21 ]

Hi rahual.harinkhede@gmail.com

Sorry to hear about the JVM crash. Can you post the /home/jboss/hs_err_pid1.log file referenced in mongo-error.txt? It seems like a JDK bug, but perhaps there is more information there that would be useful.

Comment by Rahul Harinkhede [ 13/May/21 ]

Can anyone look into this.

 

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