[SERVER-30362] JavaScript DBCollection.toString() stops working Created: 27/Jul/17  Updated: 30/Oct/23  Resolved: 17/Aug/17

Status: Closed
Project: Core Server
Component/s: JavaScript
Affects Version/s: 3.4.6, 3.5.10
Fix Version/s: 3.4.10, 3.5.12

Type: Bug Priority: Major - P3
Reporter: Kevin Pulo Assignee: Mark Benvenuto
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Duplicate
is duplicated by SERVER-29739 Cursor array access does not work rel... Closed
Related
is related to SERVER-30502 --disableJavaScriptJIT does not disab... Closed
is related to SERVER-29739 Cursor array access does not work rel... Closed
is related to SERVER-30769 Mongo shell throws 'exception during ... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.4
Sprint: Platforms 2017-08-21
Participants:

 Description   

Calling toString() on a DBCollection object (eg. as returned by db.getCollection(...)) usually just returns the full ns as a string (via getFullName()).

However, after a while toString() unexpectedly returns "[object DBCollection]".

This string no doubt comes from the default SpiderMonkey/JS Object toString() function. "A while" means a few thousand calls — to be exact, it looks like 2 less than a multiple of 1100, depending on the exact conditions.

dbcoll_tostring_1.js

var c = db.getCollection("foo");
for (i = 0; i < 1000000; i++) {
    assert.eq(c.toString(), "test.foo", i);
}

$ mongo dbcoll_tostring_1.js
MongoDB shell version v3.4.6
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.4.6
assert: ["[object DBCollection]"] != ["test.foo"] are not equal : 2197
doassert@src/mongo/shell/assert.js:18:14
assert.eq@src/mongo/shell/assert.js:54:5
@dbcoll_tostring_1.js:3:1
 
2017-07-27T13:35:30.637+1000 E QUERY    [thread1] Error: ["[object DBCollection]"] != ["test.foo"] are not equal : 2197 :
doassert@src/mongo/shell/assert.js:18:14
assert.eq@src/mongo/shell/assert.js:54:5
@dbcoll_tostring_1.js:3:1
failed to load: dbcoll_tostring_1.js

As if that wasn't bizarre enough, it then continues working as normal for a while, before permanently failing. The pattern seems to involve multiples of 1100 calls.

dbcoll_tostring_2.js

var c = db.getCollection("foo");
var prev = -1;
for (i = 0; i < 1000000; i++) {
    if (c.toString() !== "test.foo") {
        print(i - prev);
        prev = i;
    }
}

$ mongo dbcoll_tostring_2.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 2198
      1 1100
 996702 1

The behaviour is deterministic.

Disabling JIT doesn't help.

It's something peculiar about toString() specifically. Calling getFullName() directly works as expected:

dbcoll_tostring_3.js

var c = db.getCollection("foo");
for (i = 0; i < 1000000; i++) {
    assert.eq(c.getFullName(), "test.foo", i);
}

$ mongo dbcoll_tostring_3.js
MongoDB shell version v3.4.6
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.4.6

Versions:

  • 3.4 and later are affected, but 3.2 and earlier are unaffected.
  • 3.3.5 is affected, but not 3.3.4. So highly likely related to the SpiderMonkey 38 -> 45 upgrade (SERVER-23358).

$ /m/3.3.4/bin/mongo dbcoll_tostring_2.js | uniq -c
      1 MongoDB shell version: 3.3.4
      1 connecting to: test
$ /m/3.3.5/bin/mongo dbcoll_tostring_2.js | uniq -c
      1 MongoDB shell version: 3.3.5
      1 connecting to: test
      1 2198
      1 1100
 996702 1

It's independent of which JS object is having toString() called (almost — note that this is 3298, not 2198):

dbcoll_tostring_4.js

var prev = -1;
for (i = 0; i < 1000000; i++) {
    if (db.getCollection("a"+i).toString() !== "test.a"+i) {
        print(i - prev);
        prev = i;
    }
}

$ mongo dbcoll_tostring_4.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 3298
      1 1100
 995602 1

