fix(collector): improved capturing object logging via bunyan (#664)

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

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": "[email protected]",
+  "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"
+}

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":"[email protected]","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) {

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