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

Singleton ClientEncryption object cause JVM crash after long idle time of application

XMLWordPrintableJSON

    • None
    • Fully Compatible
    • None
    • None
    • None
    • None
    • None
    • None

      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.

       

       

       

        1. mongo-error.txt
          1 kB

            Assignee:
            jeff.yemin@mongodb.com Jeffrey Yemin
            Reporter:
            rahual.harinkhede@gmail.com Rahul Harinkhede
            None
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: