Sails: Very strange behavior when adding postgres models to existing sails project.

[jpnarkinsky]

Waterline version: 0.13.5
Node version: 8.11.4
NPM version: 5.6.0 (but we mostly use [email protected]
Operating system: Ubuntu 18.10

---

I've got a very strange issue that I'd like some advice on. I have an existing, well-established sails app using Sails 1.0.2 (originally created using 0.13 and upgraded), [email protected]. For quite a while now, the app has had 9 models (all using pg). I'm now trying to add three more. Since we don't like automigrations, I created these in postgres, then created models for sails based on the postgres table using sails generate model. These models appear very similar to the ones that already exist.

However, if I try to do a simple query, I get some very strange errors. (Note that "User" is one of my pre-existing models, not one of the new ones.)

sails> User.find().then(console.log)
Promise {
_bitField: 0,
_fulfillmentHandler0: undefined,
_rejectionHandler0: undefined,
_promise0: undefined,
_receiver0: undefined }

sails> Unhandled rejection AdapterError: Unexpected error from database adapter: Could not run select() because of 2 problems:

• "datastore" is required, but it was not defined.

• "models" is required, but it was not defined.

If I remove the new model files, this works fine. If the files are present (even if the entire content is commented out!) I get the same error. I've tried recreating and simplifying the tables (since I used some advanced Postgres features) but that did nothing.

The only thing I've found that makes any difference is if I add the "datastore" attribute to the new models. In that case, I can query the "old" models but get the same error when I try to query a new one.

I've confirmed that all my settings in config/models.js & config/datastores.js look right. This issue disappears completely the moment I remove the new model files. I've tried to isolate this down to one model just to keep things simple.

Here's the postgresql schema for one of the tables:

                                  Table "public.mailbox"
  Column   |       Type        |      Modifiers      | Storage  | Stats target | Description
-----------+-------------------+---------------------+----------+--------------+-------------
 id        | character varying | not null            | extended |              |
 name      | character varying | not null            | extended |              |
 createdAt | character varying | not null            | extended |              |
 updatedAt | character varying | not null            | extended |              |
 usage     | "mailboxTypes"    |                     | plain    |              |
 profile   | jsonb             | default '{}'::jsonb | extended |              |
Indexes:
    "mailbox_pkey" PRIMARY KEY, btree (id)

(Note that I've also tried recreating this without using custom types like the "mailboxTypes" ENUM.)

Here's the model source code.

/**
 * Mailbox.js
 *
 * @description :: A model definition.  Represents a database table/collection/etc.
 * @docs        :: https://sailsjs.com/docs/concepts/models-and-orm/models
 */
const stockCreate = require('waterline/lib/waterline/methods/create');

module.exports = {
  attributes: {
    name: {
      type: 'string',
    },
    usage: {
      type: 'string',
    },
    profile: {
      type: 'json',
    },
    // folders: {
    //   collection: 'mailboxfolder', via:
    //   'mailbox',
    // },
  },
  create: function(newRecord, explicitCbMaybe, metaContainer) {
    if (!newRecord.id) {
      Object.assign(newRecord, {
        id: new URN({
          type: 'mailbox',
        }).toString(),
      });
    }
    return stockCreate.bind(this)(newRecord, explicitCbMaybe, metaContainer);
  },
};

(I realize the create function is a bit strange, but that's actually identical to the one we use for all the old models -- our 'id' column is a formatted URN that is used as part of our ABAC security architecture. We had problems with "beforeCreate" not firing for this purpose when we were first starting to use sails.)

I've been through the local.js, datastores.js, and models.js carefully, as well as the env/development.js, and nothing is apparent. My colleague tells me I should emphasize that everything starts working again if I just remove these models.

Finally, I get a very similar error message when I exit unless I add the 'datastore' key to the model. It still doesn't work for the Mailbox model, but the exit message goes away.

patrick@therios:~/src/hc-registry$ sails console --dontLift

 info: Loading app in interactive mode...
 info: Sails is not listening for requests (since `dontLift` was enabled).
 info: You still have access to your models, helpers, and `sails`.

 info: Initializing custom hook (`utilities`)
 info: Welcome to the Sails console.
 info: ( to exit, type <CTRL>+<C> )

sails> error: Could not tear down the ORM hook.  Error details: Error: Invalid data store identity. No data store exist with that identity.
    at Object.teardown (/home/patrick/src/hc-registry/node_modules/sails-postgresql/helpers/teardown.js:60:26)
    at wrapper (/home/patrick/src/hc-registry/node_modules/@sailshq/lodash/lib/index.js:3275:19)
    at Deferred._handleExec (/home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/machine/lib/private/help-build-machine.js:1076:19)
    at Deferred.exec (/home/patrick/src/hc-registry/node_modules/parley/lib/private/Deferred.js:286:10)
    at Deferred.switch (/home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/machine/lib/private/help-build-machine.js:1469:16)
    at teardownDatastore (/home/patrick/src/hc-registry/node_modules/sails-postgresql/lib/adapter.js:101:18)
    at /home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/async/dist/async.js:3047:20
    at replenish (/home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/async/dist/async.js:884:21)
    at /home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/async/dist/async.js:888:13
    at eachLimit$1 (/home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/async/dist/async.js:3136:26)
    at Object.<anonymous> (/home/patrick/src/hc-registry/node_modules/sails-postgresql/node_modules/async/dist/async.js:920:20)
    at Object.teardown (/home/patrick/src/hc-registry/node_modules/sails-postgresql/lib/adapter.js:96:13)
    at /home/patrick/src/hc-registry/node_modules/waterline/lib/waterline.js:758:27
    at /home/patrick/src/hc-registry/node_modules/waterline/node_modules/async/dist/async.js:3047:20
    at eachOfArrayLike (/home/patrick/src/hc-registry/node_modules/waterline/node_modules/async/dist/async.js:1002:13)
    at eachOf (/home/patrick/src/hc-registry/node_modules/waterline/node_modules/async/dist/async.js:1052:9)
    at Object.eachLimit (/home/patrick/src/hc-registry/node_modules/waterline/node_modules/async/dist/async.js:3111:7)
    at Object.teardown (/home/patrick/src/hc-registry/node_modules/waterline/lib/waterline.js:742:11)
    at Hook.teardown (/home/patrick/src/hc-registry/node_modules/sails-hook-orm/index.js:246:30)
    at Sails.wrapper (/home/patrick/src/hc-registry/node_modules/@sailshq/lodash/lib/index.js:3275:19)
    at Object.onceWrapper (events.js:313:30)
    at emitNone (events.js:106:13)
    at Sails.emit (events.js:208:7)
    at Sails.emitter.emit (/home/patrick/src/hc-registry/node_modules/sails/lib/app/private/after.js:56:26)
    at /home/patrick/src/hc-registry/node_modules/sails/lib/app/lower.js:67:11
    at beforeShutdown (/home/patrick/src/hc-registry/node_modules/sails/lib/app/lower.js:45:12)
    at Sails.lower (/home/patrick/src/hc-registry/node_modules/sails/lib/app/lower.js:49:3)
    at Sails.wrapper [as lower] (/home/patrick/src/hc-registry/node_modules/@sailshq/lodash/lib/index.js:3275:19)
    at REPLServer.<anonymous> (/home/patrick/src/hc-registry/node_modules/sails/bin/sails-console.js:205:16)
    at Object.onceWrapper (events.js:313:30)
    at emitNone (events.js:106:13)
    at REPLServer.emit (events.js:208:7)
    at REPLServer.emitExit (repl.js:396:10)
    at emitNone (events.js:111:20)
    at REPLServer.emit (events.js:208:7)
    at REPLServer.Interface.close (readline.js:368:8)
    at process.nextTick (repl.js:609:31)
    at _combinedTickCallback (internal/process/next_tick.js:131:7)
    at process._tickDomainCallback (internal/process/next_tick.js:218:9)
patrick@therios:~/src/hc-registry$

I'm sure that there's something on our side that's causing this, but I'm at a loss to figure out what.

Thanks!

[sailsbot]

@jpnarkinsky Thanks for posting, we'll take a look as soon as possible.

---

For help with questions about Sails, click here. If you’re interested in hiring @sailsbot and her minions in Austin, click here.

[rachaelshaw]

@jpnarkinsky What happens if you remove the "create" method? I'm not sure overriding that method will work-- Waterline and/or sails-postgresql probably does not know the difference between their notions of the standard create and a custom create from userland. (If it turns out it's this, and that behavior was working previously in Sails 0.12, then we should definitely add something to the upgrading guide about this)

[jpnarkinsky]

I'll try it when I get to my desk today, but two reasons I doubt that's it:

1. It's identical to the create method we use in all the "old" models.
2. I'm 90% sure I tried that.

But I'll check to make sure and get back to you.

[Later: confirmed, I commented out the create and it made no difference.]

[jpnarkinsky]

Another datapoint: if I add a completely new model from scratch (i.e. sails generate model) it shows exactly the same behavior. The thing that makes this so puzzling is that this works fine for existing models; it's only new models that fail. Does waterline cache the models somewhere?

[jpnarkinsky]

Okay, I think I figured this out. I was able to get it working by removing every datastore but 'default' from datastores.js & local.js and tweaking the configuration of the default datastore. Based on some time with the debugger, here's what it looks like to me:

1. I believe that, in some cases, sails-postgresql can fail to setup the datastore (for an unknown reason)
2. When it does this, Sails thinks the datastore is still there (as evidenced by sails.getDatastore()) but the datastore doesn't make it into sails.adapters['sails-postgresql'].datastores.
3. Presumably, although I didn't trace this all the way through, sails is following it's own list of datastores instead of the adapter's list. That's what causes the exceptions on exit (in the teardown method)
4. Likewise, when it does a select() using the postgres adapter, it tries to get the datastore by name from the adapter's list of datastores. Since the adapter never initialized that datastore, that produces the "Find" error message.

So, this appears to have been a configuration issue in our codebase, but it was made difficult to diagnose by not getting an error when the adapter didn't get setup. Does this all make sense to you guys? If so, I'll delve into sails-postgresql and try to do a fix then submit a PR.

[jpnarkinsky]

Okay, I think I found the problem, but I'd rather not try to address it. It's actually in waterline, and it looks like waterline isn't catching errors from registerAdapter:

//waterline/lib/waternline.js@713
        // Call the `registerDatastore` adapter method.
        datastore.adapter.registerDatastore(datastore.config, usedSchemas, next);

      } catch (err) { return next(err); }

So, it fails silently, and neither sails nor the operator knows that the datastore setup failed.

[jpnarkinsky]

Found out why it worked on my old models but not my new models... my old models had "required: true" for the id column. My new ones didn't have required: true, so it failed. The postgres adapter returned an error, but it's not getting displayed.

Hope all this is helpful.

[mikermcneil]

Okay, I think I found the problem, but I'd rather not try to address it. It's actually in waterline, and it looks like waterline isn't catching errors from registerAdapter

@jpnarkinsky I'll see if I can figure it out- if it turns out it's not handling an error, this is something worth fixing long term anyway since it'll just keep swallowing and swallowing

[mikermcneil]

Hope all this is helpful.

@jpnarkinsky it is! Thank you.

I took a look (re invocation of the registerDatastore function not catching errors), and I don't see offhand why the error wouldn't be handled. Even if the adapter's registerDatastore function throws synchronously instead of calling its callback with an error, it'd still be handled by the outer try block:
https://github.com/balderdashy/waterline/blob/v0.13.5/lib/waterline.js#L713-L716

All that said, since we're inside an async.each() which simultaneously does this for multiple datastores at the same time:
https://github.com/balderdashy/waterline/blob/v0.13.5/lib/waterline.js#L647-L650

So it seems possible that there could be a race condition going on there. async.each() calls its final callback upon seeing the first error, but since iteratee functions are presumably asynchronous, and they were all started at the same time, they'll keep running. I'm not sure how that would be causing the behavior you're seeing offhand, but it might be worth a think.

Nevertheless, I think you're onto something with what you said in https://github.com/balderdashy/sails/issues/4617#issuecomment-433644556 -- I'm also pretty sure that's the issue.

The load-time logic in Waterline (especially involving datastores) is one of the last remaining bits of code from waterline ≤0.12 that wasn't overhauled in 0.13, so since it hasn't had as much love recently, I always have a tendency to assume it's the cause of our problems. That said, it's also possible there's another spot in waterline or sails-hook-orm that's causing this.

As you may have noticed in the code, the medium-term plan is to refactor to always just use Waterline.start(). It'll be kind of a mess to do, with not a _huge_ return on investment, which is why we haven't done it yet. But it's definitely on my radar.

In the mean time, I'm glad you posted the underlying configuration problems that were causing this (could make a big difference for others finding this conversation in search).

If you have any other ideas about what could be going on as you're working with this stuff, or if you think I'm off base with my takeaway about error handling above, def let me know. Thank you!