Uploaded image for project: 'Node.js Driver'
  1. Node.js Driver
  2. NODE-3133

autoEncryption produces serverHeartbeatFailed - with MongoError typemismatch

XMLWordPrintableJSON

      When I try to use autoEncryption, serverHeartbeat produces failed with MongoError: typemismatch.

      I use:

      • module mongodb 3.6.4
      • module mongodb-client-encryption 1.2.1
      • mongo from dockerhub 4.4.3-bionic
      • node 12.18.3, typescript 4.1.3

      I am trying to use autoEncryption with this sample code.

      import fs from 'fs';
import { MongoClient, MongoClientOptions } from 'mongodb';
import delay from 'delay';
import { ClientEncryption } from 'mongodb-client-encryption';

process.on('uncaughtException', (ex) => {
  console.error('Uncaught Exception: %s', ex.message);
});

process.on('unhandledRejection', (re) => {
  console.error('Unhandled Rejection: %s', re);
  process.exit(1);
});

(async () => {
  const uri = 'mongodb://172.17.0.2:27017';
  console.log('URI: %s', uri);

  const masterKey = fs.readFileSync('master-key.txt');
  console.log('Master Key Read');

  const client = new MongoClient(uri, {
    appname: 'mongenc-plain',
    useUnifiedTopology: true,
    useNewUrlParser: true,
  } as MongoClientOptions);
  console.log('Try to connect');
  await client.connect();
  console.log('Connected');

  const dbName = 'test';
  const collName = 'col';
  const keyVaultNamespace = `${dbName}.datakeys`;
  const kmsProviders = {
    local: {
      key: masterKey,
    },
  };

  // Create new ClientEncryption.
  const clientEncryption = new ClientEncryption(client, {
    kmsProviders,
    keyVaultNamespace,
  })

  // Check for mySpecialKey.
  const db = client.db(dbName);
  const col = db.collection('datakeys');
  const resultDK = await col.find({ keyAltNames: 'mySpecialKey'}).limit(1).toArray();
  const dataKeyId = (typeof resultDK[0] !== 'undefined')
    ? resultDK[0]._id
    : await clientEncryption.createDataKey('local', { keyAltNames: ['mySpecialKey'] });

  const schemaMap = {
    [`${dbName}.${collName}`]: {
      bsonType: 'object',
      properties: {
        encryptedField: {
          encrypt: {
            keyId: [ dataKeyId ],
            bsonType: 'string',
            algorithm: 'AEAD_AES_256_CBC_HMAC_SHA_512-Deterministic'
          }
        }
      }
    }
  };

  const encryptedClient = new MongoClient(uri, {
    appname: 'mongenc-secure',
    useUnifiedTopology: true,
    autoEncryption: {
      keyVaultNamespace,
      kmsProviders,
      schemaMap,
      extraOptions: {
        mongocryptdSpawnPath: './bin/mongocryptd',
        mongocryptdSpawnArgs: ['--nounixsocket'],
      },
    },
  } as any);

  const mongoEvents = [
    // SDAM
    'serverOpening',
    'serverClosed',
    'serverDescriptionChanged',
    'serverHeartbeatFailed',
    'serverHeartbeatSucceeded',
    'topologyOpening',
    'topologyClosed',
    'topologyDescriptionChanged',
    // General
    'connect',
    'error',
    'parseError',
    'close',
    'timeout',
    'destroy',
  ];
  mongoEvents.forEach((e) => {
    client.on(e, () => {
      console.log('[%s] CLIENT event: %s', new Date().toISOString(), e);
    });
    encryptedClient.on(e, () => {
      console.log('[%s] ENCRYPT event: %s', new Date().toISOString(), e);
    });
  });

  await encryptedClient.connect();
  console.log('Encrypted client connect.');

  const dbSecure= encryptedClient.db(dbName);
  const collectionSecure = dbSecure.collection(collName);

  const sampleString = new Date().toISOString();
  console.log('Sample String:', sampleString);

  await collectionSecure.insertOne({ encryptedField: sampleString });
  const result = await collectionSecure.findOne({
    encryptedField: { $eq: sampleString },
  });
  console.log(result);

  // Delay to 12s to see whether heartbeat failed.
  await delay(12000);
  console.log('Delay');

  await encryptedClient.close();
  await client.close();
  console.log('Close client');
})();

      When I run the code, these are output at terminal.

      URI: mongodb://172.17.0.2:27017
