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

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

Open
keystef opened this issue Oct 12, 2023 · 4 comments
Open
Labels
bug Something isn't working

Comments

@keystef
Copy link

keystef commented Oct 12, 2023

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

@keystef keystef added the bug Something isn't working label Oct 12, 2023
@gopinaath
Copy link

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

@jandobrx
Copy link

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

@terehov
Copy link
Contributor

terehov commented Dec 28, 2023

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
Copy link
Author

keystef commented Jan 2, 2024

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);

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants