collection-hooks causing operations to fail silently

[mizzao]

Hi Mathieu,

I filed a bug with Meteor after observing some really strange behavior in my app with collection operations failing randomly (see https://github.com/meteor/meteor/issues/1289) but then realized it was a collection-hooks problem.

If you want to see what is going on, open http://crowdmapper.meteor.com in different browsers, and try to add and delete some rows on the 'Events' tab.

Should I debug the code in master or just switch to aop and help you with that?

[matb33]

My first instinct is to recommend that you try removing the find/findOne code from collection-hooks, and try again. The hooks were very stable for a long period of time -- the recent changes could be at the root of it.

Edit: also remove the publish wrapper too. That will get the hooks back into a state that I used for months flawlessly

[mizzao]

I'll take a look, although none of the things I observed involved a find.

Are you not planning to include find hooks in aop? That would make me sad.

[matb33]

I am thinking it will be a separate smart package actually. Plan is to break out the functionality that allows us to add new validators (which is at the core of how the new hooks work -- just like allow/deny) into a separate smart package. THAT smart package would form the basis of the PR against core.

We could then write a find-hooks package, that depends on extensible-validators (or whatever it'll be called)

[matb33]

If there's any chance you can send me a small repro case (or even your whole codebase including steps to eventually reproduce -- i understand it's kinda random), that would help

[mizzao]

@matb33 actually the problem is very deterministic. I can reproduce it exactly in my code. I haven't had time today to debug yet, but if you want to help, I can put up a --debug deployment on meteor.com and/or show you elsewhere. If you want to talk about this in person, maybe we can follow up on e-mail, IM, or whatever method of communication is easiest for you.

Also, the smart-packages-inside-smart-packages approach probably won't work too well right now until the package management system is overhauled. See oortcloud/meteorite#175. In any case, I 100% need the find hooks and will gladly help with that where possible.

[matb33]

Oh I wouldn't put a smart package inside an other, just have one depend on the other.

[matb33]

If I'm to help debug, I would need the codebase to work from so I can try things out. You can just zip it up if you want, then I can have a look

[mizzao]

It's available here: https://github.com/mizzao/CrowdMapper

You'll need the following packages pulled in as well, and be running on the devel branch of meteor:

• https://github.com/HarvardEconCS/turkserver-meteor
• https://github.com/HarvardEconCS/meteor-iron-router
• https://github.com/mizzao/meteor-user-status
• https://github.com/mizzao/meteor-x-editable-bootstrap
• https://github.com/mizzao/meteor-sharejs
• https://github.com/mizzao/meteor-accounts-testing

I'm actually not even using the hooks in my app. The mere fact of loading them (replacing function prototypes) is causing things to break. It's possible that a change on devel caused this and that's why you haven't seen it yet. However, there were too many things changed in my app to go back to 0.6.4.1 and find out.

[mizzao]

Just recording this in a convenient place...this error seems to cause, at the very least, inserts and removes to fail. I am seeing these thrown on the server. Once this happens the client that did the insert seems to not receive proper insert and remove updates over DDP anymore.

I20130808-17:30:45.994(-4)? Error in Mongo write: MongoError: E11000 duplicate key error index: meteor.events.$_id_  dup key: { : "YQZdXzcaZoYbaZe5H" }
I20130808-17:30:45.995(-4)?     at Object.toError (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/utils.js:110:11)
I20130808-17:30:45.995(-4)?     at /home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/collection.js:345:24
I20130808-17:30:45.996(-4)?     at Server.Base._callHandler (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/connection/base.js:378:7)
I20130808-17:30:45.996(-4)?     at Server.connect.connectionPool.on.server._serverState (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/connection/server.js:468:18)
I20130808-17:30:45.996(-4)?     at MongoReply.parseBody (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/responses/mongo_reply.js:137:5)
I20130808-17:30:45.999(-4)?     at Server.connect.connectionPool.on.server._serverState (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/connection/server.js:426:20)
I20130808-17:30:46.000(-4)?     at EventEmitter.emit (events.js:96:17)
I20130808-17:30:46.000(-4)?     at _connect (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/connection/connection_pool.js:191:13)
I20130808-17:30:46.000(-4)?     at EventEmitter.emit (events.js:99:17)
I20130808-17:30:46.001(-4)?     at Socket.exports.Connection.createDataHandler (/home/mao/projects/meteor/packages/mongo-livedata/.build/npm/node_modules/mongodb/lib/mongodb/connection/connection.js:384:22)
I20130808-17:30:46.001(-4)?     at Socket.EventEmitter.emit (events.js:96:17)
I20130808-17:30:46.001(-4)?     at TCP.onread (net.js:397:14)

[mizzao]

Hi @matb33, I fully intend to figure out what's going on here...just got sidetracked by some other work lately. Will get back to it as soon as I can!

[lacco]

I have a similar problem with collection-hooks package: As soon as I add it to my projects, some actions (like insert and remove) doesn't work anymore properly. I used https://github.com/arunoda/meteor-ddp-analyzer to have a look at the messages that are passed to and from the server, but I have to admit that this doesn't help me to debug the error. Perhaps somebody else can help me?

Use case: Adding three categories ("A 10", "A 11", "A 12") through the client

Without collection-hooks (all categories are created):

--> 2153419 {"msg":"method","method":"/categories/insert","params":[{"name":"A 10","_id":"mNGXgcjT4RK9dc76E"}],"id":"1"}
<-- 7 {"msg":"result","id":"1"}
<-- 91 {"msg":"added","collection":"categories","id":"mNGXgcjT4RK9dc76E","fields":{"name":"A 10"}}
<-- 91 {"msg":"updated","methods":["1"]}
--> 4903 {"msg":"method","method":"/categories/insert","params":[{"name":"A 11","_id":"9zMaMdM9y7Msv6Kp7"}],"id":"2"}
<-- 6 {"msg":"result","id":"2"}
<-- 94 {"msg":"added","collection":"categories","id":"9zMaMdM9y7Msv6Kp7","fields":{"name":"A 11"}}
<-- 94 {"msg":"updated","methods":["2"]}
--> 5675 {"msg":"method","method":"/categories/insert","params":[{"name":"A 12","_id":"kpaKaeZtuYMBQjcrQ"}],"id":"3"}
<-- 7 {"msg":"result","id":"3"}
<-- 78 {"msg":"added","collection":"categories","id":"kpaKaeZtuYMBQjcrQ","fields":{"name":"A 12"}}
<-- 78 {"msg":"updated","methods":["3"]}

With collection-hooks (only the first one is created):

--> 8459 {"msg":"method","method":"/categories/insert","params":[{"name":"A 10","_id":"AHshJX6EHA9MMwRfc"},null],"id":"1"}
<-- 10 {"msg":"added","collection":"categories","id":"AHshJX6EHA9MMwRfc","fields":{"name":"A 10"}}
--> 2286 {"msg":"method","method":"/categories/insert","params":[{"name":"A 11","_id":"btRhCwn34jMzhMu5w"},null],"id":"2"}
--> 2867 {"msg":"method","method":"/categories/insert","params":[{"name":"A 12","_id":"x59YRg5w3gGhFTfbp"},null],"id":"3"}

Any before/ after hooks are deactivated, I am running meteor 0.6.5.1 and collection-hooks 0.3.2. Any ideas?

[lacco]

I just recognized that removing the Meteor.Collection.prototype.insert (https://github.com/matb33/meteor-collection-hooks/blob/master/collection-hooks.js#L85) override "fixes" the problem for inserts.

[matb33]

This will be tough to diagnose... the likely cause is another smart package not playing well with collection hooks. A reproducible test case would go a long way...

[matb33]

Would you be willing to try the "refactor" branch?

https://github.com/matb33/meteor-collection-hooks/tree/refactor

Make sure to read the examples as the API has changed

[mizzao]

@lacco just for the sake of completeness, I was observing this same problem when using the hooks (only the first item is created/updated). @matb33 as you can see, it wasn't the find or publish we added that was causing this. I'm also happy to try refactor and help track this down if it still exists.

[matb33]

@mizzao and @lacco, are you by any chance generating your own _id for the insert calls?

[lacco]

@matb33 No, I don't set/ generate any _id on insert. Additionally, I have to admit that I had to migrate away from collection-hooks since it caused real trouble on a production app, so I am currently not able to try out the refactor branch :(

[mizzao]

@matb33 nope, not generating any _id either. Although, I can get back to reproducing this bug when I start working on the app that was experiencing it.

[matb33]

@mizzao Is the issue still present with the new version of collection hooks? crossing fingers

[matb33]

Not sure if this particular issue is still relevant in the newest version of collection hooks. Since this was filed, there was a complete rewrite.

For the sake of my sanity, I'll close this but please do re-open if the issue still occurs with the newest version of collection hooks

[matb33]

@mizzao you weren't crazy after all -- the duplicate _id was caused by a scenario where you insert the same document twice (not specifying the _id). Collection hooks mutated the doc by adding the _id as a convenience for the after hook. However that caused the second insert (which assumed no _id was added) to fail

[mizzao]

@matb33 that doesn't mean I'm not crazy, but I'll take it. I was working on some other aspects of my project for a while, but will start making heavy use of collection hooks very soon, and you'll probably hear from me again. :)

[matb33]

@mizzao I forgot to mention that what this fix implies is that in an after insert hook, you can't look at doc._id anymore. You have to get it via this._id (so that the doc remains unmutated by collection hooks)