Receiving 500 errors instead of 401s

[jasonaowen]

While running locally on main, 401 unauthorized errors are getting turned into 500 internal server errors.

Example error

``` [2024-08-08T21:12:11.734Z] ERROR (659560): secret or public key must be provided source: "src/middleware/errorHandler.ts" statusCode: 500 err: { "type": "UnauthorizedError", "message": "secret or public key must be provided", "stack": UnauthorizedError: secret or public key must be provided at new UnauthorizedError (node_modules/express-jwt/dist/errors/UnauthorizedError.js:22:28) at node_modules/express-jwt/dist/index.js:139:38 at step (node_modules/express-jwt/dist/index.js:33:23) at Object.next (node_modules/express-jwt/dist/index.js:14:53) at fulfilled (node_modules/express-jwt/dist/index.js:5:58) "code": "invalid_token", "status": 401, "name": "UnauthorizedError", "inner": { "type": "JsonWebTokenError", "message": "secret or public key must be provided", "stack": JsonWebTokenError: secret or public key must be provided at node_modules/jsonwebtoken/verify.js:113:19 at getSecret (node_modules/jsonwebtoken/verify.js:97:14) at Object.module.exports [as verify] (node_modules/jsonwebtoken/verify.js:101:10) at node_modules/express-jwt/dist/index.js:133:50 at step (node_modules/express-jwt/dist/index.js:33:23) at Object.next (node_modules/express-jwt/dist/index.js:14:53) at fulfilled (node_modules/express-jwt/dist/index.js:5:58) "name": "JsonWebTokenError" } } ```

Receiving unauthorized requests is a normal operation, particularly in an internet-facing application, so such errors should be communicated appropriately both externally and in our logs.

[slifty]

Just to clarify: We have many tests that ensure that no auth key translates to 401, so I don't think that they're being turned into 500s universally / for the most general case.

I can confirm that, for instance, attempting to create a base field with no auth results in a 401, not a 500:

And likewise when trying to load proposals:

It sounds like this may be a specific situation where an auth token has been provided but is not properly formed. Agreed 500 error is not what we want in that case.

Could you share more about exactly how you were making the call that led to this error, and which endpoint you were calling?

[slifty]

I should add: it will still be useful to understand what led to this error so that we can write a test for it, but I am guessing that the solution itself is going to be to make sure our error handler checks for the jwt implementation of UnauthorizedError when mapping error codes, in addition to what it does now which is check if the error is an instance of our own UnauthorizedError.

[bickelj]

I accidentally reproduced this locally just now.

curl -X 'POST' \
  'http://localhost:3001/proposalVersions' \
  -H 'accept: application/json' \
  -H 'Authorization: Bearer eyJhb...3Y2g' \
  -H 'Content-Type: application/json' \
  -d '{
    "sourceId": 1,
    "proposalId": 100,
"sourceId": 2,
    "fieldValues": [
        {
            "value": "Seattle Yada Housing Alliance",
            "position": 0,
            "applicationFormFieldId": 1
        },
        {
            "value": "Nonprofit Yada",
            "position": 1,
            "applicationFormFieldId": 2
        }
    ],
    "applicationFormId": 1
}'

This was via Swagger which reported an error 500 status code along with this body response:

{
  "name": "UnauthorizedError",
  "message": "jwt expired",
  "details": [
    {
      "code": "invalid_token",
      "status": 401,
      "name": "UnauthorizedError",
      "inner": {
        "name": "TokenExpiredError",
        "message": "jwt expired",
        "expiredAt": "2024-09-19T18:40:11.000Z"
      }
    }
  ]
}

And of course what was printed to the console, corroborating the 500 status on the HTTP level while having an inconsistent status set on the inside:

[2024-09-19T18:41:55.468Z] TRACE (89571):
    source: "/home/user/code/ots/ext/PhilanthropyDataCommons/service/src/middleware/errorHandler.ts"
