deno: npm:mongodb fails on v1.35.1

September 18th

Just ran into the same problem while upgrading Deno. Currently stuck on 1.34.2 because it’s the only version that supports npm:mongodb and doesn’t have this bug.

@bartlomieju here’s a minimal and reliable reproduction with the latest version of Deno (1.36.3) and npm:mongo (5.8.1) and MongoDB server (on Ubuntu 22.04):

import { MongoClient } from "npm:mongodb@5.8.1"; 

let client = new MongoClient(`mongodb://localhost:27017/deno-bug-test`,  {});
let db = client.db("deno-bug-test");

// await db.collection("col1").deleteMany({});

// if collection is empty, insert 10 dummy docs for testing:
if(!await db.collection("col1").findOne({})) {
  console.log("Inserting dummy docs...");
  // note: it may be possible to reproduce with simpler docs than this - haven't tried to chisel them down
  let docs = await fetch("https://gist.githubusercontent.com/josephrocca/88db398d7785b96aacd037fbf1bdce7e/raw/63b5922460e149677f78e8b3280ffc792279b739/denoMongoDbDebugDummyDocs.json").then(r => r.json());
  for(let doc of docs) {
    await db.collection("col1").insertOne(doc);
  }
}

console.log("Starting...");

await Promise.all([
  db.collection("col1").find({}).limit(10).toArray(),
  db.collection("col1").find({}).limit(10).toArray(),
  db.collection("col1").find({}).limit(10).toArray(),
  db.collection("col1").find({}).limit(10).toArray(),
  db.collection("col1").find({}).limit(10).toArray(),
]);

console.log("Done.");

Some notes:

• It seems to only occur when several concurrent requests are sent to MongoDB
• The bug was introduced in 1.35.1
• The bug sometimes causes the query to hang indefinitely rather than throw an error (though I can’t reliably reproduce that - the above code just reproduces the errors).

There are several different types of errors that I get and they occur randomly depending on the data, so I think TillaTheHun0 is correct that there’s some sort of compression/decompression bug that’s feeding MongoDB driver some garbled data:

error: Uncaught BSONError: bad string length in bson
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2626:23)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2705:21)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at internalDeserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2538:12)
    at Object.deserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:4014:12)
    at BinMsg.parse (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/commands.js:461:54)
    at Connection.onMessage (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:178:21)
    at MessageStream.<anonymous> (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:61:60)
    at MessageStream.emit (ext:deno_node/_stream.mjs:1852:9)

error: Uncaught (in promise) MongoParseError: Invalid message size: 539784052, max allowed: 67108864
    at processIncomingData (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:93:25)
    at MessageStream._write (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:33:9)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3948:16)
    at _write (ext:deno_node/_stream.mjs:3893:14)
    at MessageStream.Writable.write (ext:deno_node/_stream.mjs:3896:14)
    at Socket.ondata (ext:deno_node/_stream.mjs:3180:26)
    at Socket.emit (ext:deno_node/_stream.mjs:1852:9)
    at addChunk (ext:deno_node/_stream.mjs:2874:16)
    at readableAddChunk (ext:deno_node/_stream.mjs:2853:13)
    at Socket.Readable.push (ext:deno_node/_stream.mjs:2792:14)

error: Uncaught (in promise) BSONError: Invalid UTF-8 string in BSON document
    at getValidatedString (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:3003:27)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2628:21)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2705:21)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at internalDeserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2538:12)
    at Object.deserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:4014:12)
    at BinMsg.parse (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/commands.js:461:54)
    at Connection.onMessage (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:178:21)
    at MessageStream.<anonymous> (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:61:60)

error: Uncaught (in promise) MongoParseError: Invalid message size: -234851216
    at processIncomingData (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:90:25)
    at MessageStream._write (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:33:9)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3948:16)
    at _write (ext:deno_node/_stream.mjs:3893:14)
    at MessageStream.Writable.write (ext:deno_node/_stream.mjs:3896:14)
    at Socket.ondata (ext:deno_node/_stream.mjs:3180:26)
    at Socket.emit (ext:deno_node/_stream.mjs:1852:9)
    at addChunk (ext:deno_node/_stream.mjs:2874:16)
    at readableAddChunk (ext:deno_node/_stream.mjs:2853:13)
    at Socket.Readable.push (ext:deno_node/_stream.mjs:2792:14)

error: Uncaught (in promise) BSONError: Detected unknown BSON type 96 for fieldname "28"
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2967:19)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2705:21)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2705:21)
    at deserializeObject (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2687:25)
    at internalDeserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2538:12)
    at Object.deserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:4014:12)
    at BinMsg.parse (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/commands.js:461:54)
    at Connection.onMessage (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:178:21)
    at MessageStream.<anonymous> (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:61:60)

