[$100] Help debug "Uncaught Error: Key $setOnInsert must not start with '$'"

nadeemjq · August 24, 2017, 11:49am

Hi,

I’m getting this error in the console:

Uncaught Error: Key $setOnInsert must not start with '$'

It blocks my route from rendering completely.

I have no idea why this is happening. I’m not setting anything on insert.

Any debugging suggestions (“where to look” etc) that helps to solve this will be rewarded with $100 over PayPal.

The console:

13:37:08.024 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61 Uncaught Error: Key $setOnInsert must not start with '$'
    at b (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61:13646)
    at h (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61:18904)
    at Object.<anonymous> (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61:18814)
    at JSON.stringify (<anonymous>)
    at l (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61:18781)
    at r.t [as insert] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61:21186)
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3018)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
b @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61
h @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61
(anonymous) @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61
l @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61
t @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:61
update @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67
o.(anonymous function) @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
(anonymous) @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
A.each.A.forEach @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7
(anonymous) @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
A.each.A.forEach @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7
_performWrites @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
_flushBufferedWrites @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
_livedata_data @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
e.connection._livedata_data @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:265
r @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
(anonymous) @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
A.each.A.forEach @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7
t.socket.onmessage @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
r.dispatchEvent @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
C._dispatchMessage @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
C._didMessage @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
r.ws.onmessage @ b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53
13:37:22.175 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481
13:37:58.220 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481
13:38:03.615 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481
13:38:18.913 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481
13:38:32.388 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481
13:38:33.319 b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1 Exception in flushing DDP buffered writes: Error: Expected to find a document to change
    at Object.update (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:67:3285)
    at Object.o.(anonymous function) [as update] (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:42812)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:51008
    at Array.forEach (<anonymous>)
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:854)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50987
    at Function.A.each.A.forEach (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:7:998)
    at b._performWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50943)
    at b._flushBufferedWrites (https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:53:50746)
    at https://app.sembly.no/b12ba4edc843fd7d8052aef16448de1e6fd465b5.js?meteor_js_resource=true:1:7481

herteby · August 24, 2017, 1:29pm

Okay, here are my five cents

It’s a Mongo error.

$setOnInsert is a Mongo operator.

Mongo does not allow keys to start with $ ($ is reserved for operators). So it seems that Mongo is not recognizing the operator. One reason could be that you’re using $setOnInsert on the client, and MiniMongo only supports a limited number of operators.

Here are all the occurences of $setOnInsert in the Meteor code

radekmie · August 24, 2017, 6:07pm

I saw it already. If you are using SimpleSchema (even indirectly for example with collection2 or other packages), check for some autoValues. Also, this is a client error - is there any server message?

nadeemjq · August 26, 2017, 8:31pm

Thanks, herteby.

While I don’t disagree with your statements, I don’t understand how to proceed from the information you have shared.

nadeemjq · August 26, 2017, 8:33pm

Thank you, radekmie.

I am using SimpleSchema.

I have a few fields that have autoValues.

However, I don’t understand the relevance. Can you explain?

Update: I removed the autoValue but it didn’t help

radekmie · August 27, 2017, 11:27am

All autoValues are resolved on insert/update and done with $set or other operators, including $setOnInsert. If it’s still happening after removing all of them, only debugging can help. This one really depends on your code and used packages. If it blocks routing, try to remove everything that is happening on this route. Maybe it’s something connected reactively, not directly? You have to find out.

This stack trace won’t help you much, because it’s an error thrown in response of invalid update.

nadeemjq · August 27, 2017, 11:40am

Hello,

@radekmie, @herteby: Even though your suggestions haven’t yet helped solve the problem, I very much appreciate the fact that you chimed in. For this fact alone I’d like to buy you both a round of beer, so please send me your PayPal addresses. The original offer still stands, of course.

Some more debugging information:

There are no related errors on the server.
The issue is intermittent. It almost always occurs on the first initial load of the route, but after reload or subsequent login/logout of the user it might go away.
The issue seems to plague only particular route-param pair, for example /shedules/idOfScheduleA will trigger the error, but /schedules/idOfScheduleB will not. I’m using FlowRouter from VeliovGroup.

Moreover, I put a breakpoint on common.js:1053, which is the end of the stack trace. I then climbed up the stack trace to figure out where this $setOnInsert is coming from.

It appears that something is manually adding $setOnInsert_ to my document as a top level field, like this:

writes: Object
  schedules: Array(1)
  0:
  collection: "schedules"
  fields:
    $setOnInsert: undefined
    end_time: "2017-08-25T09:45:00+02:00"
    event_id: "irHW7HMwEqXBxDKi8"
    ext_id: 317927922041290100
    start_time: "2017-08-25T08:15:00+02:00"
    takesAttendance: true
    title: "Studietid"
    user_ids: (2) ["PmPZcAJkq6HgGpSmH", "927xpom7x7a59fcMY"]
  __proto__: Object
  id: "BmpJiZDdSp4uSuyyp"
  msg: "added"
  __proto__: Object
  length: 1
  __proto__: Array(0)
__proto__: Object

This is the value of the writes variable at livedata_connection.js:1318, that is inside _flushBufferedWrites function. Please note that $setOnInsert is not a field in my schema.