[2024-09-19T18:41:55.469Z] ERROR (89571): jwt expired
    source: "/home/user/code/ots/ext/PhilanthropyDataCommons/service/src/middleware/errorHandler.ts"
    statusCode: 500
    err: {
      "type": "UnauthorizedError",
      "message": "jwt expired",
      "stack":
          UnauthorizedError: jwt expired
              at new UnauthorizedError (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/errors/UnauthorizedError.js:22:28)
              at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:139:38
              at step (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:33:23)
              at Object.next (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:14:53)
              at fulfilled (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:5:58)
      "code": "invalid_token",
      "status": 401,
      "name": "UnauthorizedError",
      "inner": {
        "type": "TokenExpiredError",
        "message": "jwt expired",
        "stack":
            TokenExpiredError: jwt expired
                at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:190:21
                at getSecret (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:97:14)
                at Object.module.exports [as verify] (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:101:10)
                at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:133:50
                at step (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:33:23)
                at Object.next (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:14:53)
                at fulfilled (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:5:58)
        "name": "TokenExpiredError",
        "expiredAt": "2024-09-19T18:40:11.000Z"
      }
    }

[bickelj]

I added these trace statements to errorHandler.ts to see if I could repeat it, and I did get one of these:

const getHttpStatusCodeForError = (error: unknown): number => {
    if (error instanceof DatabaseError) {
        const errorCode = error.tinyPgError.queryContext.error.code;
        return getHttpStatusCodeForDatabaseErrorCode(errorCode);
    }
    if (error instanceof InternalValidationError) {
        logger.trace('instanceof InternalValidationError')
        return 500;
    }
    if (error instanceof InputValidationError) {
        logger.trace('instanceof InputValidationError')
        return 400;
    }
    if (error instanceof InputConflictError) {
        logger.trace('instanceof InputConflictError')
        return 409;
    }
    if (error instanceof UnauthorizedError) {
        logger.trace('instanceof UnauthorizedError');
        return 401;
    }
    if (error instanceof NotFoundError) {
        logger.trace('instanceof NotFoundError');
        return 404;
    }
    // In the `jwks-rsa` library, when a rate limit is exceeded a string error gets thrown.
    if (
        typeof error === 'string' &&
        error.includes('exceeds maximum tokens per interval')
    ) {
        logger.trace('typeof error === string && error.includes...');
        return 503;
    }
    logger.trace('defaulting to 500');
    return 500;
};

Terminal: [2024-09-19T18:58:35.939Z] TRACE (90686): defaulting to 500

This means none of the instanceofs matched.

[bickelj]

When I change the code around UnauthorizedError back to what it was before e7e681f05df23a2409074207e866763c673badb3, where it was an import from express-jwt and the code looked like this, then I get the expected 401:

    if (error instanceof UnauthorizedError) {
        logger.trace('instanceof UnauthorizedError');
        return error.status;
    }

Terminal shows [2024-09-19T19:23:30.205Z] TRACE (91567): instanceof UnauthorizedError, and the response:

[2024-09-19T19:23:30.205Z] DEBUG (91567): jwt expired
    source: "/home/user/code/ots/ext/PhilanthropyDataCommons/service/src/middleware/errorHandler.ts"
    statusCode: 401
    err: {
      "type": "UnauthorizedError",
      "message": "jwt expired",
      "stack":
          UnauthorizedError: jwt expired
              at new UnauthorizedError (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/errors/UnauthorizedError.js:22:28)
              at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:139:38
              at step (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:33:23)
              at Object.next (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:14:53)
              at fulfilled (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:5:58)
      "code": "invalid_token",
      "status": 401,
      "name": "UnauthorizedError",
      "inner": {
        "type": "TokenExpiredError",
        "message": "jwt expired",
        "stack":
            TokenExpiredError: jwt expired
                at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:190:21
                at getSecret (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:97:14)
                at Object.module.exports [as verify] (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/jsonwebtoken/verify.js:101:10)
                at /home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:133:50
                at step (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:33:23)
                at Object.next (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:14:53)
                at fulfilled (/home/user/code/ots/ext/PhilanthropyDataCommons/service/node_modules/express-jwt/dist/index.js:5:58)
        "name": "TokenExpiredError",
        "expiredAt": "2024-09-19T18:40:11.000Z"
      }
    }

[slifty]

Great! And based on your experimentation it sounds like this aligns with the earlier observation of:

I should add: it will still be useful to understand what led to this error so that we can write a test for it, but I am guessing that the solution itself is going to be to make sure our error handler checks for the jwt implementation of UnauthorizedError when mapping error codes, in addition to what it does now which is check if the error is an instance of our own UnauthorizedError.

I'll make a patch + a test.

[jasonaowen]

The case I reported - secret or public key must be provided - came from trying to use a token from the wrong IdP. That is, log in to an IdP, which satisfies the front-end, but which is different from the IdP the back-end is configured to use.