Client Side Encryption schema error with MongoDB driver 4.3+

[rainerfrey-inxmail]

Hi,

there seems to be an incompatibility with the generated validation schema with encrypted properties and newer driver versions.
I have the following entity class, and use MongoJsonSchemaCreator to create the schema:

@Document( collection = "blockedEmails" )
@Encrypted( keyId = "#{ mongocrypt.keyId(#target) }", algorithm = AEAD_AES_256_CBC_HMAC_SHA_512_Deterministic )
public class EmailBlocklistEntryEntity {
    @Encrypted
    private String email;


    public String getEmail() {
        return email;
    }


    public void setEmail( String email ) {
        this.email = email;
    }
}

This creates the following schema:

{"encryptMetadata": {"keyId": [{"$binary": {"base64": "9MNyAMBdQFWAQ6IKUAt9Mw==", "subType": "04"}}], "algorithm": "AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic"}, "type": "object", "properties": {"email": {"encrypt": {"bsonType": "string", "algorithm": null}}}}

With driver version 4.3.4 and newer (didn't test 4.3.0-4.3.3), when creating a collection with this schema, I receive the following exception:

Caused by: org.springframework.data.mongodb.UncategorizedMongoDbException: Command failed with error 51084 (Location51084): 'Array elements must have bindata type UUID, found 3' on server nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017. The full response is {"ok": 0.0, "errmsg": "Array elements must have bindata type UUID, found 3", "code": 51084, "codeName": "Location51084", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1641832661, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "jZXcnJl4LpShCTnYIabMjNP9PDg=", "subType": "00"}}, "keyId": 7017886637933723649}}, "operationTime": {"$timestamp": {"t": 1641832661, "i": 1}}}; nested exception is com.mongodb.MongoCommandException: Command failed with error 51084 (Location51084): 'Array elements must have bindata type UUID, found 3' on server nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017. The full response is {"ok": 0.0, "errmsg": "Array elements must have bindata type UUID, found 3", "code": 51084, "codeName": "Location51084", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1641832661, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "jZXcnJl4LpShCTnYIabMjNP9PDg=", "subType": "00"}}, "keyId": 7017886637933723649}}, "operationTime": {"$timestamp": {"t": 1641832661, "i": 1}}}
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:140)
	at org.springframework.data.mongodb.core.MongoTemplate.potentiallyConvertRuntimeException(MongoTemplate.java:2906)
	at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:530)
	at org.springframework.data.mongodb.core.MongoTemplate.doCreateCollection(MongoTemplate.java:2405)
	at org.springframework.data.mongodb.core.MongoTemplate.createCollection(MongoTemplate.java:619)

With driver version 4.2.3 it works.

I'm not sure whether this is to be considered a bug in newer driver versions, or an incompatible but intended change that Spring Data MongoDB needs to adapt to. I'm using Spring Data MongoDB 3.3.0 in a Spring Boot 2.6.2 application.

I'm not familiar with the MongoDB driver code base but when looking through issues implemented in 4.3.x I came across this one that I assume could be related:
https://jira.mongodb.org/browse/JAVA-4140

This occurs with MongoDB Atlas versions 4.4 and 5.0.

[christophstrobl]

@jyemin any changes you are aware of that may be related to this?

[jyemin]

I'm not aware of anything in the driver. And it's strange because there is nothing I can see in the provided schema that corresponds to the error message (which is coming from the server, not the driver). If we can get a minimal reproducible example, we can take a closer look.

[rainerfrey-inxmail]

I can create an example application no problem.

[rainerfrey-inxmail]

So here is the example. In build.gradle, the version property downgrades the driver to 4.2.3. When I remove it or set it to a newer version, I get the exception.

https://github.com/rainerfrey-inxmail/spring-data-momgodb-csfle-example

[jyemin]

@rainerfrey-inxmail thanks for the example application. I'm still investigating, but one thing that I'm seeing that's different: even with the 4.2.3 driver I see the same exception. Can you confirm that when you run this application as is, with 4.2.3, you don't get the exception? Try dropping the collection in the database prior to running the example, to ensure you're starting with a clean slate.

[jyemin]

I can reproduce the issue, using the provided sample application. Here's what's happening:

1. The value of the uuidRepresentation setting is configured via org.springframework.boot.autoconfigure.mongo.MongoPropertiesClientSettingsBuilderCustomizer as JAVA_LEGACY, which means that all instances of java.util.UUID will be encoded as BSON Binary subtype 3
2. The data key is decoded by org.springframework.data.mongodb.util.encryption.EncryptionUtils#resolveKeyId as an instance of java.util.UUID.
3. The data key is added as an instance of java.util.UUID into the JSON schema document (of type org.bson.Document) that is passed as the validator when creating the collection.
4. The driver encodes that UUID as BSON binary subtype 3 in accordance with the configured UUID representation.

@rainerfrey-inxmail to work around the issue, I suggest that you tack on uuidRepresentation=standard to the uri, e.g. mongodb://localhost/?uuidRepresentation=standard. But only do this if you're not already relying on UUID encoding in any other parts of your application (i.e. none of your collections are already storing UUID values).

For the Spring team, I suggest that org.springframework.data.mongodb.util.encryption.EncryptionUtils#resolveKeyId be changed such that it returns an instance of org.bson.types.Binary rather than java.util.UUID. Note that the catch clause in that method will already do that:

  // This will return an instance of org.bson.types.Binary with binary subtype 4
  return org.bson.Document.parse("{ val : { $binary : { base64 : '" + potentialKeyId + "', subType : '04'} } }")
   					.get("val");

Assuming that's feasible, it will avoid the UUID encoding issue entirely.

[jyemin]

@rainerfrey-inxmail one other thing I found: there was a change in 4.3.0 that does affect the behavior of your application, though not in the way that you reported. With 4.2.3, I get the following exception:

java.lang.IllegalStateException: Failed to execute ApplicationRunner
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:761) ~[spring-boot-2.6.2.jar:2.6.2]
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:748) ~[spring-boot-2.6.2.jar:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:309) ~[spring-boot-2.6.2.jar:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1301) ~[spring-boot-2.6.2.jar:2.6.2]
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1290) ~[spring-boot-2.6.2.jar:2.6.2]
	at com.example.mongocsfleexample.MongoCsfleExampleApplication.main(MongoCsfleExampleApplication.java:10) ~[main/:na]
Caused by: org.bson.codecs.configuration.CodecConfigurationException: The uuidRepresentation has not been specified, so the UUID cannot be encoded.
	at org.bson.codecs.UuidCodec.encode(UuidCodec.java:72) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.UuidCodec.encode(UuidCodec.java:37) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.EncoderContext.encodeWithChildContext(EncoderContext.java:91) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeValue(DocumentCodec.java:203) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeIterable(DocumentCodec.java:225) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeValue(DocumentCodec.java:198) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeMap(DocumentCodec.java:217) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeValue(DocumentCodec.java:200) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.writeMap(DocumentCodec.java:217) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.encode(DocumentCodec.java:159) ~[bson-4.2.3.jar:na]
	at org.bson.codecs.DocumentCodec.encode(DocumentCodec.java:46) ~[bson-4.2.3.jar:na]
	at org.bson.Document.toJson(Document.java:440) ~[bson-4.2.3.jar:na]
	at org.bson.Document.toJson(Document.java:413) ~[bson-4.2.3.jar:na]
	at org.bson.Document.toJson(Document.java:400) ~[bson-4.2.3.jar:na]
	at com.example.mongocsfleexample.config.DefineEncryptionSchema.run(DefineEncryptionSchema.java:39) ~[main/:na]
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:758) ~[spring-boot-2.6.2.jar:2.6.2]
	... 5 common frames omitted

With 4.3.0, I don't get that exception. This is due to the fact that 4.3.0 includes a fix for https://jira.mongodb.org/browse/JAVA-4140.

However, I don't think it's directly relevant to your findings, since this exception is due to the log statement in com.example.mongocsfleexample.config.DefineEncryptionSchema#run:

        logger.info( sampleSchema.schemaDocument().toJson() );

[rainerfrey-inxmail]

@jyemin thank you so much for the investigation and the suggested workaround, I will apply this today.

With driver 4.2.3 I neither get the original exception, nor the CodecConfigurationException from your later comment. I'm running the application as is, just with MongoDB and key configured in application.yml. There is no exception output, and the collection is created with the schema validator option. ICTM I'm using Java 17.

spring-data-momgodb-csfle-example git:(main) ✗ ./gradlew dependencyInsight --dependency org.mongodb:mongodb-driver-sync

> Task :dependencyInsight
org.mongodb:mongodb-driver-sync:4.2.3 (selected by rule)
   variant "compile" [
      org.gradle.status              = release (not requested)
      org.gradle.usage               = java-api
      org.gradle.libraryelements     = jar (compatible with: classes)
      org.gradle.category            = library

      Requested attributes not found in the selected variant:
         org.gradle.dependency.bundling = external
         org.gradle.jvm.environment     = standard-jvm
         org.gradle.jvm.version         = 17
   ]

org.mongodb:mongodb-driver-sync:4.4.0 -> 4.2.3
\--- org.springframework.boot:spring-boot-starter-data-mongodb:2.6.2
     \--- compileClasspath (requested org.springframework.boot:spring-boot-starter-data-mongodb)

spring-data-momgodb-csfle-example git:(main) ✗ ./gradlew clean bootRun

> Task :bootRun

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.6.2)

