Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-66777

FLE 2 internal transactions are being interrupted by logical session reaper

    • Fully Compatible
    • ALL
    • v6.0
    • Hide

      1. Start single node replica set, i.e. ./mongo --replSet test
      2. ./mongo --eval "rs.initiate();"
      3. Run script. It takes ~40 minutes to hit the error.

      db.getSiblingDB("test").dropDatabase();
      
      db.keystore.drop();
      
      const localKMS = {
          key: BinData(
              0,
              "/tu9jUCBqZdwCelwE/EAm/4WqdxrSMi04B8e9uAV+m30rI1J2nhKZZtQjdvsSCwuI4erR6IEcEK+5eGUAODv43NDNIR9QheT2edWFewUfHKsl9cnzTc86meIzOmYl6dr")
      };
      
      
      const clientSideFLEOptions = {
          kmsProviders: {
              local: localKMS,
          },
          keyVaultNamespace: "test.keystore",
          schemaMap: {},
      };
      
      const shell = Mongo("localhost:27017", clientSideFLEOptions);
      const edb = shell.getDB("test");
      
      const keyVault = shell.getKeyVault();
      
      keyVault.createKey(
          "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0");
      
      assert.commandWorked(db.createEncryptedCollection("basic", {
          encryptedFields: {
              "fields": [
                  {
                      "path": "ssn",
                      "keyId": keyVault.createKey(
                          "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"),
                      "bsonType": "string",
                      "queries": { "queryType": "equality" }
                  },
                  {
                      "path": "mobile",
                      "keyId": keyVault.createKey(
                          "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"),
                      "bsonType": "string",
                      "queries": { "queryType": "equality" }
                  },
                  {
                      "path": "gender",
                      "keyId": keyVault.createKey(
                          "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"),
                      "bsonType": "string",
                      "queries": { "queryType": "equality" }
                  }
              ]
          }
      }));
      
      print("Starting Load: " + new Date());
      
      for (let i = 0; i < 10000000; i++) {
          if (i % 100 == 0) { print(i + " ") }
      
          let mobile = Math.random().toString().slice(2, 11);
          mobile = mobile.slice(0, 3) + "-" + mobile.slice(3, 6) + "-" + mobile.slice(6);
      
          const ssn = Math.random().toString().slice(2, 11);
          const g = Math.floor(Math.random() * 10);
          const gender = g < 2 ? "they" : g < 6 ? "she" : "he";
      
          try {
              edb.basic.insertOne({
                  name: "John Doe",
                  mobile: mobile,
                  ssn: ssn,
                  address: "157 Electric Ave.",
                  gender: gender,
              });
          } catch (e) {
              let d = new Date();
              print("\nException on load: " + d + "||" + e);
          }
      }
      
      print("Done loading: " + new Date())
      

      4. After 40 minutes, operations will be interrupted and visible in the shell as follows

      Exception on load: <DATE> ||WriteError({
          "index": 0,
          "code" : 11601,
          "errmsg" : "operation was interrupted",
          ... 
      })
      
      Show
      1. Start single node replica set, i.e. ./mongo --replSet test 2. ./mongo --eval "rs.initiate();" 3. Run script. It takes ~40 minutes to hit the error. db.getSiblingDB("test").dropDatabase(); db.keystore.drop(); const localKMS = { key: BinData( 0, "/tu9jUCBqZdwCelwE/EAm/4WqdxrSMi04B8e9uAV+m30rI1J2nhKZZtQjdvsSCwuI4erR6IEcEK+5eGUAODv43NDNIR9QheT2edWFewUfHKsl9cnzTc86meIzOmYl6dr") }; const clientSideFLEOptions = { kmsProviders: { local: localKMS, }, keyVaultNamespace: "test.keystore", schemaMap: {}, }; const shell = Mongo("localhost:27017", clientSideFLEOptions); const edb = shell.getDB("test"); const keyVault = shell.getKeyVault(); keyVault.createKey( "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"); assert.commandWorked(db.createEncryptedCollection("basic", { encryptedFields: { "fields": [ { "path": "ssn", "keyId": keyVault.createKey( "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"), "bsonType": "string", "queries": { "queryType": "equality" } }, { "path": "mobile", "keyId": keyVault.createKey( "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"), "bsonType": "string", "queries": { "queryType": "equality" } }, { "path": "gender", "keyId": keyVault.createKey( "local", "arn:aws:kms:us-east-1:579766882180:key/89fcc2c4-08b0-4bd9-9f25-e3687b580d0"), "bsonType": "string", "queries": { "queryType": "equality" } } ] } })); print("Starting Load: " + new Date()); for (let i = 0; i < 10000000; i++) { if (i % 100 == 0) { print(i + " ") } let mobile = Math.random().toString().slice(2, 11); mobile = mobile.slice(0, 3) + "-" + mobile.slice(3, 6) + "-" + mobile.slice(6); const ssn = Math.random().toString().slice(2, 11); const g = Math.floor(Math.random() * 10); const gender = g < 2 ? "they" : g < 6 ? "she" : "he"; try { edb.basic.insertOne({ name: "John Doe", mobile: mobile, ssn: ssn, address: "157 Electric Ave.", gender: gender, }); } catch (e) { let d = new Date(); print("\nException on load: " + d + "||" + e); } } print("Done loading: " + new Date()) 4. After 40 minutes, operations will be interrupted and visible in the shell as follows Exception on load: <DATE> ||WriteError({ "index": 0, "code" : 11601, "errmsg" : "operation was interrupted", ... })
    • Sharding NYC 2022-05-30, Sharding NYC 2022-06-13

      While performance testing FLE 2, we have observed some internal transactions are being interrupted during the load phase. In our simple tests, we use a single connection from the mongo shell and load one document at a time. After approximately 30 minutes, the logical session cache reaper interrupts FLE 2 internal transactions approximately every 5 minutes.

      The same single connection is used through the load phase. The same lsid is used.

      This issue can also be repro with the node.js driver.

            Assignee:
            cheahuychou.mao@mongodb.com Cheahuychou Mao
            Reporter:
            mark.benvenuto@mongodb.com Mark Benvenuto
            Votes:
            0 Vote for this issue
            Watchers:
            9 Start watching this issue

              Created:
              Updated:
              Resolved: