fix log messages to be memoized and add tests for memoization

Author: wconti27

packages/dd-trace/src/encode/0.4.js

@@ -5,6 +5,7 @@ const { Chunk, MsgpackEncoder } = require('../msgpack')
 const log = require('../log')
 const { isTrue } = require('../util')
 const coalesce = require('koalas')
+const { memoize } = require('../log/utils')
 
 const SOFT_LIMIT = 8 * 1024 * 1024 // 8MB
 
@@ -339,13 +340,22 @@ class AgentEncoder {
   }
 }
 
+const memoizedLogDebug = memoize((key, message) => {
+  log.debug(message)
+  // return something to store in memoize cache
+  return true
+})
+
 function formatSpanEvents (span) {
   for (const spanEvent of span.span_events) {
     if (spanEvent.attributes) {
       for (const [key, value] of Object.entries(spanEvent.attributes)) {
         const newValue = convertSpanEventAttributeValues(key, value)
-        if (newValue !== undefined) spanEvent.attributes[key] = newValue
-        else delete spanEvent.attributes[key] // delete from attributes if undefined
+        if (newValue !== undefined) {
+          spanEvent.attributes[key] = newValue
+        } else {
+          delete spanEvent.attributes[key] // delete from attributes if undefined
+        }
       }
       if (Object.entries(spanEvent.attributes).length === 0) {
         delete spanEvent.attributes
@@ -388,20 +398,18 @@ function convertSpanEventAttributeValues (key, value, depth = 0) {
           array_value: convertedArray
         }
       } else {
-      // If all elements were unsupported, return undefined
+        // If all elements were unsupported, return undefined
         return undefined
       }
     } else {
-      log.warn(
-        `Encountered nested array data type for span event v0.4 encoding. 
-        Skipping encoding key: ${key}: with value: ${typeof value}.`
+      memoizedLogDebug(key, 'Encountered nested array data type for span event v0.4 encoding. ' +
+        `Skipping encoding key: ${key}: with value: ${typeof value}.`
       )
       return undefined
     }
   } else {
-    log.warn(
-      `Encountered unsupported data type for span event v0.4 encoding, key: ${key}: with value: ${typeof value}. 
-      Skipping encoding of pair.`
+    memoizedLogDebug(key, 'Encountered unsupported data type for span event v0.4 encoding, key: ' +
+       `${key}: with value: ${typeof value}. Skipping encoding of pair.`
     )
     return undefined
   }

packages/dd-trace/src/log/index.js

@@ -6,19 +6,7 @@ const { isTrue } = require('../util')
 const { traceChannel, debugChannel, infoChannel, warnChannel, errorChannel } = require('./channels')
 const logWriter = require('./writer')
 const { Log } = require('./log')
-
-const memoize = func => {
-  const cache = {}
-  const memoized = function (key) {
-    if (!cache[key]) {
-      cache[key] = func.apply(this, arguments)
-    }
-
-    return cache[key]
-  }
-
-  return memoized
-}
+const { memoize } = require('./utils')
 
 const config = {
   enabled: false,

packages/dd-trace/src/log/utils.js

@@ -0,0 +1,16 @@
+'use strict'
+
+const memoize = func => {
+  const cache = {}
+  const memoized = function (key) {
+    if (!cache[key]) {
+      cache[key] = func.apply(this, arguments)
+    }
+
+    return cache[key]
+  }
+
+  return memoized
+}
+
+module.exports = { memoize }

packages/dd-trace/test/encode/0.4.spec.js

@@ -5,6 +5,8 @@ require('../setup/tap')
 const { expect } = require('chai')
 const msgpack = require('@msgpack/msgpack')
 const id = require('../../src/id')
+const proxyquire = require('proxyquire')
+const sinon = require('sinon')
 
 function randString (length) {
   return Array.from({ length }, () => {
@@ -23,7 +25,7 @@ describe('encode', () => {
       logger = {
         debug: sinon.stub()
       }
-      const { AgentEncoder } = proxyquire('../src/encode/0.4', {
+      const { AgentEncoder } = proxyquire('../../src/encode/0.4', {
         '../log': logger
       })
       writer = { flush: sinon.spy() }
@@ -474,8 +476,15 @@ describe('encode', () => {
   })
 
   describe('with configuration', () => {
+    let logger
+
     beforeEach(() => {
-      const { AgentEncoder } = proxyquire('../src/encode/0.4', {
+      // Create a sinon spy for log.debug
+      logger = {
+        debug: sinon.spy()
+      }
+
+      const { AgentEncoder } = proxyquire('../../src/encode/0.4', {
         '../log': logger
       })
       writer = { flush: sinon.spy(), _config: { trace: { nativeSpanEvents: true } } }
@@ -565,5 +574,71 @@ describe('encode', () => {
 
       expect(trace[0].span_events).to.deep.equal(formattedTopLevelEvent)
     })
+
+    it('should call log.debug only once for the same unsupported key', () => {
+      const topLevelEvents = [
+        {
+          name: 'Event 1',
+          time_unix_nano: 1000000,
+          attributes: { unsupported_key: { some: 'object' }, other_key: 'valid' }
+        },
+        {
+          name: 'Event 2',
+          time_unix_nano: 2000000,
+          attributes: { unsupported_key: { another: 'object' } }
+        },
+        {
+          name: 'Event 3',
+          time_unix_nano: 3000000,
+          attributes: { unsupported_key: { yet: 'another object' } }
+        },
+        {
+          name: 'Event 4',
+          time_unix_nano: 4000000,
+          attributes: { unsupported_key: { different: 'structure' } }
+        }
+      ]
+
+      data[0].span_events = topLevelEvents
+
+      encoder.encode(data)
+
+      // Assert that log.debug was called only once for 'unsupported_key'
+      sinon.assert.calledOnce(logger.debug)
+      sinon.assert.calledWith(
+        logger.debug,
+        sinon.match(/Encountered unsupported data type for span event v0\.4 encoding, key: unsupported_key/)
+      )
+    })
+
+    it('should call log.debug once per unique unsupported key', () => {
+      const topLevelEvents = [
+        {
+          name: 'Event 1',
+          time_unix_nano: 1000000,
+          attributes: { unsupported_key1: { some: 'object' }, unsupported_key2: { another: 'object' } }
+        },
+        {
+          name: 'Event 2',
+          time_unix_nano: 2000000,
+          attributes: { unsupported_key1: { different: 'structure' }, unsupported_key3: { more: 'objects' } }
+        },
+        {
+          name: 'Event 3',
+          time_unix_nano: 3000000,
+          attributes: { unsupported_key2: { yet: 'another object' }, unsupported_key3: { extra: 'data' } }
+        }
+      ]
+
+      data[0].span_events = topLevelEvents
+
+      encoder.encode(data)
+
+      // Assert that log.debug was called once for each unique unsupported key
+      expect(logger.debug.callCount).to.equal(3)
+      expect(logger.debug.getCall(0).args[0]).to.match(/unsupported_key1/)
+      expect(logger.debug.getCall(1).args[0]).to.match(/unsupported_key2/)
+      expect(logger.debug.getCall(2).args[0]).to.match(/unsupported_key3/)
+    })
   })
 })