error: Uncaught (in promise) BSONError: One object, sized correctly, with a spot for an EOO, but the EOO isn't 0x00
    at internalDeserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:2536:15)
    at Object.deserialize (file:///home/joe/.cache/deno/npm/registry.npmjs.org/bson/5.4.0/lib/bson.cjs:4014:12)
    at BinMsg.parse (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/commands.js:461:54)
    at Connection.onMessage (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:178:21)
    at MessageStream.<anonymous> (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/connection.js:61:60)
    at MessageStream.emit (ext:deno_node/_stream.mjs:1852:9)
    at processIncomingData (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:124:16)
    at MessageStream._write (file:///home/joe/.cache/deno/npm/registry.npmjs.org/mongodb/5.8.1/lib/cmap/message_stream.js:33:9)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3948:16)
    at _write (ext:deno_node/_stream.mjs:3893:14)

I am also seeing this issue when upgrading Deno >1.35.0. I can run code that queries a MongoDB Atlas Cluster on Deno 1.35.0 that will then intermittently throw errors on Deno 1.35.1. It seems a regression was introduced in Deno 1.35.1.

The issue only arose for me when there were concurrent operations being sent to the Node Mongo Driver ie. Promise.all

The error produced by the Node Mongo Driver is always either MongoParseError: Invalid message size or BSONError: bad string length in bson.

Looking at the release for Deno 1.35.1 I am noticing some changes to node/http and ext/http around compression. Perhaps that’s related to this issue, as all the errors i’m seeing have to do with message length.

Here’s a minimal reproduction (it uses the sample dataset provided by MongoDB Atlas, but you can change it to whatever):

import { MongoClient } from 'npm:mongodb@5.7.0'

const url = '<YOUR_MONGO_CONNECTION_STRING>'

const query = (db) => (collection) =>
  db
    .collection(collection)
    .find({}, { limit: 10 })
    .toArray()

async function main() {
  let client = new MongoClient(url)
  await client.connect()

  const db = client.db('sample_airbnb')

  await Promise.all(Array(10).fill('listingsAndReviews').map(query(db)))
    .then(res => console.log(res.length))
    .finally(() => client.close())
}

main()

I also experience this error intermittently and cannot share a reproduction because it only happens intermittently but here is my stack trace:

  full_error: MongoParseError: Invalid message size: 1415196742, max allowed: 67108864
    at processIncomingData (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/cmap/message_stream.js:93:25)
    at processIncomingData (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/cmap/message_stream.js:126:20)
    at MessageStream._write (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/cmap/message_stream.js:33:9)
    at writeOrBuffer (ext:deno_node/_stream.mjs:3948:16)
    at _write (ext:deno_node/_stream.mjs:3893:14)
    at MessageStream.Writable.write (ext:deno_node/_stream.mjs:3896:14)
    at TLSSocket.ondata (ext:deno_node/_stream.mjs:3180:26)
    at TLSSocket.emit (ext:deno_node/_stream.mjs:1852:9)
    at addChunk (ext:deno_node/_stream.mjs:2874:16)
    at readableAddChunk (ext:deno_node/_stream.mjs:2853:13) {
    [Symbol(errorLabels)]: Set(0) {}
  }
}

EDIT: I also get another error sometimes that I’ll just add here as well:

error MongoRuntimeError: Getmore must run on the same server operation began on
    at GetMoreOperation.executeCallback (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/operations/get_more.js:22:29)
    at file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/operations/operation.js:65:18
    at ext:deno_node/internal/util.mjs:93:15
    at new Promise (<anonymous>)
    at ext:deno_node/internal/util.mjs:78:12
    at GetMoreOperation.execute (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/operations/operation.js:66:11)
    at executeOperationAsync (file:///home/user/.cache/deno/npm/registry.npmjs.org/mongodb/5.7.0/lib/operations/execute_operation.js:82:36)
    at eventLoopTick (ext:core/01_core.js:183:11) {
  [Symbol(errorLabels)]: Set(0) {}
}

The lastest 1.36.3 can still repruduce this issue. Does anyone know which verion will fix this issue?

v1.37 will fix it, you can update to canary (deno upgrade --canary) which includes the fix.

@littledivy Just tested and can verify that it seems to be fixed - thanks!

Thanks for the report. We’ll try to debug it this week.

For now, I don’t think I have any useful reproduction code.

I wrote my website in Fresh, and I served some static resources for my web at a route. The route only reads binary data from mongodb with collection.findOne({ $or: conditions }). It occasionally fails and the only difference in error messages is the number of Invalid message size in MongoParseError: Invalid message size: 1882601779, max allowed: 67108864.

I guess it happens at TLS layer (TLSSocket in stack trace), but I don’t think my network is tampered with (man in the middle attack, etc.) as it would not occur if I used v1.35.0.

v1.35.2 has been released, so I will try with it.