Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Stack traces are awful #12044

Closed
jedwards1211 opened this issue Mar 29, 2020 · 23 comments · Fixed by #13347
Closed

Stack traces are awful #12044

jedwards1211 opened this issue Mar 29, 2020 · 23 comments · Fixed by #13347
Labels
released type: refactor For issues and PRs. Things that improve the code readability, maintainability, testability, etc.

Comments

@jedwards1211
Copy link
Contributor

jedwards1211 commented Mar 29, 2020

No one wants stack traces like this, and they don't have to be this bad in recent versions of node.

SequelizeValidationError: Validation error: Cannot read property 'length' of undefined
      at Promise.all.then (node_modules/sequelize/lib/instance-validator.js:74:15)
      at tryCatcher (node_modules/bluebird/js/release/util.js:16:23)
      at Promise._settlePromiseFromHandler (node_modules/bluebird/js/release/promise.js:547:31)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:604:18)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at PromiseArray._resolve (node_modules/bluebird/js/release/promise_array.js:127:19)
      at PromiseArray._promiseFulfilled (node_modules/bluebird/js/release/promise_array.js:145:14)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:609:26)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at Promise._resolveCallback (node_modules/bluebird/js/release/promise.js:466:57)
      at Promise._settlePromiseFromHandler (node_modules/bluebird/js/release/promise.js:559:17)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:604:18)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at PromiseArray._resolve (node_modules/bluebird/js/release/promise_array.js:127:19)
      at PromiseArray._promiseFulfilled (node_modules/bluebird/js/release/promise_array.js:145:14)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:609:26)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at Promise._resolveCallback (node_modules/bluebird/js/release/promise.js:466:57)
      at Promise._settlePromiseFromHandler (node_modules/bluebird/js/release/promise.js:559:17)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:604:18)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at Promise._resolveCallback (node_modules/bluebird/js/release/promise.js:466:57)
      at Promise._settlePromiseFromHandler (node_modules/bluebird/js/release/promise.js:559:17)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:604:18)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at Promise._fulfill (node_modules/bluebird/js/release/promise.js:673:18)
      at PromiseArray._resolve (node_modules/bluebird/js/release/promise_array.js:127:19)
      at PromiseArray._promiseFulfilled (node_modules/bluebird/js/release/promise_array.js:145:14)
      at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:609:26)
      at Promise._settlePromise0 (node_modules/bluebird/js/release/promise.js:649:10)
      at Promise._settlePromises (node_modules/bluebird/js/release/promise.js:729:18)
      at _drainQueueStep (node_modules/bluebird/js/release/async.js:93:12)
      at _drainQueue (node_modules/bluebird/js/release/async.js:86:9)
      at Async._drainQueues (node_modules/bluebird/js/release/async.js:102:5)
      at Immediate.Async.drainQueues [as _onImmediate] (node_modules/bluebird/js/release/async.js:15:14)
      at process.topLevelDomainCallback (domain.js:120:23)
@sushantdhiman
Copy link
Contributor

Any help with modernizing our code-base will be appreciated :)

@sushantdhiman sushantdhiman added the type: refactor For issues and PRs. Things that improve the code readability, maintainability, testability, etc. label Apr 4, 2020
@jedwards1211
Copy link
Contributor Author

Oh okay, yeah I'll start working on some of that stuff, glad the plan is to switch to async!

@jedwards1211
Copy link
Contributor Author

jedwards1211 commented Apr 4, 2020

FYI we should try using https://github.com/sgilroy/async-await-codemod before doing any of that work by hand

@jedwards1211
Copy link
Contributor Author

It works on a lot of things 🎉 but not on the bluebird stuff. I'll look into writing a codemod to automatically convert bluebird things

@SimonSchick
Copy link
Contributor

I'm having a hard time getting --async-stack-traces to work on locally which makes most stack traces borderline useless, got any guidance on that?

@jedwards1211
Copy link
Contributor Author

Can you show me the command you're running? Maybe it's in the script argument position instead of the node argument position

@jedwards1211
Copy link
Contributor Author

We can close this now too right?

@sushantdhiman
Copy link
Contributor

Validation or client side errors have improved significantly

ValidationError [SequelizeValidationError]: notNull Violation: User.name cannot be null
    at InstanceValidator._validate (/var/projects/oss/sequelize/lib/instance-validator.js:78:13)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
    at async InstanceValidator._validateAndRunHooks (/var/projects/oss/sequelize/lib/instance-validator.js:111:7)
    at async InstanceValidator.validate (/var/projects/oss/sequelize/lib/instance-validator.js:93:12)
    at async model.save (/var/projects/oss/sequelize/lib/model.js:3867:7)
    at async Function.create (/var/projects/oss/sequelize/lib/model.js:2195:12)
    at async /var/projects/oss/sequelize/sscce.js:27:3 {
  name: 'SequelizeValidationError',
  errors: [
    ValidationErrorItem {
      message: 'User.name cannot be null',
      type: 'notNull Violation',
      path: 'name',
      value: null,
      origin: 'CORE',
      instance: [User],
      validatorKey: 'is_null',
      validatorName: null,
      validatorArgs: []
    }
  ]
}

But we can still improve database errors. We can inject stack trace from original caller so it shows what method is failing, like User.create in this case

UniqueConstraintError [SequelizeUniqueConstraintError]: Validation error
    at Query.formatError (/var/projects/oss/sequelize/lib/dialects/postgres/query.js:338:18)
    at Query.run (/var/projects/oss/sequelize/lib/dialects/postgres/query.js:87:18)
    at processTicksAndRejections (internal/process/task_queues.js:97:5) {
  name: 'SequelizeUniqueConstraintError',
  errors: [
    ValidationErrorItem {
      message: 'id must be unique',
      type: 'unique violation',
      path: 'id',
      value: '1',
      origin: 'DB',
      instance: [User],
      validatorKey: 'not_unique',
      validatorName: null,
      validatorArgs: []
    }
  ],
  fields: { id: '1' },
  parent: error: duplicate key value violates unique constraint "Users_pkey"
      at Connection.parseE (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:614:13)
      at Connection.parseMessage (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:413:19)
      at Socket.<anonymous> (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:129:22)
      at Socket.emit (events.js:311:20)
      at addChunk (_stream_readable.js:294:12)
      at readableAddChunk (_stream_readable.js:275:11)
      at Socket.Readable.push (_stream_readable.js:209:10)
      at TCP.onStreamRead (internal/stream_base_commons.js:186:23) {
    name: 'error',
    length: 173,
    severity: 'ERROR',
    code: '23505',
    detail: 'Key (id)=(1) already exists.',
    hint: undefined,
    position: undefined,
    internalPosition: undefined,
    internalQuery: undefined,
    where: undefined,
    schema: 'public',
    table: 'Users',
    column: undefined,
    dataType: undefined,
    constraint: 'Users_pkey',
    file: 'nbtinsert.c',
    line: '432',
    routine: '_bt_check_unique',
    sql: 'INSERT INTO "Users" ("id","name","createdAt","updatedAt") VALUES ($1,$2,$3,$4) RETURNING "id","name","createdAt","updatedAt";',
    parameters: [
      1,
      'a',
      '2020-05-23 05:53:06.183 +00:00',
      '2020-05-23 05:53:06.183 +00:00'
    ]
  },
  original: error: duplicate key value violates unique constraint "Users_pkey"
      at Connection.parseE (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:614:13)
      at Connection.parseMessage (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:413:19)
      at Socket.<anonymous> (/var/projects/oss/sequelize/node_modules/pg/lib/connection.js:129:22)
      at Socket.emit (events.js:311:20)
      at addChunk (_stream_readable.js:294:12)
      at readableAddChunk (_stream_readable.js:275:11)
      at Socket.Readable.push (_stream_readable.js:209:10)
      at TCP.onStreamRead (internal/stream_base_commons.js:186:23) {
    name: 'error',
    length: 173,
    severity: 'ERROR',
    code: '23505',
    detail: 'Key (id)=(1) already exists.',
    hint: undefined,
    position: undefined,
    internalPosition: undefined,
    internalQuery: undefined,
    where: undefined,
    schema: 'public',
    table: 'Users',
    column: undefined,
    dataType: undefined,
    constraint: 'Users_pkey',
    file: 'nbtinsert.c',
    line: '432',
    routine: '_bt_check_unique',
    sql: 'INSERT INTO "Users" ("id","name","createdAt","updatedAt") VALUES ($1,$2,$3,$4) RETURNING "id","name","createdAt","updatedAt";',
    parameters: [
      1,
      'a',
      '2020-05-23 05:53:06.183 +00:00',
      '2020-05-23 05:53:06.183 +00:00'
    ]
  },
  sql: 'INSERT INTO "Users" ("id","name","createdAt","updatedAt") VALUES ($1,$2,$3,$4) RETURNING "id","name","createdAt","updatedAt";'
}

@jedwards1211
Copy link
Contributor Author

jedwards1211 commented May 23, 2020

@sushantdhiman what version of node are you using?

I'm kind of confused what you mean because when I tested findOrCreate at least I did get a good stack trace for a unique constraint error.

