fix: Updated shimmer to handle instrumenting named and default exports of CommonJS modules in ESM

bin/macos-firewall.sh

@@ -0,0 +1,26 @@
+#!/bin/sh
+# Script that adds rules to Mac OS X Socket Firewall to avoid
+# popups asking to accept incoming network connections when
+# running tests.
+#
+# Originally from https://github.com/nodejs/node/blob/5398cb55ca10d34ed7ba5592f95b3b9f588e5754/tools/macos-firewall.sh
+
+SFW="/usr/libexec/ApplicationFirewall/socketfilterfw"
+NODE_PATH=$(realpath $(which node))
+
+add_and_unblock () {
+  if [ -e "$1" ]
+  then
+    echo Processing "$1"
+    $SFW --remove "$1" >/dev/null
+    $SFW --add "$1"
+    $SFW --unblock "$1"
+  fi
+}
+
+if [ -f $SFW ];
+then
+  add_and_unblock "$NODE_PATH"
+else
+  echo "SocketFirewall not found in location: $SFW"
+fi

lib/instrumentation/pg.js

@@ -19,6 +19,7 @@ function getQuery(shim, original, name, args) {
   return statement
 }
 
+// eslint-disable-next-line sonarjs/cognitive-complexity
 module.exports = function initialize(agent, pgsql, moduleName, shim) {
   shim.setDatastore(shim.POSTGRES)
 
@@ -78,21 +79,33 @@ module.exports = function initialize(agent, pgsql, moduleName, shim) {
     })
   }
 
