Loading...

XML

Word

Printable

JSON

Type: Bug
Resolution: Fixed
Priority: Major - P3
Fix Version/s: 3.4.10, 3.5.12
Affects Version/s: 3.4.6, 3.5.10
Component/s: JavaScript
Labels:
None

Backwards Compatibility:
Fully Compatible
Operating System:
ALL
Backport Requested:

v3.4
Sprint:
Platforms 2017-08-21

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.

is duplicated by

SERVER-29739 Cursor array access does not work reliably

Closed

is related to

SERVER-30502 --disableJavaScriptJIT does not disable JIT

Closed

SERVER-29739 Cursor array access does not work reliably

Closed

SERVER-30769 Mongo shell throws 'exception during autocomplete'

Closed

Assignee:: Mark Benvenuto

Reporter:: Kevin Pulo

Participants:: Githook User, Kevin Pulo, Mark Benvenuto

Votes:: 0 Vote for this issue

Watchers:: 11 Start watching this issue

Created:: Jul 27 2017 05:41:12 AM UTC

Updated:: Oct 30 2023 11:14:51 PM UTC

Resolved:: Aug 17 2017 06:42:01 PM UTC

Details

Description

Attachments

Issue Links

Activity

People

Dates