[1.4.0.1] Error: key $lt must not start with '$'

[WayneUong]

[xx.xx.xx.xx] Exception in setInterval callback: Error: key $lt must not start with '$'
[xx.xx.xx.xx]     at Object.Future.wait (/bundle/bundle/programs/server/node_modules/fibers/future.js:449:15)
[xx.xx.xx.xx]     at MongoConnection.<anonymous> (packages/meteor/helpers.js:119:1)
[xx.xx.xx.xx]     at MongoConnection.(anonymous function) (packages/mongo/mongo_driver.js:771:49)
[xx.xx.xx.xx]     at [object Object].remove (packages/mongo/collection.js:624:29)
[xx.xx.xx.xx]     at _cleanStaleResults (packages/oauth/pending_credentials.js:30:1)
[xx.xx.xx.xx]     at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
[xx.xx.xx.xx]     at packages/meteor/timers.js:6:1
[xx.xx.xx.xx]     at runWithEnvironment (packages/meteor/dynamics_nodejs.js:110:1)
[xx.xx.xx.xx]     - - - - -
[xx.xx.xx.xx]     at Error (native)
[xx.xx.xx.xx]     at serializeInto (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:706:19)
[xx.xx.xx.xx]     at serializeObject (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
[xx.xx.xx.xx]     at serializeInto (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:731:17)
[xx.xx.xx.xx]     at serializeObject (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
[xx.xx.xx.xx]     at serializeInto (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:731:17)
[xx.xx.xx.xx]     at serializeObject (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
[xx.xx.xx.xx]     at serializeInto (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:577:17)
[xx.xx.xx.xx]     at serializeObject (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
[xx.xx.xx.xx]     at serializeInto (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:731:17)
    at [object Object].serialize (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/bson.js:48:27)
    at [object Object].Query.toBin (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/commands.js:143:25)
    at executeWrite (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/wireprotocol/3_2_support.js:69:20)
    at [object Object].WireProtocol.insert (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/wireprotocol/3_2_support.js:80:3)
    at [object Object].Server.insert (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/server.js:502:35)
    at executeWriteOperation (/bundle/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/replset.js:896:37)

[laosb]

Can you provide a full reproduce with code, not only the error message? It's hard to guess what did you write through a error message.

[brianlukoff]

I'm seeing something similar: it's coming from a query of the form CollectionName.update({ ... }, { $addToSet: { ... } }, { upsert: true }), but it's only happening intermittently -- have not yet been able to reproduce.

[glasser]

The line that triggers this appears to be

  OAuth._pendingCredentials.remove({ createdAt: { $lt: timeCutoff } });

in pendingCredentials.js.

It seems that somehow this remove call is turning into an insert on the wire. Very strange! (The error that results is insert-specific.) Unfortunately some useful middle part of the stack trace seems to have disappeared. @benjamn any thoughts?

[glasser]

In @brianlukoff's case it is an update turning into an insert. @brianlukoff reported this to Galaxy support and I saw in that report that there were other things in the stack trace like matb33:collection-hooks and aldeed:collection2-core, and upserts are strangely similar to inserts. But in this case it's just a remove and those packages are not in the stack trace.

@WayneUong can you share with us the contents of your .meteor/versions file? Maybe some package is modifying how remove works somehow?

[WayneUong]

This is my current .meteor/versions, it is probably pretty similar to one at the time of the error:

255kb:meteor-status@1.5.0
accounts-base@1.2.9
accounts-google@1.0.10
accounts-oauth@1.1.13
accounts-password@1.2.12
aldeed:template-extension@4.0.0
allow-deny@1.0.5
autoupdate@1.2.11
babel-compiler@6.9.0
babel-runtime@0.1.10
base64@1.0.9
binary-heap@1.0.9
blaze@2.1.8
blaze-html-templates@1.0.4
blaze-tools@1.0.9
boilerplate-generator@1.0.9
caching-compiler@1.0.6
caching-html-compiler@1.0.6
callback-hook@1.0.9
check@1.2.3
coffeescript@1.1.4
dburles:collection-helpers@1.0.4
ddp@1.2.5
ddp-client@1.2.9
ddp-common@1.2.6
ddp-rate-limiter@1.0.5
ddp-server@1.2.10
deps@1.0.12
diff-sequence@1.0.6
easy:search@2.0.9
easysearch:autosuggest@2.0.10
easysearch:components@2.0.9
easysearch:core@2.0.9
ecmascript@0.5.7
ecmascript-runtime@0.3.12
ejson@1.0.12
email@1.1.16
erasaur:meteor-lodash@4.0.0
es5-shim@4.6.13
fastclick@1.0.12
force-ssl@1.0.12
fortawesome:fontawesome@4.4.0_1
fourseven:scss@3.8.0_1
froala:editor@2.3.4
geojson-utils@1.0.9
google@1.1.13
hot-code-push@1.0.4
html-tools@1.0.10
htmljs@1.0.10
http@1.2.8
id-map@1.0.8
iron:controller@1.0.12
iron:core@1.0.11
iron:dynamic-template@1.0.12
iron:layout@1.0.12
iron:location@1.0.11
iron:middleware-stack@1.1.0
iron:router@1.0.13
iron:url@1.0.11
jeremy:selectize@0.12.1_5
jquery@1.11.9
juliancwirko:s-alert@3.1.4
juliancwirko:s-alert-stackslide@3.1.3
launch-screen@1.0.12
less@2.6.5
livedata@1.0.18
localstorage@1.0.11
logging@1.1.14
lookback:tooltips@0.5.2
maazalik:highcharts@0.4.0
matb33:bootstrap-base@10.0.0
matb33:bootstrap-popovers@10.0.0
matb33:bootstrap-tooltip@10.0.0
matb33:bootstrap-transition-js@10.0.0
matb33:collection-hooks@0.8.3
matdutour:popup-confirm@0.1.26
matteodem:easy-search@2.0.0
meteor@1.2.16
meteor-base@1.0.4
meteorhacks:aggregate@1.3.0
meteorhacks:collection-utils@1.2.0
meteorhacks:inject-initial@1.0.4
meteorhacks:kadira@2.30.0
meteorhacks:meteorx@1.4.1
meteorhacks:ssr@2.2.0
meteorhacks:subs-manager@1.6.4
meteorhacks:zones@1.6.0
mikowals:batch-insert@1.1.13
minifier-css@1.2.13
minifier-js@1.2.13
minimongo@1.0.17
mizzao:timesync@0.4.0
mizzao:user-status@0.6.6
mobile-experience@1.0.4
mobile-status-bar@1.0.12
modules@0.7.5
modules-runtime@0.7.5
momentjs:moment@2.14.4
mongo@1.1.10
mongo-id@1.0.5
mongo-livedata@1.0.12
mrgalaxy:stripe@2.2.2
mystor:device-detection@0.2.0
npm-bcrypt@0.8.7
npm-mongo@1.5.45
oauth@1.1.11
oauth2@1.1.10
observe-sequence@1.0.12
ordered-dict@1.0.8
peerlibrary:assert@0.2.5
peerlibrary:base-component@0.16.0
peerlibrary:blaze-components@0.18.0
peerlibrary:computed-field@0.3.1
peerlibrary:data-lookup@0.1.0
peerlibrary:reactive-field@0.1.0
peppelg:bootstrap-3-modal@1.0.4
percolate:migrations@0.9.8
percolate:synced-cron@1.3.2
promise@0.8.3
rajit:bootstrap3-datepicker@1.5.1
random@1.0.10
rate-limit@1.0.5
reactive-dict@1.1.8
reactive-var@1.0.10
reload@1.1.10
retry@1.0.8
reywood:publish-composite@1.4.2
risul:bootstrap-colorpicker@2.3.0
rochal:slimscroll@1.3.3
routepolicy@1.0.11
service-configuration@1.0.10
session@1.1.6
sha@1.0.8
simple:reactive-method@1.0.2
spacebars@1.0.12
spacebars-compiler@1.0.12
srp@1.0.9
standard-minifier-css@1.1.8
standard-minifier-js@1.1.8
stevezhu:lodash@4.0.0
summernote:standalone@0.8.1
templating@1.1.14
templating-tools@1.0.4
themeteorites:blaze-magic-events@0.0.5
tmeasday:publish-counts@0.7.3
todda00:friendly-slugs@0.6.0
tracker@1.1.0
twbs:bootstrap@3.3.6
ui@1.0.11
underscore@1.0.9
url@1.0.10
webapp@1.3.10
webapp-hashing@1.0.9
wizonesolutions:canonical@0.0.5
zimme:active-route@2.3.2
zimme:collection-behaviours@1.1.3
zimme:collection-softremovable@1.0.5

[glasser]

There seem to be a large number of packages here that tweak how collections work (collection hooks, etc). Is this issue easily reproducible for you? Can you pare down your app bit by bit (removing packages, etc) to see which packages are required to see this issue?

[WayneUong]

I have neither encountered nor been able to reproduce this error again. We have a very large app and narrowing down which module that caused this isn’t possible. I just saw it once in the server log and posted it here to see if anyone saw this too.

On Aug 17, 2016, at 3:00 PM, David Glasser notifications@github.com wrote:

There seem to be a large number of packages here that tweak how collections work (collection hooks, etc). Is this issue easily reproducible for you? Can you pare down your app bit by bit (removing packages, etc) to see which packages are required to see this issue?

[brianlukoff]

We are also not able to reproduce in dev, although in our case it is happening pretty consistently (and randomly) in production).

[brianlukoff]

This error persists even after using .direct to bypass collection-hooks:

Error: key $addToSet must not start with '$'
    at Object.Future.wait (/app/bundle/programs/server/node_modules/fibers/future.js:449:15)
    at MongoConnection.<anonymous> (packages/meteor/helpers.js:119:1)
    at MongoConnection.(anonymous function) (packages/mongo/mongo_driver.js:771:49)
    at Object.collection.(anonymous function) [as update] (packages/matb33_collection-hooks/collection-hooks.js:107:1)
    at [object Object].update (packages/mongo/collection.js:589:29)
    at packages/matb33_collection-hooks/collection-hooks.js:101:1
    at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
    at Object.directOp (packages/matb33_collection-hooks/collection-hooks.js:21:1)
    at Object.self.direct.(anonymous function) [as update] (packages/matb33_collection-hooks/collection-hooks.js:100:1)
    at Subscription.<anonymous> (server/activity.js:54:26)
    at Subscription.<anonymous> (packages/peerlibrary_related/packages/peerlibrary_related.js:157:1)
    at packages/matb33_collection-hooks/collection-hooks.js:281:1
    at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
    at Subscription._handler (packages/matb33_collection-hooks/collection-hooks.js:280:1)
    at packages/check/match.js:107:1
    at [object Object]._.extend.withValue (packages/meteor/dynamics_nodejs.js:56:1)
    - - - - -
    at Error (native)
    at serializeInto (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:706:19)
    at serializeObject (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
    at serializeInto (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:731:17)
    at serializeObject (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
    at serializeInto (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:577:17)
    at serializeObject (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:291:18)
    at serializeInto (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/parser/serializer.js:731:17)
    at [object Object].serialize (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/bson/lib/bson/bson.js:48:27)
    at [object Object].Query.toBin (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/connection/commands.js:143:25)
    at executeWrite (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/wireprotocol/3_2_support.js:69:20)
    at [object Object].WireProtocol.insert (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/wireprotocol/3_2_support.js:80:3)
    at [object Object].Server.insert (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/server.js:502:35)
    at executeWriteOperation (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/mongos.js:668:13)
    at [object Object].Mongos.insert (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb-core/lib/topologies/mongos.js:697:3)
    at [object Object].Mongos.insert (/app/bundle/programs/server/npm/node_modules/meteor/npm-mongo/node_modules/mongodb/lib/mongos.js:316:17)

[tmeasday]

@WayneUong - can I ask which database provider you are using?

[WayneUong]

We’re using ScaleGrid.io http://scalegrid.io/

On Aug 22, 2016, at 5:10 PM, Tom Coleman notifications@github.com wrote:

@WayneUong https://github.com/WayneUong - can I ask which database provider you are using?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub #7594 (comment), or mute the thread https://github.com/notifications/unsubscribe-auth/AIC8BgYSa3Mol1QIp5iy53dhBS9JWYc-ks5qijpogaJpZM4JeGzW.

[tmeasday]

Managed to hunt it down: mongodb-js/mongodb-core#121. The issue only happens when you have connection issues.

I'll do a release of npm-mongo which bumps the dependency to the latest that includes this fix. Stand by.

[brianlukoff]

Fantastic - thanks @tmeasday ! Is it possible for us to utilize the new version of npm-mongo in our app now or will we have to wait until 1.4.1.1 (or whatever the next version is) is out?