-  // The pg module defines "native" getter which sets up the native client lazily
-  // (only when called).  We replace the getter, so that we can instrument the native
-  // client.  The original getter replaces itself with the instance of the native
-  // client, so only instrument if the getter exists (otherwise assume already
-  // instrumented).
-  const origGetter = pgsql.__lookupGetter__('native')
-  if (origGetter) {
-    delete pgsql.native
-    pgsql.__defineGetter__('native', function getNative() {
-      const temp = origGetter()
-      if (temp != null) {
-        instrumentPGNative(temp)
-      }
-      return temp
-    })
+  if (pgsql[Symbol.for('nr-esm-proxy')] === true) {
+    // When pg is imported via an ESM import statement, then our proxy will
+    // make our non-ESM native getter wrapper not work correctly. Basically,
+    // the getter will get evaluated by the proxy, and we never gain access to
+    // replace the getter with our own implementation. Luckily, we get to
+    // simplify in this scenario.
+    const native = pgsql.default.native
+    if (native !== null) {
+      instrumentPGNative(native)
+    }
+  } else {
+    // The pg module defines a "native" getter which sets up the native client lazily
+    // (only when called).  We replace the getter, so that we can instrument the native
+    // client.  The original getter replaces itself with the instance of the native
+    // client, so only instrument if the getter exists (otherwise assume already
+    // instrumented).
+    const origGetter = pgsql.__lookupGetter__('native')
+    if (origGetter) {
+      delete pgsql.native
+      pgsql.__defineGetter__('native', function getNative() {
+        const temp = origGetter()
+        if (temp != null) {
+          instrumentPGNative(temp)
+        }
+        return temp
+      })
+    }
   }
 
   // wrapping for JS

lib/instrumentation/winston.js

@@ -101,7 +101,12 @@ function registerFormatter({ opts, agent, winston }) {
   if (opts.format) {
     opts.format = winston.format.combine(instrumentedFormatter(), opts.format)
   } else {
-    opts.format = instrumentedFormatter()
+    // The default formatter for Winston is the JSON formatter. If the user
+    // has not provided a formatter through opts.format, we must emulate the
+    // default. Otherwise, the message symbol will not get attached to log
+    // messages and transports, e.g. the "Console" transport, will not be able
+    // to output logs correctly.
+    opts.format = winston.format.combine(instrumentedFormatter(), winston.format.json())
   }
 }
 

lib/shimmer.js

@@ -537,10 +537,7 @@ function instrumentPostLoad(agent, nodule, moduleName, resolvedName, esmResolver
       return
     }
 
-    // We only return the .default when we're a CJS module in the import-in-the-middle(ESM)
-    // callback hook
-    const resolvedNodule = instrumentation.isEsm || !esmResolver ? nodule : nodule.default
-
+    const resolvedNodule = resolveNodule({ nodule, instrumentation, esmResolver })
     const shim = shims.createShimFromType({
       type: instrumentation.type,
       agent,
@@ -579,6 +576,60 @@ function instrumentPostLoad(agent, nodule, moduleName, resolvedName, esmResolver
   return nodule
 }
 
+/**
+ * If a module that is being shimmed was loaded via a typical `require` then
+ * we can use it as normal. If was loaded via an ESM import, then we need to
+ * handle it with some extra care. This function inspects the module,
+ * the conditions around its loading, and returns an appropriate object for
+ * subsequent shimming methods.
+ *
+ * @param {object} params Input parameters.
+ * @param {object} params.nodule The nodule being instrumented.
+ * @param {object} params.instrumentation The configuration for the nodule
+ * to be instrumented.
+ * @param {boolean|null} params.esmResolver Indicates if the nodule was loaded
+ * via an ESM import.
+ * @returns {object} The nodule or a Proxy.
+ */
+function resolveNodule({ nodule, instrumentation, esmResolver }) {
+  if (instrumentation.isEsm === true || !esmResolver) {
+    return nodule
+  }
+
+  // We have a CJS module wrapped by import-in-the-middle having been
+  // imported through ESM syntax. Due to the way CJS modules are parsed by
+  // ESM's import, we can have the same "export" attached to the `default`
+  // export and as a top-level named export. In order to shim things such
+  // that our users don't need to know to access `something.default.foo`
+  // when they have done `import * as something from 'something'`, we need
+  // to proxy the proxy in order to set our wrappers on both instances.
+  const noduleDefault = nodule.default
+  const origNodule = nodule
+  return new Proxy(
+    { origNodule, noduleDefault },
+    {
+      get(target, name) {
+        if (name === Symbol.for('nr-esm-proxy')) {
+          return true
+        }
+        if (target.noduleDefault[name]) {
+          return target.noduleDefault[name]
+        }
+        return target.origNodule[name]
+      },
+      set(target, name, value) {
+        if (target.origNodule[name]) {
+          target.origNodule[name] = value
+        }
+        if (target.noduleDefault[name]) {
+          target.noduleDefault[name] = value
+        }
+        return true
+      }
+    }
+  )
+}
+
 /**
  * Attempts to execute an onRequire hook for a given module.
  * If it fails it will call an onError hook and log warnings accordingly

test/versioned/winston-esm/common.mjs

@@ -0,0 +1,13 @@
+/*
+ * Copyright 2023 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import Transport from 'winston-transport'
+export class Sink extends Transport {
+  loggedLines = []
+  log(data, done) {
+    this.loggedLines.push(data)
+    done()
+  }
+}

test/versioned/winston-esm/fixtures/named-import.mjs

@@ -0,0 +1,13 @@
+/*
+ * Copyright 2023 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import winston from 'winston'
+
+export function doLog(sink) {
+  const logger = winston.createLogger({
+    transports: sink
+  })
+  logger.warn('import winston from winston')
+}

test/versioned/winston-esm/fixtures/star-import.mjs

@@ -0,0 +1,13 @@
+/*
+ * Copyright 2023 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import * as winston from 'winston'
+
+export function doLog(sink) {
+  const logger = winston.createLogger({
+    transports: sink
+  })
+  logger.warn('import * as winston from winston')
+}

test/versioned/winston-esm/newrelic.cjs

@@ -0,0 +1,28 @@
+/*
+ * Copyright 2020 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+'use strict'
+
+exports.config = {
+  app_name: ['New Relic for Node.js tests'],
+  license_key: 'license key here',
+  logging: {
+    level: 'trace',
+    filepath: '../../../newrelic_agent.log'
+  },
+  utilization: {
+    detect_aws: false,
+    detect_pcf: false,
+    detect_azure: false,
+    detect_gcp: false,
+    detect_docker: false
+  },
+  distributed_tracing: {
+    enabled: true
+  },
+  transaction_tracer: {
+    enabled: true
+  }
+}

test/versioned/winston-esm/package.json

@@ -0,0 +1,20 @@
+{
+  "name": "winston-esm-tests",
+  "version": "0.0.0",
+  "type": "module",
+  "private": true,
+  "tests": [
+    {
+      "engines": {
+        "node": ">=16"
+      },
+      "dependencies": {
+        "winston": ">=3",
+        "winston-transport": ">=4"
+      },
+      "files": [
+        "winston.tap.mjs"
+      ]
+    }
+  ]
+}

test/versioned/winston-esm/winston.tap.mjs

@@ -0,0 +1,85 @@
+/*
+ * Copyright 2023 New Relic Corporation. All rights reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import tap from 'tap'
+import { randomUUID } from 'node:crypto'
+import helper from '../../lib/agent_helper.js'
+import names from '../../../lib/metrics/names.js'
+import { Sink } from './common.mjs'
+
+const { LOGGING } = names
+
+tap.beforeEach(async (t) => {
+  t.context.test_id = randomUUID()
+  t.context.agent = helper.instrumentMockedAgent()
+})
+
+tap.afterEach((t) => {
+  helper.unloadAgent(t.context.agent)
+})
+
+tap.test('named import issues logs correctly', async (t) => {
+  const sink = new Sink()
+  const { agent } = t.context
+  agent.config.application_logging.forwarding.enabled = true
+
+  const { doLog } = await import('./fixtures/named-import.mjs?test=' + t.context.test_id)
+  doLog(sink)
+  t.equal(1, sink.loggedLines.length, 'log is written to the transport')
+
+  const log = sink.loggedLines[0]
+  const symbols = Object.getOwnPropertySymbols(log)
+  // Instrumented logs should still be decorated internally by Winston with
+  // a message symbol.
+  t.equal(
+    true,
+    symbols.some((s) => s.toString() === 'Symbol(message)'),
+    'log object has winston internal symbol'
+  )
+
+  const agentLogs = agent.logs.getEvents()
+  t.equal(
+    true,
+    agentLogs.some((l) => {
+      return l?.message === 'import winston from winston'
+    }),
+    'log gets added to agent logs'
+  )
+
+  const metric = agent.metrics.getMetric(LOGGING.LIBS.WINSTON)
+  t.equal(1, metric.callCount, 'winston log metric is recorded')
+})
+
+tap.test('alias import issues logs correctly', async (t) => {
+  const sink = new Sink()
+  const { agent } = t.context
+  agent.config.application_logging.forwarding.enabled = true
+
+  const { doLog } = await import('./fixtures/star-import.mjs?test=' + t.context.test_id)
+  doLog(sink)
+  t.equal(1, sink.loggedLines.length, 'log is written to the transport')
+
+  const log = sink.loggedLines[0]
+  const symbols = Object.getOwnPropertySymbols(log)
+  // Instrumented logs should still be decorated internally by Winston with
+  // a message symbol.
+  t.equal(
+    true,
+    symbols.some((s) => s.toString() === 'Symbol(message)'),
+    'log object has winston internal symbol'
+  )
+
+  const agentLogs = agent.logs.getEvents()
+  t.equal(
+    true,
+    agentLogs.some((l) => {
+      return l?.message === 'import * as winston from winston'
+    }),
+    'log gets added to agent logs'
+  )
+
+  const metric = agent.metrics.getMetric(LOGGING.LIBS.WINSTON)
+  t.equal(1, metric.callCount, 'winston log metric is recorded')
+})