On Node 12.16.2 I ran the following in a test and the stack trace is pretty good (except for saying Function.findOrCreate instead of User.findOrCreate:

      await User.create({
        username: 'gottlieb'
      });

      await User.findOrCreate({
        where: {
          objectId: 'asdasdasd'
        },
        defaults: {
          username: 'gottlieb'
        }
      }).catch(e => console.error(e.stack))

Output

SequelizeUniqueConstraintError: Validation error
    at Query.formatError (/Users/andy/sequelize/lib/dialects/postgres/query.js:338:18)
    at Query.run (/Users/andy/sequelize/lib/dialects/postgres/query.js:128:20)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
    at async /Users/andy/sequelize/lib/sequelize.js:613:16
    at async PostgresQueryInterface.insert (/Users/andy/sequelize/lib/dialects/abstract/query-interface.js:735:21)
    at async model.save (/Users/andy/sequelize/lib/model.js:3944:35)
    at async Function.create (/Users/andy/sequelize/lib/model.js:2195:12)
    at async Function.findOrCreate (/Users/andy/sequelize/lib/model.js:2307:25)
    at async Context.<anonymous> (/Users/andy/sequelize/test/integration/model/create.test.js:89:7)

@jedwards1211
Copy link
Contributor Author

jedwards1211 commented May 23, 2020

Okay weird...for some reason causing the error with User.create doesn't work:

      await User.create({
        username: 'gottlieb'
      });

      await User.create({
        username: 'gottlieb'
      }).catch(e => console.error(e.stack))
SequelizeUniqueConstraintError: Validation error
    at Query.formatError (/Users/andy/sequelize/lib/dialects/postgres/query.js:338:18)
    at Query.run (/Users/andy/sequelize/lib/dialects/postgres/query.js:87:18)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)

I'm confused why though, esp since findOrCreate delegates to create.

@jedwards1211
Copy link
Contributor Author

Okay so I see that for Postgres at least the findOrCreate error is thrown from lib/dialects/postgres/query.js:128:20 and not as a result of catching another error. Whereas create catches an error and throws a wrapper at lib/dialects/postgres/query.js:87:18.

The code that loses the stack trace is

  async run(sql, parameters) {
    ...

    try {
      queryResult = await query;
    } catch (err) {
      // set the client so that it will be reaped if the connection resets while executing
      if (err.code === 'ECONNRESET') {
        connection._invalid = true;
      }

      err.sql = sql;
      err.parameters = parameters;
      throw this.formatError(err);
    }

Maybe catch inside async doesn't preserve the async stack traces in V8?

@jedwards1211
Copy link
Contributor Author

jedwards1211 commented May 23, 2020

Actually I think that since the underlying pg code is using event emitters that's where the stack traces get lost 😕
I still don't fully understand why the async stack traces don't get lost of the query succeeds though.

@sushantdhiman
Copy link
Contributor

Linking nodejs/node#11865 (comment) for reference

@sushantdhiman
Copy link
Contributor

Perhaps related nodejs/node#30822

@jedwards1211
Copy link
Contributor Author

jedwards1211 commented Jun 26, 2020

That's funny, you discovered my comment I made while investigating this issue. I'm surprised it got so many upvotes, I thought I probably misunderstood when async stack traces are supposed to work, but maybe it really is a bug in V8.

@Caerbannog
Copy link

Caerbannog commented Aug 30, 2020

Upgrading to node version 14 fixed some sequelize stacktraces on my project. They now include some function calls that were missing.
Node version 14 is based on V8 version 8, which includes this fix: https://bugs.chromium.org/p/v8/issues/detail?id=10040

@jedwards1211
Copy link
Contributor Author

@sushantdhiman I think we've probably done everything we can in this codebase to ensure better stack traces...do you know of anything else we can improve?

@papb
Copy link
Member

papb commented Aug 31, 2020

Hi @jedwards1211, I can't think of anything from the top of my head but if I do I will let you know. Again, thank you so much for the help you provided! That was great.

By the way, Sushant is no longer maintaining Sequelize, I am trying to take care of things but have been really busy these days...

@sushantdhiman
Copy link
Contributor

Yes, this issue can be closed @jedwards1211

@papb papb closed this as completed Aug 31, 2020
@jedwards1211
Copy link
Contributor Author

I see, yeah I don't blame either one of you.
Want me to automate the require -> import conversion at some point?

@papb
Copy link
Member

papb commented Aug 31, 2020

@jedwards1211 I don't even know what is the state of the source code right now to be honest 😅 I see some files were converted to .ts, perhaps you could convert everything else to TS converting require to import? That would be cool!!

@github-actions
Copy link
Contributor

🎉 This issue has been resolved in version 6.10.0 🎉

The release is available on:

Your semantic-release bot 📦🚀

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
released type: refactor For issues and PRs. Things that improve the code readability, maintainability, testability, etc.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants