From d0f16d136eaa5695fdf4128314a9c34a03e2a50b Mon Sep 17 00:00:00 2001 From: Katharina Irrgang Date: Wed, 7 Dec 2022 10:24:56 +0100 Subject: [PATCH] fix(collector): improved capturing object logging via bunyan (#664) --- .../test/tracing/logger/bunyan/app.js | 7 ++++ .../logger/bunyan/assets/large_obj.json | 37 ++++++++++++++++++ .../test/tracing/logger/bunyan/test.js | 23 +++++++---- .../tracing/instrumentation/loggers/bunyan.js | 39 ++++++++++++++++++- 4 files changed, 96 insertions(+), 10 deletions(-) create mode 100644 packages/collector/test/tracing/logger/bunyan/assets/large_obj.json diff --git a/packages/collector/test/tracing/logger/bunyan/app.js b/packages/collector/test/tracing/logger/bunyan/app.js index 7c7b0ad369..c75414d215 100644 --- a/packages/collector/test/tracing/logger/bunyan/app.js +++ b/packages/collector/test/tracing/logger/bunyan/app.js @@ -23,7 +23,9 @@ const request = require('request-promise'); const bodyParser = require('body-parser'); const express = require('express'); const morgan = require('morgan'); +const fs = require('fs'); +const path = require('path'); const bunyan = require('bunyan'); const logger = bunyan.createLogger({ name: 'test-logger' }); @@ -75,6 +77,11 @@ app.get('/error-random-object-only', (req, res) => { finish(res); }); +app.get('/error-large-object-only', (req, res) => { + logger.error(JSON.parse(fs.readFileSync(path.join(__dirname, 'assets', 'large_obj.json'), 'utf8'))); + finish(res); +}); + app.get('/error-object-and-string', (req, res) => { logger.error(new Error('This is an error.'), 'Error message - should be traced.'); finish(res); diff --git a/packages/collector/test/tracing/logger/bunyan/assets/large_obj.json b/packages/collector/test/tracing/logger/bunyan/assets/large_obj.json new file mode 100644 index 0000000000..67027c1fb4 --- /dev/null +++ b/packages/collector/test/tracing/logger/bunyan/assets/large_obj.json @@ -0,0 +1,37 @@ +{ + "_id": "638dea148cff492d47e792ea", + "index": 0, + "guid": "01b61bfa-fe4c-4d75-9224-389c4c04de10", + "isActive": false, + "balance": "$1,919.18", + "picture": "http://placehold.it/32x32", + "age": 37, + "eyeColor": "blue", + "name": "Manning Brady", + "gender": "male", + "company": "ZYTRAC", + "email": "manningbrady@zytrac.com", + "phone": "+1 (957) 538-2183", + "address": "146 Bushwick Court, Gilgo, New York, 2992", + "about": "Ullamco cillum reprehenderit eu proident veniam laboris tempor voluptate. Officia deserunt velit incididunt consequat labore et ut labore irure in duis. Dolor pariatur sit elit commodo ut.\r\n", + "registered": "2021-11-24T10:27:31 -01:00", + "latitude": 74.90663, + "longitude": 0.29352, + "tags": ["velit", "irure", "proident", "laborum", "consectetur", "ipsum", "dolore"], + "friends": [ + { + "id": 0, + "name": "Rush Snow" + }, + { + "id": 1, + "name": "Norma Stout" + }, + { + "id": 2, + "name": "Tameka Wolfe" + } + ], + "greeting": "Hello, Manning Brady! You have 8 unread messages.", + "favoriteFruit": "strawberry" +} diff --git a/packages/collector/test/tracing/logger/bunyan/test.js b/packages/collector/test/tracing/logger/bunyan/test.js index 7cd6b3fde0..9386949457 100644 --- a/packages/collector/test/tracing/logger/bunyan/test.js +++ b/packages/collector/test/tracing/logger/bunyan/test.js @@ -57,12 +57,15 @@ mochaSuiteFn('tracing/logger/bunyan', function () { it("must capture a nested error object's message", () => runTest('nested-error-object-only', true, 'This is a nested error.')); - it('must not serialize random object', () => + it('must serialize random object', () => runTest('error-random-object-only', true, '{"foo":"[Object]"}')); + + it('must serialize large object', () => runTest( - 'error-random-object-only', + 'error-large-object-only', true, - 'Log call without message. ' + - 'The Bunyan "fields" argument will not be serialized by Instana for performance reasons.' + // eslint-disable-next-line max-len + '{"_id":"638dea148cff492d47e792ea","index":0,"guid":"01b61bfa-fe4c-4d75-9224-389c4c04de10","isActive":false,"balance":"$1,919.18","picture":"http://placehold.it/32x32","age":37,"eyeColor":"blue","name":"Manning Brady","gender":"male","company":"ZYTRAC","email":"manningbrady@zytrac.com","phone":"+1 (957) 538-2183","address":"146 Bushwick Court, Gilgo, New York, 2992","about":"Ullamco cillum reprehenderit eu proident veniam laboris tempor voluptate. Officia deserunt velit incididunt consequat la...', + 500 )); it("must capture an error object's message and an additional string", () => @@ -72,7 +75,7 @@ mochaSuiteFn('tracing/logger/bunyan', function () { runTest('nested-error-object-and-string', true, 'This is a nested error. -- Error message - should be traced.')); it('must trace random object and string', () => - runTest('error-random-object-and-string', true, 'Error message - should be traced.')); + runTest('error-random-object-and-string', true, '{"foo":"[Object]"} - Error message - should be traced.')); it('must trace child logger error', () => runTest('child-error', true, 'Child logger error message - should be traced.')); @@ -124,7 +127,7 @@ mochaSuiteFn('tracing/logger/bunyan', function () { }); }); - function runTest(url, expectErroneous, message) { + function runTest(url, expectErroneous, message, lengthOfMessage) { return appControls.trigger(url).then(() => testUtils.retry(() => agentControls.getSpans().then(spans => { @@ -134,7 +137,7 @@ mochaSuiteFn('tracing/logger/bunyan', function () { span => expect(span.f.h).to.equal('agent-stub-uuid') ]); testUtils.expectAtLeastOneMatching(spans, span => { - checkBunyanSpan(span, entrySpan, expectErroneous, message); + checkBunyanSpan(span, entrySpan, expectErroneous, message, lengthOfMessage); }); testUtils.expectAtLeastOneMatching(spans, span => { checkNextExitSpan(span, entrySpan); @@ -153,7 +156,7 @@ mochaSuiteFn('tracing/logger/bunyan', function () { ); } - function checkBunyanSpan(span, parent, erroneous, message) { + function checkBunyanSpan(span, parent, erroneous, message, lengthOfMessage) { expect(span.t).to.equal(parent.t); expect(span.p).to.equal(parent.s); expect(span.k).to.equal(constants.EXIT); @@ -166,6 +169,10 @@ mochaSuiteFn('tracing/logger/bunyan', function () { expect(span.data).to.exist; expect(span.data.log).to.exist; expect(span.data.log.message).to.equal(message); + + if (lengthOfMessage) { + expect(span.data.log.message.length).to.equal(lengthOfMessage); + } } function checkNextExitSpan(span, parent) { diff --git a/packages/core/src/tracing/instrumentation/loggers/bunyan.js b/packages/core/src/tracing/instrumentation/loggers/bunyan.js index df6fb1c73c..0c1bf65d0c 100644 --- a/packages/core/src/tracing/instrumentation/loggers/bunyan.js +++ b/packages/core/src/tracing/instrumentation/loggers/bunyan.js @@ -54,6 +54,8 @@ function instrumentedLog(ctx, originalLog, originalArgs, markAsError) { span.stack = tracingUtil.getStackTrace(instrumentedLog); const fields = originalArgs[0]; let message = originalArgs[1]; + const maxStrLength = 500; + if (typeof fields === 'string') { message = fields; } else if (fields && typeof fields.message === 'string' && typeof message === 'string') { @@ -73,10 +75,43 @@ function instrumentedLog(ctx, originalLog, originalArgs, markAsError) { message = `${fields.err.message} -- ${message}`; } else if (fields && fields.err && typeof fields.err === 'object' && typeof fields.err.message === 'string') { message = fields.err.message; - } else if (typeof message !== 'string') { + } else if (typeof fields === 'object') { + // CASE: we try our best to serialize logged objects + // we do not want to directly call JSON.stringify because we do not know how big the object is and + // there might be possible circular dependencies in the object. + const maxNoOfKeys = 100; + const obj = {}; + + Object.keys(fields).every((key, index) => { + // CASE: stop iteration if we have enough keys + if (index > maxNoOfKeys) { + return false; + } + + const val = fields[key]; + if (typeof val === 'object') { + obj[key] = '[Object]'; + } else { + obj[key] = val; + } + + return true; + }); + + if (message && typeof message === 'string') { + message = `${JSON.stringify(obj)} - ${message}`; + } else { + message = JSON.stringify(obj); + } + } else { message = - 'Log call without message. The Bunyan "fields" argument will not be serialized by Instana for performance reasons.'; + 'Log call without message. The Bunyan "fields" argument cannot be serialized by Instana because of unknown format.'; + } + + if (message.length > maxStrLength) { + message = `${message.substring(0, maxStrLength - 3)}...`; } + span.data.log = { message };