Looks like it's sensitive to the calling scope, or the call site, or at the very least related to them somehow. You can induce an extra 1100 (or 1200) successful calls by calling from a different site, eg. from another for loop, or by nesting inside a function call which is called with a unique signature (in terms of parameter types):

dbcoll_tostring_5.js

var prev = -1;
for (i = 0; i < 1000000; i++) {
    if (db.getCollection("a"+i).toString() !== "test.a"+i) {
        print(i - prev);
        prev = i;
    }
}
var prev = -1;
for (i = 0; i < 1000000; i++) {
    if (db.getCollection("a"+i).toString() !== "test.a"+i) {
        print(i - prev);
        prev = i;
    }
}

$ mongo dbcoll_tostring_5.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 3298
      1 1100
 995602 1
      1 1101
      1 1100
 997799 1

dbcoll_tostring_6.js

print(db.getCollection('a0').toString());
print(db.getCollection('a1').toString());
print(db.getCollection('a2').toString());
print(db.getCollection('a3').toString());
...
print(db.getCollection('a999997').toString());
print(db.getCollection('a999998').toString());
print(db.getCollection('a999999').toString());

$ awk 'BEGIN { for (i = 0; i < 1000000; i++) printf("print(db.getCollection('\''a%d'\'').toString());\n", i) }' > dbcoll_tostring_6.js
$ mongo dbcoll_tostring_6.js | grep -v '^test\.a[0-9]\+$'
MongoDB shell version v3.4.6
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.4.6

dbcoll_tostring_7.js

for (j = 0; j < 2; j++) {
    var prev = -1;
    for (i = 0; i < 1000000; i++) {
        if (db.getCollection("a"+i).toString() !== "test.a"+i) {
            print(i - prev);
            prev = i;
        }
    }
}

$ mongo dbcoll_tostring_7.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 3597
      1 1200
 995203 1
      1 1200
 998800 1

dbcoll_tostring_8.js

var fun = function(a,b) {
    var prev = -1;
    for (i = 0; i < 1000000; i++) {
        if (db.getCollection("a"+i).toString() !== "test.a"+i) {
            print(i - prev);
            prev = i;
        }
    }
};
print("RUNNING: fun()");   fun();
print("RUNNING: fun()");   fun();

$ mongo dbcoll_tostring_8.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 RUNNING: fun()
      1 3298
      1 1100
 995602 1
      1 RUNNING: fun()
1000000 1

dbcoll_tostring_9.js

var fun = function(a,b) {
    print("RUNNING: fun(" + tojsononeline(a) + "," + tojsononeline(b) + ")");
    var prev = -1;
    for (i = 0; i < 1000000; i++) {
        if (db.getCollection("a"+i).toString() !== "test.a"+i) {
            print(i - prev);
            prev = i;
        }
    }
};
fun();
fun();

$ mongo dbcoll_tostring_9.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 RUNNING: fun(undefined,undefined)
      1 3298
      1 1100
 995602 1
      1 RUNNING: fun(undefined,undefined)
      1 1100
 998900 1

dbcoll_tostring_10.js

var fun = function(a,b) {
    var prev = -1;
    for (i = 0; i < 1000000; i++) {
        if (db.getCollection("a"+i).toString() !== "test.a"+i) {
            print(i - prev);
            prev = i;
        }
    }
};
print("RUNNING: fun()");                      fun();
print("RUNNING: fun()");                      fun();
print("RUNNING: fun(1,2)");                   fun(1,2);
print("RUNNING: fun(\"foo\",\"bar\")");       fun("foo","bar");
print("RUNNING: fun(3,4)");                   fun(3,4);
print("RUNNING: fun(\"foo\",2)");             fun("foo",2);
print("RUNNING: fun(\"fred\",\"barney\")");   fun("fred","barney");
print("RUNNING: fun(2,\"foo\")");             fun(2,"foo");
print("RUNNING: fun(2,{})");                  fun(2,{});
print("RUNNING: fun({},2)");                  fun({},2);

$ mongo dbcoll_tostring_10.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 RUNNING: fun()
      1 3298
      1 1100
 995602 1
      1 RUNNING: fun()
1000000 1
      1 RUNNING: fun(1,2)
      1 1099
 998901 1
      1 RUNNING: fun("foo","bar")
      1 1099
 998901 1
      1 RUNNING: fun(3,4)
1000000 1
      1 RUNNING: fun("foo",2)
1000000 1
      1 RUNNING: fun("fred","barney")
1000000 1
      1 RUNNING: fun(2,"foo")
1000000 1
      1 RUNNING: fun(2,{})
      1 1099
 998901 1
      1 RUNNING: fun({},2)
      1 1099
 998901 1

It seems to be peculiar to DBCollection, DB, and DBQuery. These classes have a JS toString() function. However, Mongo and Timestamp also have such a JS toString(), but aren't affected.

dbcoll_tostring_11.js

print(DB)
print(DB.prototype.toString)
print(db.toString)
var prev = -1;
for (i = 0; i < 1000000; i++) {
    var s = db.toString();
    if (s !== "test") {
        print(i - prev, s);
        prev = i;
    }
}
 
print();
 
print(DBQuery)
print(DBQuery.prototype.toString)
print(db.foo.find().toString)
var prev = -1;
for (i = 0; i < 1000000; i++) {
    var s = db.foo.find().toString();
    if (s !== "DBQuery: test.foo -> { }") {
        print(i - prev, s);
        prev = i;
    }
}
 
print();
 
print(Mongo)
print(Mongo.prototype.toString)
print(db.getMongo().toString)
var prev = -1;
for (i = 0; i < 1000000; i++) {
    var s = db.getMongo().toString();
    if (s !== "connection to 127.0.0.1:27017") {
        print(i - prev, s);
        prev = i;
    }
}
 
print();
 
print(Timestamp)
print(Timestamp.prototype.toString)
print(Timestamp(1, 2).toString)
var prev = -1;
for (i = 0; i < 1000000; i++) {
    var s = Timestamp(1, 2).toString();
    if (s !== "Timestamp(1, 2)") {
        print(i - prev, s);
        prev = i;
    }
}
 
print();
 
print(Timestamp)
print(Timestamp.prototype.toString)
print((new Timestamp(1, 2)).toString)
var prev = -1;
for (i = 0; i < 1000000; i++) {
    var s = (new Timestamp(1, 2)).toString();
    if (s !== "Timestamp(1, 2)") {
        print(i - prev, s);
        prev = i;
    }
}

$ mongo dbcoll_tostring_11.js | uniq -c
      1 MongoDB shell version v3.4.6
      1 connecting to: mongodb://127.0.0.1:27017
      1 MongoDB server version: 3.4.6
      1 function DB() {
      1     [native code]
      1 }
      1 function () {
      1         return this._name;
      1     }
      1 function () {
      1         return this._name;
      1     }
      1 2198 [object DB]
      1 1100 [object DB]
 996702 1 [object DB]
      1
      1 function DBQuery() {
      1     [native code]
      1 }
      1 function () {
      1     return "DBQuery: " + this._ns + " -> " + tojson(this._query);
      1 }
      1 function () {
      1     return "DBQuery: " + this._ns + " -> " + tojson(this._query);
      1 }
      1 2201 [object DBQuery]
      1 1100 [object DBQuery]
 996699 1 [object DBQuery]
      1
      1 function Mongo() {
      1     [native code]
      1 }
      1 function () {
      1     return "connection to " + this.host;
      1 }
      1 function () {
      1     return "connection to " + this.host;
      1 }
      1
      1 function Timestamp() {
      1     [native code]
      1 }
      1 function () {
      1         return "Timestamp(" + this.t + ", " + this.i + ")";
      1     }
      1 function () {
      1         return "Timestamp(" + this.t + ", " + this.i + ")";
      1     }
      1
      1 function Timestamp() {
      1     [native code]
      1 }
      1 function () {
      1         return "Timestamp(" + this.t + ", " + this.i + ")";
      1     }
      1 function () {
      1         return "Timestamp(" + this.t + ", " + this.i + ")";
      1     }

