crystal

crystal copied to clipboard

Description

While trying out bun, I found that the log output did not look very nice. After doing some digging, I found that the main reason was that bun displays a piece of the code from where the error originates whereas node simply prints the message line.

node:

Masked GraphQL error (hash: 'wiy-9FuoG4YyjQDsoOgPm0ivhaQ', id: 'CDPY2NZ8ZL') error: permission denied for table authenticated_only
    at /home/felix/private/labelt/node_modules/pg/lib/client.js:526:17
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async PgExecutor._executeWithClient (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:48:27)
    at async /home/felix/private/labelt/node_modules/@dataplan/pg/dist/adaptors/pg.js:187:36
    at async withPgClient (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/adaptors/pg.js:228:20)
    at async withPgClientFromPgService (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/pgServices.js:114:16)
    at async PgExecutor._execute (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:143:16)
    at async /home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:274:31 {
  path: [ 'authenticatedOnlies', 'edges' ],
  locations: [ { line: 3, column: 5 } ],
  extensions: [Object: null prototype] {}
}

bun:

Masked GraphQL error (hash: 'Yso1vgL5wxudmqqGcOa_Xb7uuDA', id: 'MHXAKDVRWU') 521 |         result = new this._Promise((resolve, reject) => {
522 |           query.callback = (err, res) => (err ? reject(err) : resolve(res))
523 |         }).catch((err) => {
524 |           // replace the stack trace that leads to `TCP.onStreamRead` with one that leads back to the
525 |           // application that created the query
526 |           Error.captureStackTrace(err)
                      ^
GraphQLError: permission denied for table authenticated_only
 path: "authenticatedOnlies,nodes"
      at /workspaces/labelt/node_modules/pg/lib/client.js:526:17
      at processTicksAndRejections (native:1:1)

While things do not look as bad in node as in bun, I would argue that a newline is better to use here as well (and looking better in bun of course does not hurt, even if it's not an officially supported platform).

With these changes, the output now looks like:

node:

Masked GraphQL error (hash: 'wiy-9FuoG4YyjQDsoOgPm0ivhaQ', id: 'N9VLN9QFWA')
error: permission denied for table authenticated_only
    at /home/felix/private/labelt/node_modules/pg/lib/client.js:526:17
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async PgExecutor._executeWithClient (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:48:27)
    at async /home/felix/private/labelt/node_modules/@dataplan/pg/dist/adaptors/pg.js:187:36
    at async withPgClient (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/adaptors/pg.js:228:20)
    at async withPgClientFromPgService (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/pgServices.js:114:16)
    at async PgExecutor._execute (/home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:143:16)
    at async /home/felix/private/labelt/node_modules/@dataplan/pg/dist/executor.js:274:31 {
  path: [ 'authenticatedOnlies', 'edges' ],
  locations: [ { line: 3, column: 5 } ],
  extensions: [Object: null prototype] {}
}

bun:

Masked GraphQL error (hash: 'wiy-9FuoG4YyjQDsoOgPm0ivhaQ', id: '2LJNUKMQUR')
521 |         result = new this._Promise((resolve, reject) => {
522 |           query.callback = (err, res) => (err ? reject(err) : resolve(res))
523 |         }).catch((err) => {
524 |           // replace the stack trace that leads to `TCP.onStreamRead` with one that leads back to the
525 |           // application that created the query
526 |           Error.captureStackTrace(err)
                      ^
GraphQLError: permission denied for table authenticated_only
 path: "authenticatedOnlies,edges"
      at /workspaces/labelt/node_modules/pg/lib/client.js:526:17
      at processTicksAndRejections (native:1:1)

Performance impact

Unknown. The change mirrors what console.error(a,b) did internally, just with a different separator. I'm therefore assuming it to be minimal

Security impact

None

Checklist

• [x] My code matches the project's code style and yarn lint:fix passes.
• [ ] I've added tests for the new feature, and yarn test passes.
• [ ] I have detailed the new feature in the relevant documentation.
• [ ] I have added this feature to 'Pending' in the RELEASE_NOTES.md file (if one exists).
• [ ] If this is a breaking change I've explained why.

🦋 Changeset detected

Latest commit: 61f8bbca5badda5b27872e0ee01a2d4c1372210d

The changes in this PR will be included in the next version bump.

This PR includes changesets to release 5 packages

Name	Type
grafserv	Patch
@grafserv/persisted	Patch
pgl	Patch
postgraphile	Patch
graphile	Patch

Not sure what this means? Click here to learn what changesets are.

Click here if you're a maintainer who wants to add another changeset to this PR

I spoke with @benjie about submitting a similar PR on discord where it was originally declined. This was motivated with:

1. Bun is not a supported platform
2. String(error) is not equivalent to printing the error directly

However, after taking a closer look, I think I have managed a changeset that is able to address these issues:

Bun is not a supported platform

I went back to look at the issue from a node-oriented point of view and believe the newline to be prettier for node as well. The fact that it looks good in bun now too is a bonus.

String(error) is not equivalent to printing the error directly

Agreed. Based on MDN docs and the console standard (specifically section 2.2, 6. 5.), console.error("%O", error) would appear to produce the equivalent, however.

---

On a sidenote: the output of String(error) is quite beautiful - regardless of runtime (bun/node). If it is consistent, I think it could be really nice to use instead of, or in conjunction with, console.error("%O", error).

String(error) translates as (at least the error I've been testing with):

error: permission denied for table authenticated_only
GraphQL HTTP Request:3:5
2 |   authenticatedOnlies {
3 |     edges {
  |     ^
4 |       node {

Looks good @benjie (readthrough only - no actual testing). Thanks for looking at this!

Yeah I tested it locally; it works well (though the output is a little long):

Masked GraphQL error (hash: 'D_lpZ-JKiyJeHeL-ewyTV8UU4gE', id: 'TKNHKATUD9')
You've requested the 'throw' field... which throws!

GraphQL HTTP Request:2:3                                                                       
1 | {                                                                                          
2 |   throw                                                                                    
  |   ^                                                                                        
3 | }                                                                                          
Error: You've requested the 'throw' field... which throws!
    at /home/benjie/Dev/graphile/crystal/postgraphile/postgraphile/graphile.config.ts:308:19
    at /home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:1806:11
    at withFieldArgsForArguments (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/operationPlan-input.ts:514:18)
    at withGlobalLayerPlan (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/lib/withGlobalLayerPlan.ts:24:21)
    at OperationPlan.planField (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:1795:37)
    at OperationPlan.processGroupedFieldSet (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:1173:36)
    at OperationPlan.planSelectionSet (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:1329:10)
    at OperationPlan.planQuery (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:679:10)
    at OperationPlan.planOperation (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:621:16)
    at new OperationPlan (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/engine/OperationPlan.ts:364:10)
    at establishOperationPlan (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/establishOperationPlan.ts:192:21)
    at establishOperationPlanFromEvent (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/prepare.ts:547:32)
    at Middleware.runSync (/home/benjie/Dev/graphile/crystal/utils/graphile-config/src/middleware.ts:90:14)
    at grafastPrepare (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/prepare.ts:590:34) 
    at withGrafastArgs (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/execute.ts:79:35) 
    at executeMiddlewareCallback (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/execute.ts:147:3)
    at Middleware.run (/home/benjie/Dev/graphile/crystal/utils/graphile-config/src/middleware.ts:68:14)
    at execute (/home/benjie/Dev/graphile/crystal/grafast/grafast/src/execute.ts:140:23)
    at /home/benjie/Dev/graphile/crystal/grafast/grafserv/src/middleware/graphql.ts:468:28
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Server.<anonymous> (/home/benjie/Dev/graphile/crystal/grafast/grafserv/src/servers/node/index.ts:113:24) {
  metadata: true,                                                                              
  mol: 42                                                                                      
}  

I guess ideally we'd indent it with something more like:

    console.error(
      "Masked GraphQL error (hash: '%s', id: '%s')\n  GraphQL Error:\n    %s\n\n  Original Error:\n\n    %s",
      hash,
      errorId,
      String(error).replace(/\n/g, '\n    '),
      inspect(error.originalError ?? error, { /* ... */ }).replace(/\n/g, '\n    '),
    );

But I'm not sure it's worth the overhead or complexity.