Master Key Read
Try to connect
Connected
Top-level use of w, wtimeout, j, and fsync is deprecated. Use writeConcern instead.
[2021-03-02T03:34:21.622Z] ENCRYPT event: topologyOpening
[2021-03-02T03:34:21.622Z] ENCRYPT event: topologyDescriptionChanged
[2021-03-02T03:34:21.622Z] ENCRYPT event: serverOpening
[2021-03-02T03:34:21.624Z] ENCRYPT event: serverHeartbeatSucceeded
[2021-03-02T03:34:21.624Z] ENCRYPT event: serverDescriptionChanged
[2021-03-02T03:34:21.624Z] ENCRYPT event: topologyDescriptionChanged
Encrypted client connect.
Sample String: 2021-03-02T03:34:21.624Z
{
  _id: 603db23db0331d0ebc3fa25b,
  encryptedField: '2021-03-02T03:34:21.624Z'
}
*[2021-03-02T03:34:22.127Z] ENCRYPT event: serverHeartbeatFailed*
[2021-03-02T03:34:22.127Z] ENCRYPT event: serverDescriptionChanged
[2021-03-02T03:34:22.127Z] ENCRYPT event: topologyDescriptionChanged
[2021-03-02T03:34:31.608Z] CLIENT event: serverHeartbeatSucceeded
[2021-03-02T03:34:32.129Z] ENCRYPT event: serverHeartbeatSucceeded
[2021-03-02T03:34:32.129Z] ENCRYPT event: serverDescriptionChanged
[2021-03-02T03:34:32.130Z] ENCRYPT event: topologyDescriptionChanged
[2021-03-02T03:34:32.633Z] ENCRYPT event: serverHeartbeatFailed
[2021-03-02T03:34:32.633Z] ENCRYPT event: serverDescriptionChanged
[2021-03-02T03:34:32.633Z] ENCRYPT event: topologyDescriptionChanged
Delay
[2021-03-02T03:34:34.151Z] ENCRYPT event: serverHeartbeatSucceeded
[2021-03-02T03:34:34.151Z] ENCRYPT event: serverDescriptionChanged
[2021-03-02T03:34:34.151Z] ENCRYPT event: topologyDescriptionChanged
[2021-03-02T03:34:34.154Z] ENCRYPT event: serverClosed
[2021-03-02T03:34:34.154Z] ENCRYPT event: topologyClosed
[2021-03-02T03:34:34.155Z] ENCRYPT event: close
[2021-03-02T03:34:34.156Z] ENCRYPT event: close
[2021-03-02T03:34:34.157Z] CLIENT event: serverClosed
[2021-03-02T03:34:34.157Z] CLIENT event: topologyClosed
[2021-03-02T03:34:34.157Z] CLIENT event: close
[2021-03-02T03:34:34.157Z] CLIENT event: close
Close client

      Field encryptedField gets encrypted succesfully, but I see log serverHeartbeatFailed. When I disable autoEncryption, I do not see any log serverHeartbeatFailed.
      When I set logLevel at mongodb (level 2), I saw this message (time matched):

      {"t":{"$date":"2021-03-02T03:34:22.126+00:00"},"s":"D2", "c":"COMMAND",  "id":21965,   "ctx":"conn284","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"ismaster":true,"maxAwaitTimeMS":10000,"topologyVersion":{"processId":{"$oid":"603d9b17a2cd9fdbcafedefa"},"counter":0},"$db":"admin"}}}
{"t":{"$date":"2021-03-02T03:34:22.126+00:00"},"s":"D1", "c":"-",        "id":23074,   "ctx":"conn284","msg":"User assertion","attr":{"error":"TypeMismatch: BSON field 'TopologyVersion.counter' is the wrong type 'int', expected type 'long'","file":"src/mongo/idl/idl_parser.cpp","line":80}}
{"t":{"$date":"2021-03-02T03:34:22.126+00:00"},"s":"D1", "c":"COMMAND",  "id":21962,   "ctx":"conn284","msg":"Assertion while executing command","attr":{"command":"ismaster","db":"admin","commandArgs":{"ismaster":true,"maxAwaitTimeMS":10000,"topologyVersion":{"processId":{"$oid":"603d9b17a2cd9fdbcafedefa"},"counter":0},"$db":"admin"},"error":"TypeMismatch: BSON field 'TopologyVersion.counter' is the wrong type 'int', expected type 'long'"}}
{"t":{"$date":"2021-03-02T03:34:22.126+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn284","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","appName":"mongenc-secure","command":{"ismaster":true,"maxAwaitTimeMS":10000,"topologyVersion":{"processId":{"$oid":"603d9b17a2cd9fdbcafedefa"},"counter":0},"$db":"admin"},"numYields":0,"ok":0,"errMsg":"BSON field 'TopologyVersion.counter' is the wrong type 'int', expected type 'long'","errName":"TypeMismatch","errCode":14,"reslen":170,"locks":{},"protocol":"op_msg","durationMillis":0}}

            Assignee:
            eric.adum@mongodb.com Eric Adum (Inactive)
            Reporter:
            andreas@alterra.id Andreas Yulius Nugroho
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: