Previous document is lost inside async callbacks

[atoi]

Sometimes in "after.update" hook the value of "this.previous" document is undefined. That happens when you make an update call inside a callback, wrapped with bindEnvironment.
I provided a simple example to see the issue. Just call "generateComments" method and take a look at your server console. You'll see something like this:

Previous post is undefined
Previous post is { _id: 'tKcwaidC9NCNJnSt2', title: 'post #6', commentsCount: 0 }
Previous post is undefined

The code below will work in meteor 1.0.4 only as it uses "rawCollection" method to run bulk insert.
Trust me, the same issue happens in meteor 1.0.3.2 when I use mongo npm to run bulk inserts.
I just did not want to bloat the example.

Example code:

posts = new Mongo.Collection('posts');
comments = new Mongo.Collection('comments');

if (Meteor.isServer) {
    Meteor.startup(function () {
        posts.remove({});

        _.each(_.range(0, 10), function (i) {
            posts.insert({title: 'post #' + i, commentsCount: 0});
        });
    });

    Meteor.methods({
        generateComments: function () {
            posts.find().forEach(function (post) {
                var data = _.map(_.range(0, 100), function (i) {
                    return {
                        _id: Random.id(),
                        postId: post._id,
                        title: 'comment #' + i
                    }
                });

                comments.rawCollection().insert(data, Meteor.bindEnvironment(function () {
                    comments.remove({_id: {$nin: _.pluck(data, '_id')}, postId: post._id});
                    posts.update(post._id, {
                        $set: {
                            commentsCount: data.length
                        }
                    });
                }));
            });
        }
    });

    posts.after.update(function (userId, post) {
        console.log('Previous post is', this.previous);
    });
}

[atoi]

Here is simpler example that just uses Meteor.defer and no calls to npm packages:

posts = new Mongo.Collection('posts');
comments = new Mongo.Collection('comments');

if (Meteor.isServer) {
    Meteor.startup(function () {
        posts.remove({});
        comments.remove({});

        _.each(_.range(0, 10), function (i) {
            var postId = posts.insert({title: 'post #' + i});

            _.each(_.range(0, 10), function (i) {
                comments.insert({title: 'comment #' + i, postId: postId});
            });
        });
    });

    Meteor.methods({
        triggerUpdate: function () {
            posts.find().forEach(function (post) {
                Meteor.defer(function () {
                    posts.update(post._id, {
                        $set: {
                            updatedAt: new Date()
                        }
                    });
                });
            });
        }
    });

    posts.after.update(function (userId, post) {
        if (!this.previous) console.warn('Previous post is lost');

        Meteor.defer(function () {
            comments.update({
                postId: post._id
            }, {
                $set: {
                    postUpdatedAt: post.updatedAt
                }
            }, {
                multi: true
            });
        });
    });

    comments.after.update(function (userId, comment) {
        if (!this.previous) console.warn('Previous comment is lost');
    });
}

[ghost]

I want confirm the bug. it's very strange, it happens irregular see output:

I20150318-10:31:29.968(1)? triggerUpdate fired
W20150318-10:31:29.984(1)? (STDERR) Previous post is lost "post #3"
W20150318-10:31:29.987(1)? (STDERR) Previous post is lost "post #3"
W20150318-10:31:29.998(1)? (STDERR) Previous post is lost "post #6"
W20150318-10:31:30.004(1)? (STDERR) Previous post is lost "post #8"
W20150318-10:31:30.016(1)? (STDERR) Previous comment is lost "comment #1"
W20150318-10:31:30.016(1)? (STDERR) Previous comment is lost "comment #0"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #2"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #6"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #9"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #4"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #5"
W20150318-10:31:30.017(1)? (STDERR) Previous comment is lost "comment #8"
W20150318-10:31:30.018(1)? (STDERR) Previous comment is lost "comment #3"
W20150318-10:31:30.019(1)? (STDERR) Previous comment is lost "comment #7"

