Custom getters called twice in a row?

[SteveEisner]

I'm tracking a bug in our library that uses Sequelize, when updated to 1.7.0-beta8 (but possibly introduced in an earlier version)

We've defined a model with a type that uses a custom getter in the new format:

      tags:
        type: Sequelize.TEXT,
        get: function(field) {
          val = this.getDataValue(field);
          console.log(val);  // <<-- we log here to show the issue
          if (val == null) return [];
          return JSON.parse(val);
        },
        set: function(val, field) {
          this.setDataValue(field, (val == null) ? null : JSON.stringify(val));
        }

What we're seeing is that the getter is called twice - one time with the raw data from the database, and a 2nd time where the raw data is already JSON parsed. The 2nd time crashes because it receives a "hydrated" object instead of the raw string.

Stack trace of the first time:

    at module.exports.DAO.get (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:95:41)
    at module.exports.DAO.get (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:106:30)
    at module.exports.Object.defineProperty.get (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:44:19)
    at null.<anonymous> (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:391:47)
    at EventEmitter.emit (events.js:95:17)
    at chainer.runSerially.success.error.emitter.query.sql (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/query-interface.js:492:17)
    at EventEmitter.emit (events.js:98:17)
    at module.exports.finish (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/query-chainer.js:142:30)
    at exec (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/query-chainer.js:96:16)

and the 2nd:

    at module.exports.DAO.get (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:95:41)
    at module.exports.DAO.get (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:106:30)
    at module.exports.DAO.toJSON (/Users/steve/projects/syi/mean-example/node_modules/sequelize/lib/dao.js:619:17)
    at Object.stringify (native)
    at ServerResponse.res.json (/Users/steve/projects/syi/mean-example/node_modules/express/lib/response.js:190:19)
    at Object.res.format._.extend.application/json (/Users/steve/projects/syi/mean-example/node_modules/feathers/lib/providers/rest.js:33:17)
    at ServerResponse.res.format (/Users/steve/projects/syi/mean-example/node_modules/express/lib/response.js:475:13)
    at Object.responder [as handle] (/Users/steve/projects/syi/mean-example/node_modules/feathers/lib/providers/rest.js:31:13)
    at next (/Users/steve/projects/syi/mean-example/node_modules/express/node_modules/connect/lib/proto.js:193:15)

notes -

• sorry if any typos etc in the excerpt above - it's not a literal copy & paste, just a reconstruction of the problem
• I believe the bug is related to Setters not working as expected - called multiple times during create #1162 - and the work that was merged in Fix for order by when you only have 1:1 includes #1189
• I left a comment in 6367758 at the line that I think may be the problem? but I'm not familiar enough with the dao code to be sure.

[mickhansen]

That line should not be the issue, it's just providing BC for .values.

[mickhansen]

How are you retrieving the data from the model? I.e. are you using .values/.get/.toJSON() ?
This looks strange, a getter shouldn't modify the original value, so multiple get calls should have no effect. Can you please try logging this.dataValues in the different calls? Some internal method must be doing something bad.

[mickhansen]

If you can provide me with a self-contained test case, i'll get this fixed for you today.

[SteveEisner]

Yep! I did that logging, the first time I get a string "["tag1", "tag2"]" and the 2nd time it's an Array of strings [ 'tag1' , 'tag2' ]
The 2nd time is definitely the results of the 1st time being fed back in to the getter.
I've worked around the issue by checking the dataValue and if it's already an array, just return that value without running the getter code again. But that just happens to work because I can recognize the transformed value. Would be harder to reliably detect string-to-string translation like the hashing in #1162...

[SteveEisner]

Appreciate it! It might take a little time -- we're using coffeescript, custom helper functions that create the Sequelize classes, etc. so I had to unwind the code a bit to create that example. I'll see if I can extract a simple example!

[mickhansen]

Well this issue definitely needs a real fix.
.dataValues should give you an object always.

[mickhansen]

Alright, i'll just need a model definition and the calls you're making to produce this error (create -> find, etc). Well yeah, a unit test - Then it should be simple for me to track down and fix this.

[SteveEisner]

Just in case it's not clear from my example - my DB field is backed by type Sequelize.STRING, so in the first call, I'm getting what I expect from this.dataValues(field), a string. And then I change its type when I parse that string into an object. Which might be the problem -- or at least revealing a kind of boundary case where inbetween the first call (hydration) and the 2nd (convert toJSON) fields of this type aren't consistently used as either pre-hydrated or post-hydrated? if that makes sense...

[mickhansen]

I see that - But since it's a getter, it shouldn't affect the raw value - Unless node suddenly magically passes strings by reference now :)

[SteveEisner]

nope, and I'm not writing back into the datavalues or anything! :)

[mickhansen]

Setters and getters should be completely ignored when hydrating from the database, atleast that's the intent.

[mickhansen]

But yeah, somethings off - A test case to prove this from start to end would be great - Then i can fix. (If you feel confident you could just create a new sample file/model and see if you can reproduce it there).

[SteveEisner]

right, that's why I called out the line I did -- that function appears to be called during hydration, and in turn, it appears to call all the customGetters

[SteveEisner]

ok! working on a repro case now - do you happen to have a sample/skeleton I could drop a model into? we're really off the beaten path in terms of our server structure... (we use coffeescript + a structure based on https://github.com/JeyDotC/articles/blob/master/EXPRESS%20WITH%20SEQUELIZE.md, wrapped in feathersjs :)

[mickhansen]

You can just do it in the style of a unit test, https://github.com/sequelize/sequelize/blob/master/test/dao/values.test.js#L199

[mickhansen]

.values/.toJSON is used nowhere in the lib code, hmm.

[mickhansen]

Mind turning on long stack traces and giving me the stracktraces from your original example? I'd like to follow it :)

[SteveEisner]

Sure, I've pulled one of the examples & am modifying it, will dump a long stack trace...

But your previous comment makes sense & might explain something. We are hitting the ORM via feathersjs wrappers, which is what's calling the toJSON (it automatically exposes JSON endpoints). You have an overload of .toJSON at line 623 of dao.js. So the flow is something like:

• PUT to /article/1
• feathersjs intercepts & calls a .update() function
• in that function we call Article.update() [article is a Sequelize model]
• we pass the updated Article back to featherjs [ the object is a fully hydrated Sequelize object ]
• it calls Article.toJSON & pipes out the result

My best guess now is that if I hydrate and object and dump "toJSON" on it I can repro this without needing feathersjs, etc.

[SteveEisner]

Updating - my small test case did not repro the bug, and since this is now about feathersjs wrapping ORM the burden's on me to prove that the bug is actually happening inside your code :) so I'm looking at the big app again & tracing to see if maybe I'm sending back the wrong object to feathers.

[SteveEisner]

OK. Got it. Here's the repro case.

Relevant parts are:

1. There's a custom "tags" field with a getter and setter. I log the getter so you can see that the incoming dataValue changes over time
2. It's the .save() call that is modifying the original object in some way. Calling toJSON() before .save() doesn't crash but calling it afterwards (on the same object) does.
3. Don't worry about the crash error message, it's just JSON.parse failing on the array. Important part is that in the 2nd and 3rd toJSON cases, the getter is getting an Array object instead of the string it expects.

Am I doing something wrong by expecting to be able to use the object this way after .save()?

var Sequelize = require(__dirname + "/node_modules/Sequelize/index");

// uses mysql default test DB
var Contact = new Sequelize('test', 'root', '').define('Contact', {
  first: { type: Sequelize.STRING },
  last: { type: Sequelize.STRING },
  tags: { 
    type: Sequelize.STRING,
    get: function(field) {
      val = this.getDataValue(field);
      console.log(val); // Shows that the 2nd time, it's getting already-hydrated data
      return JSON.parse(val);
    },
    set: function(val, field) {
      this.setDataValue(field, JSON.stringify(val));
    }
  }
});

var contact = Contact.build({
  first: 'My',
  last: 'Name',
  tags: ['yes','no']
});
contact.save().complete(function(err, me) {
  var idToTest = me.id;

  Contact.find({
    where: { id: idToTest }
  }).complete(function (err, contact) {
    console.log(contact);

    console.log(1);
    var json = contact.toJSON(); // This will not error
    console.log(json);

    contact.first = 'Your';
    contact.save().complete(function (err,saved) {

      console.log(2);
      var json1 = saved.toJSON(); // This will error
      console.log(json1);

      console.log(3);
      var json2 = contact.toJSON();  // This will also error.
      console.log(json2);
    });

  });
});

[mickhansen]

.save() should definitely not interfer with the ability to use .toJSON()/.get().
Thanks for the test case, i'll eat some breakfast and then take a look at it.

[mickhansen]

Investigating, more complex than i thought.

[mickhansen]

@SteveEisner what dialect are you using?

[mickhansen]

Solved it, postgres is doing some value processing on query result and uses object[key] directly instead of dataValues causing the setter to be triggered.

[mickhansen]

Fixed in #1239

[SteveEisner]

Glad you found it and thanks for the fast response! I'm using the mysql dialect so I was wondering if a fix in postgres code would make the difference. But I've confirmed that this is fixed in both the test case & my larger app.
Cheers-

[mickhansen]

Shouldn't ever have been an issue with the mysql dialect honestly. Test was passing for mysql :)