Logger fails when logging circular JSON structures

serhii-dolia commented 4 years ago

Description

We are using the cf-nodejs-logging-support 5.3.2, but I have checked that the latest version has the same problem.

On our production on CF we are having a problem: when we do a request to a particular server and it returns 500 response, the logger is trying to print the error message and it contains the circular JSON (the server response), and the logger crushes our server with this error:

   2020-03-30T09:35:59.66+0200 [APP/PROC/WEB/0] OUT {"error":{},"level":"error","message":"uncaughtException: Converting circular structure to JSON\n    --> starting at
 object with constructor 'ClientRequest'\n    |     property 'socket' -> object with constructor 'TLSSocket'\n  
  --- property '_httpMessage' closes the circle\nTypeError: Converting circular structure to JSON\n    --> 
starting at object with constructor 'ClientRequest'\n    |     property 'socket' -> object with constructor 
'TLSSocket'\n    --- property '_httpMessage' closes the circle\n    at JSON.stringify (<anonymous>)\n    at 
logMessage (/home/vcap/app/node_modules/cf-nodejs-logging-support/cf-nodejs-logging-support-
core/log-core.js:377:53)\n    at /home/vcap/app/node_modules/cf-nodejs-logging-support/cf-nodejs-
logging-support-core/log-core.js:29:24\n    at CloudFormationBasedLogger.log 
(/home/vcap/app/src/driven-port-implementation/logger/cf-nodejs-logging-support-logger.ts
:57:7)\n    at CloudFormationBasedLogger.error (/home/vcap/app/src/driven-port-
implementation/logger/cf-nodejs-logging-support-logger.ts:37:10)\n    at JwtCheckingSequence.handle 
(/home/vcap/app/src/drivers/loopback-webapp/jwt-checking-sequence.ts:71:14)\n    at 
processTicksAndRejections (internal/process/task_queues.js:94:5)\n    at HttpHandler._handleRequest 
(/home/vcap/app/node_modules/@loopback/rest/src/http-handler.ts:78:5)","stack":"TypeError: Converting
 circular structure to JSON\n    --> starting at object with constructor 'ClientRequest'\n    |     property 
'socket' -> object with constructor 'TLSSocket'\n    --- property '_httpMessage' closes the circle\n    at
 JSON.stringify (<anonymous>)\n    at logMessage (/home/vcap/app/node_modules/cf-nodejs-logging-
support/cf-nodejs-logging-support-core/log-core.js:377:53)\n    at /home/vcap/app/node_modules/cf-
nodejs-logging-support/cf-nodejs-logging-support-core/log-core.js:29:24\n    at 
CloudFormationBasedLogger.log (/home/vcap/app/src/driven-port-implementation/logger/cf-nodejs-
logging-support-logger.ts:57:7)\n    at CloudFormationBasedLogger.error (/home/vcap/app/src/driven-
port-implementation/logger/cf-nodejs-logging-support-logger.ts:37:10)\n    at 
JwtCheckingSequence.handle (/home/vcap/app/src/drivers/loopback-webapp/jwt-checking-
sequence.ts:71:14)\n    at processTicksAndRejections (internal/process/task_queues.js:94:5)\n    at 
HttpHandler._handleRequest (/home/vcap/app/node_modules/@loopback/rest/src/http-handler.ts:78:5)"

Steps to reproduce:

Download repo and run this code in the root folder:

const logMessage = require("./cf-nodejs-logging-support-core/log-core").logMessage;

const a = { name: 'Text1' };
const b = { name: 'Text2', sibling: a };
a.sibling = b;

logMessage("info", a);

You will get an error:

/Users/I521237/programming/cf-nodejs-logging-support/cf-nodejs-logging-support-core/log-core.js:523
            value = JSON.stringify(value);
                         ^

TypeError: Converting circular structure to JSON
    --> starting at object with constructor 'Object'
    |     property 'sibling' -> object with constructor 'Object'
    --- property 'sibling' closes the circle
    at JSON.stringify (<anonymous>)
    at writeCustomFields (/Users/I521237/programming/cf-nodejs-logging-support/cf-nodejs-logging-support-core/log-core.js:523:26)
    at logMessage (/Users/I521237/programming/cf-nodejs-logging-support/cf-nodejs-logging-support-core/log-core.js:407:5)
    at Object.<anonymous> (/Users/I521237/programming/cf-nodejs-logging-support/cf-nodejs-logging-support-core/x.js:7:1)
    at Module._compile (internal/modules/cjs/loader.js:959:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:995:10)
    at Module.load (internal/modules/cjs/loader.js:815:32)
    at Function.Module._load (internal/modules/cjs/loader.js:727:14)
    at Function.Module.runMain (internal/modules/cjs/loader.js:1047:10)
    at internal/main/run_main_module.js:17:11

How to fix it

In order to fix it, we can use this kind of library: https://www.npmjs.com/package/json-stringify-safe instead of just using JSON.stringify or just try/catch the operation of stringifying.

Let me know if you want me to write the PR or you can do it yourself.

IF you don't think this bug should be fixed, then let me know how we can deal with the problem of this unhandled error that crushes our serever.

serhii-dolia commented 4 years ago

The issue was trying to log the axios-generated error fully, so I could fix it in my code just by logging only part of this JSON. But still the problem in general remains.

christiand93 commented 4 years ago

Thank you for the report. We have fixed this problem in version 6.1.3.

SAP / cf-nodejs-logging-support