Saving model with auto-fetched relations causes stack overflow

[dirkmc]

If a model has autoFetch true, and you fetch the model then try to save it, Node reports:

RangeError: Maximum call stack size exceeded
2 Aug 19:22:00 - [nodemon] app crashed - waiting for file changes before starting...

If the auto-fetched field is overwritten it saves ok:

db.Post.get(1337, function(e,p) {
    p.user = null;
    p.channel = null;
    p.template = null;
    p.save({ updated_at: new Date() }, function(err) {
        console.log('done')
    });
});

[dresende]

Please tell use node version, orm version.

[dirkmc]

This is with the latest version of orm on the master branch

mac> node --version
v0.10.12

[dirkmc]

In Instance.js I added some debugging output so that it looks like this:

var saveInstance = function (cb, saveOptions) {
    console.log('------------')
    handleValidations(function (err) {
        if (err) {
            return saveError(cb, err);
        }

        if (opts.is_new) {
            waitHooks([ "beforeCreate", "beforeSave" ], function (err) {
                if (err) {
                    return saveError(cb, err);
                }

                return saveNew(cb, saveOptions, getInstanceData());
            });
        } else {
            waitHooks([ "beforeSave" ], function (err) {
                if (err) {
                    return saveError(cb, err);
                }

                console.log(opts.table, opts.data.id)
                console.log(opts.changes);

                if (opts.changes.length === 0) {
                    console.log('saving associations')
                    return saveAssociations(function (err) {
                        return afterSave(cb, false, err);
                    });
                }
                    console.log('saving persisted')

                return savePersisted(cb, saveOptions, getInstanceData());
            });
        }
    });
};

