[SER-279] Error Improvements by mountHouli · Pull Request #90 · amida-tech/amida-auth-microservice

mountHouli · 2019-04-05T21:19:46Z

Related JIRA tickets:

https://jira.amida.com/browse/SER-279 (read it all, please!)

What's this PR do?

Read the comments in APIError.js!

Implements the 10 features in the Jira ticket.
Updates winston to ^3.2.1 and winston-json-formatter to ^0.10.0 to get great new logging bug fixes and formatting features (see [SER-281] Log Errors winston-json-formatter#5).
Logs "operational errors" at the warn level and "programmer errors" at the error level.
Converts the existing calls to new APIError() to the new signature.

How should this be manually tested?

NODE_ENV=development always

Test 1: Attempt Login With Bad Username

(Related to features 3, 5, 7, and 10)

For each case below, make this request:

POST to api/v2/auth/login with invalid username

{
  "username": "something_invalid",
  "password": "dont care"
}

Test 1.A: Set `ALWAYS_INCLUDE_ERROR_STACKS=false`

HTTP response body:

{
    "code": "INCORRECT_USERNAME_OR_PASSWORD",
    "status": "ERROR",
    "message": "Incorrect username or password"
}

Logged to stdout:

2019-04-23T00:04:44.547Z warn Incorrect username or password  
{
  "code": "INCORRECT_USERNAME_OR_PASSWORD",
  "status": 401,
  "options": {},
  "isOperational": true,
  "isPublic": true
}

Test 1.B: Set `ALWAYS_INCLUDE_ERROR_STACKS=true`

HTTP response body:

{
    "code": "INCORRECT_USERNAME_OR_PASSWORD",
    "status": "ERROR",
    "message": "Incorrect username or password",
    "stack": "Error: Incorrect username or password\n    at /Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/src/controllers/auth.controller.js:49:17\n    at tryCatcher (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/util.js:16:23)\n    at Promise._settlePromiseFromHandler (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:512:31)\n    at Promise._settlePromise (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:569:18)\n    at Promise._settlePromise0 (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:614:10)\n    at Promise._settlePromises (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:694:18)\n    at _drainQueueStep (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:138:12)\n    at _drainQueue (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:131:9)\n    at Async._drainQueues (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:147:5)\n    at Immediate.Async.drainQueues (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:17:14)\n    at runCallback (timers.js:810:20)\n    at tryOnImmediate (timers.js:768:5)\n    at processImmediate [as _immediateCallback] (timers.js:745:5)"
}

Logged to stdout:

2019-04-23T00:40:33.842Z warn Incorrect username or password 
Error: Incorrect username or password
    at /Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/src/controllers/auth.controller.js:49:17
    at tryCatcher (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/util.js:16:23)
    at Promise._settlePromiseFromHandler (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:512:31)
    at Promise._settlePromise (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:569:18)
    at Promise._settlePromise0 (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:614:10)
    at Promise._settlePromises (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/promise.js:694:18)
    at _drainQueueStep (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:138:12)
    at _drainQueue (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:131:9)
    at Async._drainQueues (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:147:5)
    at Immediate.Async.drainQueues (/Users/houli/docs/gitrepos/amida-tech/amida-auth-microservice/node_modules/sequelize/node_modules/bluebird/js/release/async.js:17:14)
    at runCallback (timers.js:810:20)
    at tryOnImmediate (timers.js:768:5)
    at processImmediate [as _immediateCallback] (timers.js:745:5) 
{
  "code": "INCORRECT_USERNAME_OR_PASSWORD",
  "status": 401,
  "options": {},
  "isOperational": true,
  "isPublic": true
}

Test 2: Create User That Already Exists

(Related to features 1, 2, 7, 8)

Login with a user that has sufficient scope to create other users (an "admin" or "programAdmin"). Use the JWT in your authorization header for the request below.

For each case below, make this request:

POST to api/v2/user with a user that already exits

Body:

{
    "username": "some_user_that_already_exists_in_the_db",
    "email": "some_user_that_already_exists_in_the_db",
    "password": "dont care",
    "scopes": ["clinician"]
}

Test 2.A: When `LOG_LEVEL=info`

HTTP response body:

{
    "code": "GENERIC_ERROR",
    "status": "ERROR",
    "message": "Sequelize Validation Error"
}

Logged to stdout:

2019-04-23T00:12:24.835Z warn Sequelize Validation Error  
{
  "code": "GENERIC_ERROR",
  "status": 409,
  "options": {
    "isOperational": true
  },
  "isOperational": true,
  "isPublic": true
}

Test 2.B: When `LOG_LEVEL=debug`

HTTP response body:

{
    "code": "GENERIC_ERROR",
    "status": "ERROR",
    "message": "Sequelize Validation Error: Validation error: username must be unique"
}

Logged to stdout:

2019-04-23T00:09:37.364Z warn Sequelize Validation Error: Validation error: username must be unique  
{
  "code": "GENERIC_ERROR",
  "status": 409,
  "options": {
    "isOperational": true
  },
  "isOperational": true,
  "isPublic": true,
  "cause": {
    "name": "SequelizeUniqueConstraintError",
    "errors": [
      {
        "message": "username must be unique",
        "type": "unique violation",
        "path": "username",
        "value": "aaron+errtest02@amida.com",
        "origin": "DB",
        "instance": {
          "uuid": "2fa94e85-558d-4d91-97d8-31e544a715c5",
          "scopes": [
            ""
          ],
          "id": null,
          "username": "aaron+errtest02@amida.com",
          "email": "aaron+errtest02@amida.com",
          "password": "ae12f9d5a6bc41182a12acf13943ad21a0fbe8864be474cd9ed108cfbd491aa80c4924aaeb46b0c86d8534ea659441707d6d398d0cee6666c6d94ca65908ab2b82d00cc5487be61fe5be3af30597ae13a9606fe761db28dfadea55bb40214deddeae4f3dd4d39c261a22b607dbfb8135d5b456534755b623280114af1c3d15fe",
          "updatedAt": "2019-04-23T00:09:36.917Z",
          "createdAt": "2019-04-23T00:09:36.917Z",
          "salt": "0c549edf-5704-46cb-af6e-fed9eab3b90e"
        },
        "validatorKey": "not_unique",
        "validatorName": null,
        "validatorArgs": []
      }
    ],
    "fields": {
      "username": "aaron+errtest02@amida.com"
    },
    "parent": {
      "name": "error",
      "length": 226,
      "severity": "ERROR",
      "code": "23505",
      "detail": "Key (username)=(aaron+errtest02@amida.com) already exists.",
      "schema": "public",
      "table": "Users",
      "constraint": "Users_username_key",
      "file": "nbtinsert.c",
      "line": "434",
      "routine": "_bt_check_unique",
      "sql": "INSERT INTO \"Users\" (\"uuid\",\"id\",\"username\",\"email\",\"password\",\"salt\",\"scopes\",\"createdAt\",\"updatedAt\") VALUES ('2fa94e85-558d-4d91-97d8-31e544a715c5',DEFAULT,'aaron+errtest02@amida.com','aaron+errtest02@amida.com','ae12f9d5a6bc41182a12acf13943ad21a0fbe8864be474cd9ed108cfbd491aa80c4924aaeb46b0c86d8534ea659441707d6d398d0cee6666c6d94ca65908ab2b82d00cc5487be61fe5be3af30597ae13a9606fe761db28dfadea55bb40214deddeae4f3dd4d39c261a22b607dbfb8135d5b456534755b623280114af1c3d15fe','0c549edf-5704-46cb-af6e-fed9eab3b90e',ARRAY['']::VARCHAR(255)[],'2019-04-23 00:09:36.917 +00:00','2019-04-23 00:09:36.917 +00:00') RETURNING *;"
    },
    "original": {
      "name": "error",
      "length": 226,
      "severity": "ERROR",
      "code": "23505",
      "detail": "Key (username)=(aaron+errtest02@amida.com) already exists.",
      "schema": "public",
      "table": "Users",
      "constraint": "Users_username_key",
      "file": "nbtinsert.c",
      "line": "434",
      "routine": "_bt_check_unique",
      "sql": "INSERT INTO \"Users\" (\"uuid\",\"id\",\"username\",\"email\",\"password\",\"salt\",\"scopes\",\"createdAt\",\"updatedAt\") VALUES ('2fa94e85-558d-4d91-97d8-31e544a715c5',DEFAULT,'aaron+errtest02@amida.com','aaron+errtest02@amida.com','ae12f9d5a6bc41182a12acf13943ad21a0fbe8864be474cd9ed108cfbd491aa80c4924aaeb46b0c86d8534ea659441707d6d398d0cee6666c6d94ca65908ab2b82d00cc5487be61fe5be3af30597ae13a9606fe761db28dfadea55bb40214deddeae4f3dd4d39c261a22b607dbfb8135d5b456534755b623280114af1c3d15fe','0c549edf-5704-46cb-af6e-fed9eab3b90e',ARRAY['']::VARCHAR(255)[],'2019-04-23 00:09:36.917 +00:00','2019-04-23 00:09:36.917 +00:00') RETURNING *;"
    },
    "sql": "INSERT INTO \"Users\" (\"uuid\",\"id\",\"username\",\"email\",\"password\",\"salt\",\"scopes\",\"createdAt\",\"updatedAt\") VALUES ('2fa94e85-558d-4d91-97d8-31e544a715c5',DEFAULT,'aaron+errtest02@amida.com','aaron+errtest02@amida.com','ae12f9d5a6bc41182a12acf13943ad21a0fbe8864be474cd9ed108cfbd491aa80c4924aaeb46b0c86d8534ea659441707d6d398d0cee6666c6d94ca65908ab2b82d00cc5487be61fe5be3af30597ae13a9606fe761db28dfadea55bb40214deddeae4f3dd4d39c261a22b607dbfb8135d5b456534755b623280114af1c3d15fe','0c549edf-5704-46cb-af6e-fed9eab3b90e',ARRAY['']::VARCHAR(255)[],'2019-04-23 00:09:36.917 +00:00','2019-04-23 00:09:36.917 +00:00') RETURNING *;"
  }
}

Test 3: Call endpoint that doesn't exist:

(Related to feature 7)

Make a request to an endpoint that does not exist.

HTTP response body:

{
    "code": "UNKNOWN_ERROR",
    "status": "ERROR",
    "message": "Not Found"
}

Logged to stdout:

2019-04-23T00:32:32.772Z warn API not found  
{
  "code": "UNKNOWN_API",
  "status": 404,
  "options": {
    "isPublic": false
  },
  "isOperational": true,
  "isPublic": false
}

…ston-json-formatter

…cludeStack handling

…error level.

rmharrison · 2019-04-22T17:47:40Z

@mountHouli : Now that we're using the winston-json-formatter import, is this good to re-review (looks fine on a skim) and merge?

orndorffgrant

Looks really good! Just a couple small things. Also - should this (class and express middleware) be separated into its own package? We could call it amida-express-api-error and use it across all the microservices

orndorffgrant · 2019-04-24T14:47:38Z

+     * @example if (err) { new APIError(err, 'Create user failed. User already exists.', 'CREATE_USER_FAILED', 409, { isPublic: false }) }
+     */
+    /* eslint-enable max-len */
+    constructor(arg1, arg2, arg3, arg4, arg5) {


I hear this is the normal way of getting around javascript's lack of constructor/function overloading.

Personally, I would prefer a constructor that looks like this:

constructor({ causalError, message, code, status, options }) { ... }

and helper functions that would be used like this

APIError.fromCausalError(err, 'msg', 'CODE', 400) APIError.new('msg', 'CODE', 400)

which call new APIError( ... ) appropriately

This has the benefit of being easier to type check with something like Typescript or Flow because each function has exactly one type signature.

Valid view, but not including change here.
Keeping open for reference when creating APIError lib.

Agreed, the typeof is canonical javascript, but is cumbersome.
My suspicion is the developer ergonomics of function overloading (same function; different type signatures) outweighs the cumbersome canonical implementation in javascript.

Thanks for the feedback. Will revisit when pulling the code out into a lib.

@orndorffgrant

- Fixed issues flagged by @orndorffgrant (thanks for the detailed/careful review) - Minor CHANGELOG style fix * Unpacked knapsack of reference to [SER-279] _in CHANGELOG_, because JIRA issues aren't public to non-Amida users. * Amida users will still be able to see SER-279 reference for PR and link to commits.

rmharrison

Addressed @orndorffgrant comments

I hate that I cannot use APIError without new (e.g. new APIError)
I'm assuming you ( @mountHouli ) spent many hours on this to no avail. 😢

rmharrison · 2019-04-30T03:25:47Z

+     * @example if (err) { new APIError(err, 'Create user failed. User already exists.', 'CREATE_USER_FAILED', 409, { isPublic: false }) }
+     */
+    /* eslint-enable max-len */
+    constructor(arg1, arg2, arg3, arg4, arg5) {


Valid view, but not including change here.
Keeping open for reference when creating APIError lib.

Agreed, the typeof is canonical javascript, but is cumbersome.
My suspicion is the developer ergonomics of function overloading (same function; different type signatures) outweighs the cumbersome canonical implementation in javascript.

rmharrison · 2019-04-30T03:47:57Z

+// Read https://www.joyent.com/node-js/production/design/errors to understand the difference between
+// "programmer errors" (i.e. bugs) and "operational errors" (i.e. not actual bugs).
+// The APIError class assumes that if it was instantiated without a causal error, then it is being
+// used to define an "operational error", and there is no actual "programmer error"/bug.


FFR: The definition of "greater than" was confusing. Had to lookup

winston.config.npm.levels { error: 0, warn: 1, info: 2, http: 3, verbose: 4, debug: 5, silly: 6 }

to understand the direction of greater, i.e. greater ==> more verbose.

Mmm. Per our discussion I actually had it the other way at first, but I kept getting confused because the more verbose levels correspond to higher integers.

Concerns resolved

mountHouli · 2019-04-30T14:07:56Z

I did not at all attempt to make it usable without new. That would be nice. However, I suspect the new is required to get the call stack to come out correctly, without doing slightly more complicated things. I bet https://v8.dev/docs/stack-trace-api might have something relevant in this regard (I haven't read it).

mountHouli requested review from B3rry and rmharrison April 5, 2019 21:24

mountHouli changed the title ~~[SER-279] Entire implementation.~~ [SER-279] Error Improvements Apr 5, 2019

mountHouli force-pushed the feature/SER-279-error-improvements branch 2 times, most recently from e64a270 to ab9340f Compare April 8, 2019 22:23

[SER-279] Entire implementation.

6c46b53

mountHouli force-pushed the feature/SER-279-error-improvements branch from ab9340f to 6c46b53 Compare April 9, 2019 22:12

rmharrison added the hold label Apr 9, 2019

rmharrison reviewed Apr 9, 2019

View reviewed changes

Comment thread src/helpers/logLevelGte.js Outdated

mountHouli force-pushed the feature/SER-279-error-improvements branch from 4b048ea to f7337fa Compare April 19, 2019 14:03

[SER-279] remove local logLevelGte implementation; import it from win…

04edc55

…ston-json-formatter

mountHouli force-pushed the feature/SER-279-error-improvements branch from f7337fa to 04edc55 Compare April 19, 2019 14:09

Aaron Houlihan added 2 commits April 19, 2019 10:10

[SER-279] Improve isOperational, isPublic, includeCausalError, and in…

841730f

…cludeStack handling

[SER-279] log operational errors at warn level, programmer errors at …

23a7a57

…error level.

rmharrison self-requested a review April 22, 2019 18:00

Aaron Houlihan added 3 commits April 22, 2019 18:04

[SER-279] Add JSDoc to APIError, PR #90

2b63485

[SER-279] Bug fix: isPublic handling in express middleware. PR #90

314cbae

[SER-279] README and CHANGELOG updates. PR #90

0c663bc

mountHouli removed the hold label Apr 23, 2019

mountHouli requested review from orndorffgrant and puckybreg April 23, 2019 00:47

orndorffgrant previously requested changes Apr 24, 2019

View reviewed changes

rmharrison approved these changes Apr 30, 2019

View reviewed changes

rmharrison merged commit 3deab1b into develop Apr 30, 2019

rmharrison deleted the feature/SER-279-error-improvements branch April 30, 2019 05:03

rmharrison mentioned this pull request Apr 30, 2019

Feature/ser 280 require email confirmation #91

Merged

Conversation

mountHouli commented Apr 5, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Related JIRA tickets:

What's this PR do?

How should this be manually tested?

Test 1: Attempt Login With Bad Username

For each case below, make this request:

Test 1.A: Set ALWAYS_INCLUDE_ERROR_STACKS=false

Test 1.B: Set ALWAYS_INCLUDE_ERROR_STACKS=true

Test 2: Create User That Already Exists

For each case below, make this request:

Test 2.A: When LOG_LEVEL=info

Test 2.B: When LOG_LEVEL=debug

Test 3: Call endpoint that doesn't exist:

Uh oh!

Uh oh!

rmharrison commented Apr 22, 2019

Uh oh!

orndorffgrant left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

orndorffgrant Apr 24, 2019

Choose a reason for hiding this comment

Uh oh!

rmharrison Apr 30, 2019

Choose a reason for hiding this comment

Uh oh!

mountHouli Apr 30, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

rmharrison left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

rmharrison Apr 30, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

rmharrison Apr 30, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mountHouli Apr 30, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

mountHouli commented Apr 30, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

mountHouli commented Apr 5, 2019 •

edited

Loading

Test 1.A: Set `ALWAYS_INCLUDE_ERROR_STACKS=false`

Test 1.B: Set `ALWAYS_INCLUDE_ERROR_STACKS=true`

Test 2.A: When `LOG_LEVEL=info`

Test 2.B: When `LOG_LEVEL=debug`

rmharrison Apr 30, 2019 •

edited

Loading