I20150318-10:31:34.530(1)? triggerUpdate fired
W20150318-10:31:34.541(1)? (STDERR) Previous post is lost "post #1"
W20150318-10:31:34.549(1)? (STDERR) Previous post is lost "post #4"
W20150318-10:31:34.551(1)? (STDERR) Previous post is lost "post #5"
W20150318-10:31:34.553(1)? (STDERR) Previous post is lost "post #6"
W20150318-10:31:34.556(1)? (STDERR) Previous post is lost "post #8"
W20150318-10:31:34.559(1)? (STDERR) Previous post is lost "post #7"
W20150318-10:31:34.569(1)? (STDERR) Previous post is lost "post #9"
W20150318-10:31:34.608(1)? (STDERR) Previous comment is lost "comment #0"
W20150318-10:31:34.608(1)? (STDERR) Previous comment is lost "comment #8"
W20150318-10:31:34.608(1)? (STDERR) Previous comment is lost "comment #4"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #7"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #2"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #3"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #9"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #5"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #1"
W20150318-10:31:34.609(1)? (STDERR) Previous comment is lost "comment #6"

I also confirm, that in normal (sync) mode it works normally

[atoi]

Looks like the same happens when Meteor.setInterval is used. As far as I know "Meteor.defer", "Meteor.setInterval" and "Meteor.setTimeout" use "Meteor.bindEnvironment" under the hood, so looks like previous document is lost somewhere in that "environment"

[ghost]

Am 18.03.15 um 16:02 schrieb atoi:

Looks like the same happens when Meteor.setInterval is used. As far as
I know "Meteor.defer", "Meteor.setInterval" and "Meteor.setTimeout"
use "Meteor.bindEnvironment" under the hood, so looks like previous
document is lost somewhere in that "environment"

—
Reply to this email directly or view it on GitHub
#103 (comment).

yeah, definetly it is an environment variable Issue @atoi.
Looks like, "sometimes" the call is not in the same environment than the
prev.docs were created.

@matb33 do you have an idea what the issue there is, maybe we then could
help to fix it.
Or do you think, it is an Meteor internal issue with the bindEnvironment?

[matb33]

This really does look like a bug, and odds are it's a collection-hooks problem with bindEnvironment as you suspect. I don't have the time to look at it now but it's on the list for sure.

[mizzao]

Two environment variables we use are for the userId in a publish function and for direct ops:

https://github.com/matb33/meteor-collection-hooks/blob/master/collection-hooks.js

Would any of those affect the operation here?

[JohnRodney]

I was looking through this as this error showed up for me today today. If I just console.log the value of this it is the entire global object. So somehow the caller of the after update is the global object.

A non elegant solution that worked for me is to locally patch the project by just passing the previous doc into the function. This doesn't solve the issue for the repo unfortunately because this doesn't change the issue that your caller is now global.

But for anyone who has this issue as a blocker you can clone the repo and change line 72 in update to this:

_.each(docs, function (doc) {
  o.aspect.call(_.extend({
    transform: getTransform(doc),
    previous: prev.docs && prev.docs[doc._id],
    affected: affected,
    err: err
   }, ctx), userId, doc, fields, prev.mutator, prev.options, prev.docs)
})

This really confuses me as I can see you are passing an inline object as the first arguement of call here. I console logged the result and this is a valid object being returned in my case.

If anyone else has any theories I wouldn't mind helping but I needed a solution for the prev object atm (deadlines 😦 ). So I didn't get to dig any deeper into the code as I'm unfamiliar with the project as a whole.

[JohnRodney]

@matb33 I read from a couple other posts you are not finding much time to spend on this repo lately. I just wanted to ask (whenever you have time) If you would consider a hotfix patch where you just passed the previous document in as a temp solution.

Or if you could guide a bit on where you would imagine the context of this is being lost in this case. Thanks for your time.