Is this line correct?

                if (opts.changes.length === 0) {

This is the console output:

    ...
------------
users 1
[]
saving associations
------------
posts 1337
[]
saving associations
------------
users 1
[]
saving associations
------------
posts 1337
[]
saving associations
------------
users 1
[]
saving associations
------------
posts 1337
[]
saving associations
------------
users 1
[]
saving associations

RangeError: Maximum call stack size exceeded

In my definitions I have this:

models.User = db.define("users", {
    // ...
}, {
    autoFetch: true,
    autoFetchLimit: 1,

models.Post = db.define("posts", {
    // ...
}, {
    autoFetch: true,
    autoFetchLimit: 1,

// ...
models.Post.hasOne("user", models.User);
models.Post.hasOne("channel", models.Channel);
models.Post.hasOne("template", models.Template);

models.User.hasMany("channels", models.Channel, {
    // ...
}, {
    reverse: "users", // Other side of many-to-many
    mergeTable: "subscriptions",
    mergeId: "user_id",
    mergeAssocId: "channel_id"
});

[goulwenlorcy]

Hello, I have the same problem with a simple code (latest version of orm & node v0.8.9)

            this.models.permissions.get(uid, function (err, item) {
               item.save(arg, function (err) {     
                     /* ... */
                });               
            });

Node crash with:

RangeError: Maximum call stack size exceeded

Without autoFetch, it works.

[notheotherben]

@goulwenlorcy would you be able to test with v2.0.15 of ORM and tell us whether it has the same issue there? Just trying to narrow down where the issue may have crept in.

[goulwenlorcy]

With the v2.0.15, I haven't the crash error but it doesn't work and the /* ... */ part is executed 2 times.

[dresende]

This line (and subsequent scope)..

 if (opts.changes.length === 0) {

.. was added by me to try to solve the double call to .save(). Not sure how it happened. It makes the workflow continue if there are no changes (avoiding calling UPDATE on the model but continue to check associations).

[dresende]

@goulwenlorcy please post a complete example. I cannot reproduce your error..

[dirkmc]

Here's a complete example:

app.use(orm.express(Config.db.uri, {
    define: function (db, models) {
        models.User = db.define("users", {
            email: String
        });

        models.Post = db.define("posts", {
            context: String
        }, {
            // If I comment out this line it works
            autoFetch: true
        });

        models.Post.hasOne("user", models.User);

        models.Post.get(1337, function(e,p) {
            // If I uncomment this line it works
            // p.user = null;
            p.save({ updated_at: new Date() }, function(err) {
                console.log('done')
            });
        });
    }
}));

This produces a stack overflow error:

RangeError: Maximum call stack size exceeded

[dresende]

Please try v2.1.0 and tell us if the same happens.

[petrovi4]

I have same bug in v2.1.0

[dirkmc]

Hi, I'm afraid I see the same bug also. Diogo are you not able to repro with the code I pasted above?

[dxg]

I've reproduced it, going to add a failing test case in a moment

[notheotherben]

Just a heads up - the test runner is currently not running test. I've fixed it in my repo (2e50cf2) which I'm planning on merging as soon as I can get a free minute to make Travis pass all tests. (Having issues with the SQLite driver, but ORM itself is working correctly)

[dxg]

I consistently get a few failing test cases in mysql, postgres & sqlite in my linux VM other than the one above.

hasOne reverse find should be able to find given an association id - column "ownerId" does not exist
hasOne reverse find should be able to find given an association instance - timeout

Do you guys get these too? Is the stuff you're working on @spartan563 in any way related?

[notheotherben]

Timeouts are caused (usually) by other tests failing. Try grabbing the latest code from spartan563/node-orm2 and running your tests against that, should fix that particular issue.

[notheotherben]

Also, having just looked at your test case - it could be caused by attempting to save an object without any changes, I don't recall noticing anything there which could have caused it but I wasn't actually looking for anything when I went through it. Might be worth keeping that in mind when searching for the cause of the SO.

[dirkmc]

It does have a change - updated_at: new Date()

[dirkmc]

Just in case it wasn't clear from the log output I pasted above, the stack overflow is caused by the Post trying to save it's associated User, which tries to save its associated Post, which tries to save its asssociated User etc etc

[dresende]

@dxg I also have those 2 test cases failing.

[dxg]

Glad its not just me.

dirkmc & spartan: the infinite loop happens regardless of if something changed. Ill add a second test case to make this clear and perhaps to avoid future issues.

[dxg]

So it seems I previously fixed this issue, but I didn't add a test case. Then dresende fixed another issue which brought the infinite loop back, and he didn't add a test case for what he fixed either.

Now I've added a test case, and I've sort of got a fix working (still not completely) but it will likely break the thing dresende fixed. Someone will open an issue about whatever it is he fixed again, and that time round we'll add test cases and fix it properly ;)

[notheotherben]

Hahahaha, sounds like software development. Could you point me to the commit in which you fixed it so I can merge the fixes into my repo. Currently that test case is preventing me from testing anything else.

[dirkmc]

haha it's the infinite loop of software development, very meta

[dresende]

I think what I might have fixed was the double saving.

[SamuelBolduc]

Could you refer to this commit? Where you fixed the double saving? I will try to fiddle with it to see if I can find something

[dresende]

Try (before) one of these commits:

• Changes autoFetch to avoid autofetching if instance is not saved (19ee31e)
• Fixes not saving associations if no changes (other than associations) are made (8f8e2db)

[SamuelBolduc]

I installed 2.1.0, tested the save and it did not work. Then I manually reverted 8f8e2db and now it works. So this commit is really the problem.

[dresende]

You mean reverted to that commit or to the one before that?

[SamuelBolduc]

Hmm well I removed this :

return saveAssociations(function (err) {
  return afterSave(cb, false, err);
});

And replaced it with this :
return saveInstanceExtra(cb);

[dresende]

Oh.. ok. I have to see how issue #256 is with v2.1.0 but with that change reverted.

[dresende]

Well, it doesn't work. I'm going to try to fix it in another way.

[dresende]

I think a mix of both ways is needed. Maybe the problem is that saveOptions is not checked before calling saveAssociations. I'm going to try a change to see if it still works for the other issue. If it does I'll post a change here that you can try.

[dresende]

It seems to work. Try this instead of return saveInstanceExtra(cb);:

if (saveOptions.saveAssociations === false) {
    return saveInstanceExtra(cb);
}
return saveAssociations(function (err) {
    return afterSave(cb, false, err);
});

[notheotherben]

Just made the changes, it appears to call the callback multiple times... Has fixed the infinite loop issue though

[notheotherben]

Stack Traces

First Call to Callback

• setup.validations.stalkId
• saveInstanceExtra
• afterSave
• saveInstance
• saveAssociation
• saveInstanceExtra
• saveInstance START
• nextHook
• nextHook
• export.wait

Second Call to Callback

• setup.validations.stalkId
• saveInstanceExtra
• afterSave
• saveInstance
• saveAssociations
• saveInstance START
• nextHook
• nextHook
• export.wait
• nextHook

Breakdown:

saveInstance -> saveInstanceExtra -> saveAssociation -> saveInstance -> afterSave -> saveInstanceExtra
saveInstance -> saveAssociations -> saveInstance -> afterSave -> saveInstanceExtra

[notheotherben]

Looks like it may be caused by a race condition in saveAssociations. The assumption is made that all the loops which begin async operations to save associations (if any) will complete before the async operations do. The result is that pending === 0 can hold in as many as 3 places.

I'm going to try and fix the issue quickly and I'll let you know how it turns out.

[notheotherben]

Okay, the issue can be fixed by doing the following:

Initialize pending = 1 at Instance.js:225
Test if(--pending === 0) at Instance.js:289

Rationale
Treat the pending completion of loops as a pending operation, and only allow us to complete once the loops have finished AND all async operations have completed.

[dirkmc]

Works for me

[dxg]

Just made the changes, it appears to call the callback multiple times... Has fixed the infinite loop issue though

Hahaha yeah that's where I was at yesterday before I went to sleep.
We need to add a test case for 8f8e2db .

On a side note, some of that saving code needs a refactor.
Note the similarity between lib/Instance.js#L121 and /lib/Instance.js#L217.

It's effectively a duplicate (next is afterSave). I have some WIP changes to fix this, but will wait till all your stuff is merged.

[dresende]

Yes, the difference is that line 217 is run after the db.update that it's what is being avoided by that (because there's nothing to save).

[dirkmc]

While you guys are refactoring that code, would it be possible to take a look at this:
#278

[dresende]

Don't worry, we'll look into it before posting a new version 😄

[dirkmc]

Great, thanks!

[petrovi4]

Stack overflow fixed in current master, but other bug still exists:
After run this code:

tour.setTourist(tourists, function(err){
    tour.amount = 1000;
    tour.save();
});

I see in console:

DELETE FROM "tour_tourist" WHERE "tour_id" = 5
INSERT INTO "tour_tourist" ("tour_id", "tourist_id") VALUES (5, 5) RETURNING *
INSERT INTO "tour_tourist" ("tour_id", "tourist_id") VALUES (5, 2) RETURNING *
INSERT INTO "tour_tourist" ("tour_id", "tourist_id") VALUES (5, 3) RETURNING *

DELETE FROM "tour_tourist" WHERE "tour_id" = 5
INSERT INTO "tour_tourist" ("tour_id", "tourist_id") VALUES (5, 5) RETURNING *
INSERT INTO "tour_tourist" ("tour_id", "tourist_id") VALUES (5, 3) RETURNING *

So, second save always override changes made with first.

p.s. With cache enabled after

setTourist

property tour.tourist still contains previous list of tourists.

[SamuelBolduc]

So, second save always override changes made with first.

Looks like I'm having the same issue here #298

[dresende]

This should be fixed now. About this other issue of multiple INSERT let's discuss it in #298 .

[Gromina]

I still have stack overflow problem on save in 2.1.1:

    @Thing =  db.define 'thing',
      title: {type:'text'}
    ,
      autoFetch: true
    @Model =  db.define 'model',
      filename: {type: 'text'}
    ,
      cache: false
    @Model.hasOne 'thing', @Thing,
      reverse: 'models'
      autoFetch: true

When I save Thing instance, it gives me stack overflow. What's wrong with my code?

Upd: I've made a fork with failing test #338