I ran into this while working on an unrelated jstest:

...
collNum++;
var collName = "coll" + collNum;
var coll = db.getCollection(collName);
...
assert.commandWorked(coll.createIndex({ i: 1 }));
assert.commandWorked(s.s0.adminCommand({shardcollection: coll.toString(), key: {i: 1}}));
...

...
[js_test:SERVER-20392] 2017-07-26T04:19:24.108+0000 s20014| 2017-07-26T04:19:24.107+0000 D COMMAND  [conn1] AllShardsCollectionCommand: test.coll4 cmd:{ createIndexes: "coll4", indexes: [ { key: { i: 1.0 }, name: "i_1" } ], $db: "test" }
[js_test:SERVER-20392] 2017-07-26T04:19:24.116+0000 d20010| 2017-07-26T04:19:24.116+0000 I INDEX    [conn8] build index on: test.coll4 properties: { v: 2, key: { i: 1.0 }, name: "i_1", ns: "test.coll4" }
[js_test:SERVER-20392] 2017-07-26T04:19:24.116+0000 d20010| 2017-07-26T04:19:24.116+0000 I INDEX    [conn8]      building index using bulk method; build may temporarily use up to 500 megabytes of RAM
[js_test:SERVER-20392] 2017-07-26T04:19:24.137+0000 d20010| 2017-07-26T04:19:24.137+0000 I INDEX    [conn8] build index done.  scanned 8192 total records. 0 secs
[js_test:SERVER-20392] 2017-07-26T04:19:24.138+0000 s20014| 2017-07-26T04:19:24.138+0000 D -        [conn1] User Assertion: 73:Invalid namespace specified '[object DBCollection]' src/mongo/db/commands.cpp 99
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000 assert: command failed: {
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000     "ok" : 0,
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000     "errmsg" : "Invalid namespace specified '[object DBCollection]'",
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000     "code" : 73,
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000     "codeName" : "InvalidNamespace"
[js_test:SERVER-20392] 2017-07-26T04:19:24.139+0000 } : undefined
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 _getErrorWithCode@src/mongo/shell/utils.js:25:13
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 doassert@src/mongo/shell/assert.js:16:14
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 assert.commandWorked@src/mongo/shell/assert.js:403:5
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 runCase@jstests/sharding/SERVER-20392.js:64:1
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 @jstests/sharding/SERVER-20392.js:163:1
[js_test:SERVER-20392] 2017-07-26T04:19:24.140+0000 @jstests/sharding/SERVER-20392.js:4:2

Directly calling getFullName() instead of toString() is an adequate workaround in this case, but in general there may be a lot of toString() call sites already in existence.

I'm also concerned that this may be merely a symptom of some deeper problem.



 Comments   
Comment by Githook User [ 02/Oct/17 ]

Author:

{'email': 'mark.benvenuto@mongodb.com', 'name': 'Mark Benvenuto', 'username': 'markbenvenuto'}

Message: SERVER-30362 MozJS - implement resolve instead of getProperty for native types

(cherry picked from commit 4cb5071ecb94d0789392b1748b49388099a8a2ec)
Branch: v3.4
https://github.com/mongodb/mongo/commit/586dc3aab58cd75b7ab00b3431a80ea102184652

Comment by Githook User [ 17/Aug/17 ]

Author:

{'username': 'markbenvenuto', 'email': 'mark.benvenuto@mongodb.com', 'name': 'Mark Benvenuto'}

Message: SERVER-30362 MozJS - implement resolve instead of getProperty for native types
Branch: master
https://github.com/mongodb/mongo/commit/4cb5071ecb94d0789392b1748b49388099a8a2ec

Comment by Mark Benvenuto [ 09/Aug/17 ]

The issue seems to affect native types with getProperty accessors. This means DBCollection, DBQuery, and DB. If I remove getProperty from one of these types, the issue goes away. If I overwrite one of the objects like DBCollection in the script, the issue goes away.

What happens is that during Ion JITing, a call to js::jit::IonBuilder::jsop_getprop("toString") makes a call to js::jit::IonBuilder::getPropTryConstant and getPropTryConstant returns true. This matters for toString since it is a well-known property of a type which is why getFullName in DBCollection has no issues.

If we recompile with --spider-monkey-dbg=on CPPDEFINES=JS_JITSPEW, and set the environment variable IONFLAGS="bl-scripts,bl-osr", then we get more insight into what is happening.

Using the following code and mongo shell with --nodb.

const c = new DB(null, "test");
for (let i = 0; i < 1000000; i++) {
    if(c.toString() != "test") { 
        throw i;
    }
}

we get the following output:

[BaselineScripts] Baseline compiling script (shell):1 (000001A2C4D0C3D0)
[BaselineScripts] Created BaselineScript 000001A2C4204EB0 (raw 0000013FB7E4B360) for (shell):1
[BaselineScripts] Baseline compiling script src/mongo/shell/db.js:978 (000001A2C4CB5A50)
[BaselineScripts] Created BaselineScript 000001A2CA3B5C20 (raw 0000013FB7E4C270) for src/mongo/shell/db.js:978
[BaselineOSR] WarmUpCounter for src/mongo/shell/db.js:978 reached 1000 at pc 000001A2CC6A78DC, trying to switch to Ion!
[BaselineOSR]   Compile function from top for later entry!
[BaselineOSR]   Compiled with Ion!
[BaselineOSR] WarmUpCounter for (shell):1 reached 1100 at pc 000001A2CCA8909C, trying to switch to Ion!
[BaselineOSR]   Compile at loop entry!
[BaselineOSR]   Skipped compile with Ion!
[BaselineOSR] WarmUpCounter for (shell):1 reached 1100 at pc 000001A2CCA8909C, trying to switch to Ion!
[BaselineOSR]   Compile at loop entry!
[BaselineOSR]   Compiled with Ion!
[BaselineOSR]   OSR possible!
[BaselineOSR] Got jitcode.  Preparing for OSR into ion.
[BaselineOSR] Allocated IonOsrTempData at 000001A2CCA61820
[BaselineOSR] Jitcode is 0000013FB7E4E65E
2017-08-09T11:07:12.090-0400 E QUERY    [thread1] uncaught exception: 2197

This tells us that the second compilation by the Ion JIT of the loop is the problem.

Simpler Repros:

const c = new DBCollection(null, null, "foo", "test.foo");
for (i = 0; i < 1000000; i++) {
    if(c.toString() != "test.foo") { 
        throw i;
    }
}
 
const c = new DB(null, "test");
for (let i = 0; i < 1000000; i++) {
    if(c.toString() != "test") { 
        throw i;
    }
}
 
const c = DBQuery('a', 'b', 'c', 'd')
for (let i = 0; i < 1000000; i++) {
    if(c.toString() != "DBQuery: d -> null") { 
        throw i;    
    }
}

Comment by Mark Benvenuto [ 03/Aug/17 ]

I am still working on getting to the bottom of the issue, but I believe it is an issue when the baseline compiler triggers the Ion Jit, and this causes a miscompilation of the Javascript. It does not occur if the Ion JIT is disabled or if I force the Ion JIT on 100% of the time (by calling "JS_SetGlobalJitCompilerOption(_runtime.get(), JSJITCOMPILER_ION_WARMUP_TRIGGER, 0);").

The reason why there are magic numbers of loops needed like 2097 before the bug shows up is because of the Ion JIT warm up period. The Ion JIT does not kick in until a certain warm up threshold has been met. This is proportional to the size of the javascript being evaluated.

Note, that currently the --disableJavaScriptJIT flag does not work in the mongo shell as it never disables the JIT. See SERVER-30502.

This issue does not affect 3.2.x (i.e. MozJS 38), but does affect 3.4.0+ and later. It is not a regression from any intermediate MozJS 45 release incorporated into later 3.4.x releases. It is not fixed in MozJS 45.9.0 which has not been incorporated yet.

I do not know if this affects MozJS 52 ESR. Evaluating this will take several days of effort.

Generated at Thu Feb 08 04:23:33 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.