2022-01-12 09:19:04.960  INFO 74955 --- [           main] c.e.m.MongoCsfleExampleApplication       : Starting MongoCsfleExampleApplication using Java 17.0.1 on xcom-rfy.local with PID 74955 (/Users/rfy/Developer/tmp/spring-data-momgodb-csfle-example/build/classes/java/main started by rfy in /Users/rfy/Developer/tmp/spring-data-momgodb-csfle-example)
2022-01-12 09:19:04.963  INFO 74955 --- [           main] c.e.m.MongoCsfleExampleApplication       : No active profile set, falling back to default profiles: default
2022-01-12 09:19:05.463  INFO 74955 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data MongoDB repositories in DEFAULT mode.
2022-01-12 09:19:05.502  INFO 74955 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 29 ms. Found 0 MongoDB repository interfaces.
2022-01-12 09:19:06.183  INFO 74955 --- [           main] org.mongodb.driver.cluster               : Cluster created with settings {hosts=[127.0.0.1:27017], srvHost=nxpv-squad2-test.c80ou.azure.mongodb.net, mode=MULTIPLE, requiredClusterType=REPLICA_SET, serverSelectionTimeout='30000 ms', requiredReplicaSetName='atlas-yh7h8n-shard-0'}
2022-01-12 09:19:06.208  INFO 74955 --- [ure.mongodb.net] org.mongodb.driver.cluster               : Adding discovered server nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017 to client view of cluster
2022-01-12 09:19:06.257  INFO 74955 --- [ure.mongodb.net] org.mongodb.driver.cluster               : Adding discovered server nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017 to client view of cluster
2022-01-12 09:19:06.258  INFO 74955 --- [ure.mongodb.net] org.mongodb.driver.cluster               : Adding discovered server nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017 to client view of cluster
2022-01-12 09:19:06.510  INFO 74955 --- [           main] c.e.m.MongoCsfleExampleApplication       : Started MongoCsfleExampleApplication in 2.489 seconds (JVM running for 2.972)
2022-01-12 09:19:06.914  INFO 74955 --- [           main] c.e.m.config.DefineEncryptionSchema      : {"encryptMetadata": {"keyId": [{"$binary": {"base64": "9MNyAMBdQFWAQ6IKUAt9Mw==", "subType": "04"}}], "algorithm": "AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic"}, "type": "object", "properties": {"email": {"encrypt": {"bsonType": "string", "algorithm": null}}}}
2022-01-12 09:19:06.961  INFO 74955 --- [           main] org.mongodb.driver.cluster               : No server chosen by com.mongodb.client.internal.MongoClientDelegate$1@74294c1a from cluster description ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, serverDescriptions=[ServerDescription{address=nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, type=UNKNOWN, state=CONNECTING}, ServerDescription{address=nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out
2022-01-12 09:19:07.010  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:2, serverValue:19579}] to nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.010  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:6, serverValue:19580}] to nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.011  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:1, serverValue:20192}] to nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.011  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:3, serverValue:20191}] to nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.010  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:4, serverValue:19783}] to nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.011  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:5, serverValue:19782}] to nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.028  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=323637681, setName='atlas-yh7h8n-shard-0', canonicalAddress=nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017, hosts=[nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017], passives=[], arbiters=[], primary='nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='EUROPE_WEST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=2, topologyVersion=TopologyVersion{processId=61dc5d4a84b159c3f9ad7cb4, counter=5}, lastWriteDate=Wed Jan 12 09:18:57 CET 2022, lastUpdateTimeNanos=132452719584228}
2022-01-12 09:19:07.028  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=326635844, setName='atlas-yh7h8n-shard-0', canonicalAddress=nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, hosts=[nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017], passives=[], arbiters=[], primary='nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='EUROPE_WEST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=7fffffff0000000000000020, setVersion=2, topologyVersion=TopologyVersion{processId=61dc5d324dd3d85b2b82930a, counter=8}, lastWriteDate=Wed Jan 12 09:18:57 CET 2022, lastUpdateTimeNanos=132452720686568}
2022-01-12 09:19:07.028  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Monitor thread successfully connected to server with description ServerDescription{address=nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, minWireVersion=0, maxWireVersion=13, maxDocumentSize=16777216, logicalSessionTimeoutMinutes=30, roundTripTimeNanos=322501319, setName='atlas-yh7h8n-shard-0', canonicalAddress=nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, hosts=[nxpv-squad2-test-shard-00-00.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017, nxpv-squad2-test-shard-00-01.c80ou.azure.mongodb.net:27017], passives=[], arbiters=[], primary='nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017', tagSet=TagSet{[Tag{name='nodeType', value='ELECTABLE'}, Tag{name='provider', value='AZURE'}, Tag{name='region', value='EUROPE_WEST'}, Tag{name='workloadType', value='OPERATIONAL'}]}, electionId=null, setVersion=2, topologyVersion=TopologyVersion{processId=61dc5d1b5735f6ccec7bd8af, counter=6}, lastWriteDate=Wed Jan 12 09:18:57 CET 2022, lastUpdateTimeNanos=132452720423570}
2022-01-12 09:19:07.031  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Setting max election id to 7fffffff0000000000000020 from replica set primary nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.031  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Setting max set version to 2 from replica set primary nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.032  INFO 74955 --- [ngodb.net:27017] org.mongodb.driver.cluster               : Discovered replica set primary nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.244  INFO 74955 --- [           main] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:7, serverValue:20193}] to nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017
2022-01-12 09:19:07.417  INFO 74955 --- [ionShutdownHook] org.mongodb.driver.connection            : Closed connection [connectionId{localValue:7, serverValue:20193}] to nxpv-squad2-test-shard-00-02.c80ou.azure.mongodb.net:27017 because the pool has been closed.

BUILD SUCCESSFUL in 6s
5 actionable tasks: 5 executed

// before
Atlas atlas-...-shard-0 [primary] test> db.sample.drop()
true
Atlas atlas-...-shard-0  [primary] test> db.getCollectionInfos()
[]
// after
Atlas atlas-...-shard-0  [primary] test> db.getCollectionInfos()
[
  {
    name: 'sample',
    type: 'collection',
    options: {
      validator: {
        '$jsonSchema': {
          encryptMetadata: {
            keyId: [ UUID("f4c37200-c05d-4055-8043-a20a500b7d33") ],
            algorithm: 'AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic'
          },
          type: 'object',
          properties: { email: { encrypt: [Object] } }
        }
      }
    },
    info: {
      readOnly: false,
      uuid: UUID("8ce0b188-3c6a-4e90-af6a-71f0b09983f0")
    },
    idIndex: { v: 2, key: { _id: 1 }, name: '_id_' }
  }
]

[rainerfrey-inxmail]

I can confirm that setting the uuid representation to standard solves the issue with driver 4.4.0.