Bug: Logging custom objects causes BSONError - console.log works fine

[keystef]

Logging objects returned by a gRPC call results in an error (see additional context below) when the same objects can be printed without any problems using console.log.

The Objects are obtained like this:

const objects: MyCustomObject[] = await getMyCustomObjects(getMyCustomObjectsRequest);
console.log(`List objects (console)`, objects);
logger.info(`List objects (logger)`, objects);

The console.log output is as follows:

List objects (console) [
  {
    _id: new ObjectId("6527b62b25dd80f72d955468"),
    context: { requestId: 'OKL2WnG9OA==' },
    namespace: 'local',
    ownerId: 'ownerId',
    ownerType: 'ownerType',
    targetId: 'targetId',
    targetType: 'type',
    application: 'UNKNOWN',
    objectId: '6527b62b25dd80f72d955468'
  },...
]

There is no output for the logger at all but I get a stack trace in Postman, which I use to send the gRPC request.

I know the stack trace says it's a node issue but if it was I think using console.log should result in the same error.

Expected behavior The objects should be printed the same way console.log prints them.

Additional context

Error [ERR_INTERNAL_ASSERTION]: BSONError: Cannot create Buffer from undefined at Object.toLocalBufferType (/workspace/node_modules/.pnpm/[email protected]/node_modules/bson/lib/bson.cjs:136:15) at Object.toHex (/workspace/node_modules/.pnpm/[email protected]/node_modules/bson/lib/bson.cjs:163:32) at ObjectId.toHexString (/workspace/node_modules/.pnpm/[email protected]/node_modules/bson/lib/bson.cjs:2054:37) at ObjectId.inspect (/workspace/node_modules/.pnpm/[email protected]/node_modules/bson/lib/bson.cjs:2165:38) at [nodejs.util.inspect.custom] (/workspace/node_modules/.pnpm/[email protected]/node_modules/bson/lib/bson.cjs:2162:21) at formatValue (node:internal/util/inspect:806:19) at formatProperty (node:internal/util/inspect:1920:11) at formatRaw (node:internal/util/inspect:1055:9) at formatValue (node:internal/util/inspect:841:10) at formatProperty (node:internal/util/inspect:1920:11) This is caused by either a bug in Node.js or incorrect usage of Node.js internals. Please open an issue with this stack trace at https://github.com/nodejs/node/issues at new NodeError (node:internal/errors:399:5) at Function.fail (node:internal/assert:20:9) at handleMaxCallStackSize (node:internal/util/inspect:1550:10) at formatRaw (node:internal/util/inspect:1063:12) at formatValue (node:internal/util/inspect:841:10) at formatProperty (node:internal/util/inspect:1920:11) at formatArray (node:internal/util/inspect:1744:32) at formatRaw (node:internal/util/inspect:1051:14) at formatValue (node:internal/util/inspect:841:10) at inspect (node:internal/util/inspect:365:10) This is caused by either a bug in Node.js or incorrect usage of Node.js internals. Please open an issue with this stack trace at https://github.com/nodejs/node/issues

Node.js Version v18.14.0

OS incl. Version Ubuntu 22.04 but application is running inside docker container using node:18.14.0-alpine image

[gopinaath]

I got the same error while building a typescript application. Node:18:14:2, TSC: 5.3.2. MacOS

[jandobrx]

Same issue here using a custom logger this would be nice to fix!

[terehov]

Is it possible, that you have some circular dependencies somewhere? So basically, in the file where you create the root logger to the file where you try to create or consume a sub logger? Have you tried importing tslog instanciating the logger in the same file, where you replaced that logger with console.log? Because effectively it’s exactly what you did by placing console.log inside, since you instanciate it right there without importing a sub logger. We once ran into a similar problem with tRPC and assumed tslog was the problem, it turned out to be a circular dependency and a Node problem indeed. If that’s not the case, can you provide me with a repo, that boils down the problem for reproduction? Thx

[keystef]

I can't share the full code but I'm not really doing any import magic.

This is my logging config:

import { Logger, ILogObj, ISettingsParam } from 'tslog';

const prettyLogConfig: ISettingsParam<ILogObj> = {...};
const structuredLogConfig: ISettingsParam<ILogObj> = {...};

const formattedLogging: boolean = ['0', 'off', 'false', 'no'].includes(
  String(process.env?.STRUCTURED_LOGS).toLowerCase()
);
const logger: Logger<ILogObj> = new Logger(
  formattedLogging ? prettyLogConfig : structuredLogConfig
);

export { logger };

Then I use it like this:

import { logger } from './logging.js';
...

const objects: MyCustomObject[] = await getMyCustomObjects(getMyCustomObjectsRequest);
console.log(`List objects (console)`, objects);
logger.info(`List objects (logger)`, objects);