_flushBufferedWrites: function () {
    var self = this;
    if (self._bufferedWritesFlushHandle) {
      clearTimeout(self._bufferedWritesFlushHandle);
      self._bufferedWritesFlushHandle = null;
    }

    self._bufferedWritesFlushAt = null;
    // We need to clear the buffer before passing it to
    //  performWrites. As there's no guarantee that it
    //  will exit cleanly.
    var writes = self._bufferedWrites;
    self._bufferedWrites = {};
    self._performWrites(writes);
  },

I’m unable to find $setOnInsert anywhere longer up the chain.

Does anyone know what is happening.

radekmie · August 27, 2017, 12:03pm

It won’t be easy to track it - you’ll see an object reference in the debugger, so climbing up the stack may operate on the same reference without noticing. Could you post your route definition?

nadeemjq · August 27, 2017, 2:49pm

I’m note sure what you mean about “Object reference.”

My route definitions:


// Routes for logged in users
const loggedInRoutes = FlowRouter.group({
  name: 'loggedIn',
});
....
loggedInRoutes.route('/schedules/:scheduleId', {
  name: 'schedulesShow',
  action() {
    BlazeLayout.render('loggedInLayout', {
      content: 'schedulesShow',
    });
  },
});

radekmie · August 27, 2017, 3:16pm

Consider this code:

function f (x) { return g(x); }
function g (x) { x.a = 1; return h(x); }
function h (x) { throw x; }

h({});

In this case, going up the stack trace will constantly show {a: 1}, even if the a property comes from g.

In this case, check onCreated and onRendered of this (and relevant) templates.

nadeemjq · August 27, 2017, 4:29pm

@radekmie

Thank you for explaining so clearly.

I have meticulously been changing all possible factors (over 10 different packages/functions) that could be involved here, including autoValue. What seems to reliably fix the problem is downgrading to 1.5. I was on 1.5.2-rc.2 and then 1.5.1 (the recommended release).

I’m going to try to narrow it down to specific package. In any case, thank you so much for your help. Please send me your PayPal by PM and allow me to buy you a beer

nadeemjq · August 27, 2017, 4:45pm

Yep:

Upgraded to 1.5.2-rc2 and the problem is back immediately.

nadeemjq · August 27, 2017, 4:54pm

Downgraded to 1.5, and the problem was still there. But the downgrading still leaves a lot of rc2 packages in the versions file, specifically minimongo. Downgrading this to 1.2.1 solves the problem.

radekmie · August 27, 2017, 5:09pm

When updating, you’ve updated only core packages or all (including community) ones? Try to fiddle with it even more - maybe you’ve found a bug.

nadeemjq · August 28, 2017, 2:48pm

Hello @radekmie,

Here’s what I’ve done.

I emptied my .meteor/versions file, and ran meteor update --release 1.5. This ensures that only compatible packages are installed. I carefully checked for changes in community-packages version. For example, my rzymek:fullcalendar got updated as a result. I made sure each package upgrade did not cause trouble. This setup works flawlessly.
I ran meteor update --release 1.5.2-beta152.0. I then ran meteor reset. Tried with one user, no problem. Tried again with another account: Boom! Uncaught Error: Key $setOnInsert must not start with ‘$’.

Here is a git diff of the absolute minimum level of changes required to cause trouble

❰Nadeem❙~/Code/Meteor/Sembly(git✱≠master)❱✔≻ git diff --unified=0                                                                                                                                                                  16:40:49
diff --git a/.meteor/packages b/.meteor/packages
index f195752..4ddb690 100644
--- a/.meteor/packages
+++ b/.meteor/packages
@@ -38 +38 @@ mobile-experience@1.0.4
-mongo@1.1.19
+mongo@1.2.0-beta152.0
@@ -48 +48 @@ check@1.2.5
-ecmascript@0.8.1
+ecmascript@0.8.2
diff --git a/.meteor/release b/.meteor/release
index 1e7fc5b..6cae79a 100644
--- a/.meteor/release
+++ b/.meteor/release
@@ -1 +1 @@
-METEOR@1.5.1
+METEOR@1.5.2-beta152.0
diff --git a/.meteor/versions b/.meteor/versions
index 919ad0a..6adfcc7 100644
--- a/.meteor/versions
+++ b/.meteor/versions
@@ -15 +15 @@ autoupdate@1.3.12
-babel-compiler@6.19.4
+babel-compiler@6.20.0-beta152.0
@@ -23 +23 @@ blaze-tools@1.0.10
-boilerplate-generator@1.1.1
+boilerplate-generator@1.2.0-beta152.0
@@ -94 +94 @@ minifier-js@2.1.1
-minimongo@1.2.1
+minimongo@1.3.0-beta152.0
@@ -98 +98 @@ mobile-status-bar@1.0.14
-modules@0.9.4
+modules@0.10.0-beta152.0
@@ -101 +101 @@ momentjs:moment@2.18.1
-mongo@1.1.19
+mongo@1.2.0-beta152.0
@@ -115 +115 @@ percolate:synced-cron@1.3.2
-promise@0.8.9
+promise@0.9.0-beta152.0

Do you think I should file this as a bug?

radekmie · August 28, 2017, 2:58pm

You’ll probably need a reproduction to report it as a bug.

nadeemjq · August 28, 2017, 2:59pm

Cool. I’ve offered to add MDG people to my repo for access. Can’t make a public repo just yet.