Expand the Node.js metrics script usage to v14.10+ (#1198)

* Expand the Node.js metrics script usage to v14+
* Update CHANGELOG.md
* Added environment variable to opt-out of the metrics script
* Fix sha files that had no ending newline

[W-14838650](https://gus.lightning.force.com/lightning/r/a07EE00001iPkvfYAC/view)

Author: colincasey

.github/workflows/ci.yml

@@ -61,12 +61,14 @@ jobs:
     strategy:
       fail-fast: false
       matrix:
-        version: [latest, lts/*, lts/-1]
+        # check the minimum node version supported by the metrics script and the latest node version
+        # (assumes the versions between have backwards-compatible APIs)
+        version: [14.10.0, latest]
     name: Test Metrics (${{ matrix.version }})
     runs-on: ubuntu-latest
     steps:
       - uses: actions/checkout@v4
       - uses: actions/setup-node@v4
         with:
           node-version: ${{ matrix.version }}
-      - run: node --test metrics/test/metrics.spec.cjs
+      - run: npx mocha metrics/test/metrics.spec.cjs

CHANGELOG.md

@@ -5,6 +5,7 @@
 - Added Yarn version 3.8.0.
 - Added Yarn version 4.1.0.
 
+- Expand new metrics instrumentation to Node >= 14.10 ([#1198](https://github.com/heroku/heroku-buildpack-nodejs/pull/1198))
 
 ## [v235] - 2024-01-24
 

bin/report

@@ -113,8 +113,8 @@ kv_pair "lock_file" "$(meta_get "has-node-lock-file")"
 kv_pair "uses_workspaces" "$(json_has_key "$BUILD_DIR/package.json" "workspaces")"
 # what workspaces are defined? Logs as: `["packages/*","a","b"]`
 kv_pair_string "workspaces" "$(read_json "$BUILD_DIR/package.json" ".workspaces")"
-# count # of js, jsx, ts, coffee, vue, and html files to approximate project size, exclude any files in node_modules
-kv_pair "num_project_files" "$(find "$BUILD_DIR" -name '*.js' -o -name '*.ts' -o -name '*.jsx' -o -name '*.coffee' -o -name '*.vue' -o -name '*.html' | grep -cv node_modules | tr -d '[:space:]')"
+# count # of js, cjs, mjs, jsx, ts, coffee, vue, and html files to approximate project size, exclude any files in node_modules
+kv_pair "num_project_files" "$(find "$BUILD_DIR" -name '*.js' -o -name '*.cjs' -o -name '*.mjs' -o  -name '*.ts' -o -name '*.jsx' -o -name '*.coffee' -o -name '*.vue' -o -name '*.html' | grep -cv node_modules | tr -d '[:space:]')"
 # measure how large node_modules is on disk
 kv_pair "node_modules_size" "$(measure_size)"
 

lib/plugin.sh

@@ -4,26 +4,50 @@ get_node_major_version() {
   node --version | cut -d "." -f 1 | sed 's/^v//'
 }
 
+get_node_minor_version() {
+  node --version | cut -d "." -f 2
+}
+
 install_plugin() {
   local major
   local bp_dir="$1"
   local build_dir="$2"
   major=$(get_node_major_version)
+  minor=$(get_node_minor_version)
 
-  if [ "${major}" -lt "21" ]; then
-    local plugin="${bp_dir}/plugin/heroku-nodejs-plugin-node-${major}.tar.gz"
-    # If we have a version of the plugin compiled for this version of node, and the
-    # user has not opted out of including the plugin, copy it into the slug.
-    # It will be included at runtime once the user opts into the Node metrics feature
-    if [[ -f "${plugin}" ]] && [[ -z "$HEROKU_SKIP_NODE_PLUGIN" ]]; then
-      mkdir -p "${build_dir}/.heroku/"
-      tar -xzf "${plugin}" -C "${build_dir}/.heroku/"
-    fi
+  if (( major < 14 )) || (( major == 14 && minor < 10 )); then
+    install_native_plugin "$bp_dir" "$build_dir" "$major"
   else
-    local pluginScript="${bp_dir}/metrics/metrics_collector.cjs"
-    if [[ -f "${pluginScript}" ]] && [[ -z "$HEROKU_SKIP_NODE_PLUGIN" ]]; then
-        mkdir -p "${build_dir}/.heroku/metrics"
-        cp "${pluginScript}" "${build_dir}/.heroku/metrics/"
+    if [[ -n "$HEROKU_LEGACY_NODE_PLUGIN" ]] && (( major < 21 )); then
+      warn "The native addon for Node.js language metrics is no longer supported. Unset the HEROKU_LEGACY_NODE_PLUGIN environment variable to migrate to the new metrics collector."
+      install_native_plugin "$bp_dir" "$build_dir" "$major"
+    else
+      install_script_plugin "$bp_dir" "$build_dir"
     fi
   fi
 }
+
+# Node.js versions < 14.10.0 must use the prebuilt native addon
+install_native_plugin() {
+  local bp_dir="$1"
+  local build_dir="$2"
+  local major="$3"
+  local plugin="${bp_dir}/plugin/heroku-nodejs-plugin-node-${major}.tar.gz"
+  # If we have a version of the plugin compiled for this version of node, and the
+  # user has not opted out of including the plugin, copy it into the slug.
+  # It will be included at runtime once the user opts into the Node metrics feature
+  if [[ -f "${plugin}" ]] && [[ -z "$HEROKU_SKIP_NODE_PLUGIN" ]]; then
+    mkdir -p "${build_dir}/.heroku/"
+    tar -xzf "${plugin}" -C "${build_dir}/.heroku/"
+  fi
+}
+# Node.js versions >= 14.10.0 can use the metrics script
+install_script_plugin() {
+  local bp_dir="$1"
+  local build_dir="$2"
+  local pluginScript="${bp_dir}/metrics/metrics_collector.cjs"
+  if [[ -f "${pluginScript}" ]] && [[ -z "$HEROKU_SKIP_NODE_PLUGIN" ]]; then
+      mkdir -p "${build_dir}/.heroku/metrics"
+      cp "${pluginScript}" "${build_dir}/.heroku/metrics/"
+  fi
+}

metrics/metrics_collector.cjs

@@ -21,16 +21,18 @@
  *     gauges: EventLoopGauges;
  * }} MetricsPayload
  */
-const { setInterval } = require('node:timers')
-const { URL } = require('node:url');
-const { debuglog } = require('node:util');
-const { monitorEventLoopDelay, PerformanceObserver, constants, performance } = require('node:perf_hooks')
+const { setInterval } = require('timers')
+const { URL } = require('url');
+const { debuglog } = require('util');
+const { monitorEventLoopDelay, PerformanceObserver, constants, performance } = require('perf_hooks')
+const { request: insecureRequest } = require('http');
+const { request: secureRequest } = require('https');
 
 try {
     // failures from the instrumentation shouldn't mess with the application
     registerInstrumentation()
 } catch (e) {
-    log(`An unexpected error occurred: ${e.message}`)
+    log(`An unexpected error occurred: ${e.stack}`)
 }
 
 /**
@@ -53,33 +55,33 @@ function registerInstrumentation() {
     const gcObserver = new PerformanceObserver((value) => {
         value.getEntries().forEach(entry => updateMemoryCounters(memoryCounters, entry))
     })
-    gcObserver.observe({ type: 'gc' })
+    gcObserver.observe({ entryTypes: ['gc'] })
 
     const eventLoopHistogram = monitorEventLoopDelay()
     eventLoopHistogram.enable()
 
     let previousEventLoopUtilization = performance.eventLoopUtilization()
 
     const timeout  = setInterval(() => {
-        const eventLoopUtilization = performance.eventLoopUtilization(previousEventLoopUtilization)
-        eventLoopHistogram.disable()
-        gcObserver.disconnect()
-
-        const payload = {
-            counters: { ...memoryCounters },
-            gauges: captureEventLoopGauges(eventLoopUtilization, eventLoopHistogram)
-        }
+        try {
+            const eventLoopUtilization = performance.eventLoopUtilization(previousEventLoopUtilization)
+            eventLoopHistogram.disable()
+            gcObserver.disconnect()
 
-        sendMetrics(herokuMetricsUrl, payload).catch((err) => {
-            log(`An error occurred while sending metrics - ${err}`)
-        })
+            sendMetrics(herokuMetricsUrl, {
+                counters: {...memoryCounters},
+                gauges: captureEventLoopGauges(eventLoopUtilization, eventLoopHistogram)
+            })
 
-        // reset memory and event loop measures
-        previousEventLoopUtilization = eventLoopUtilization
-        memoryCounters = initializeMemoryCounters()
-        gcObserver.observe({ type: 'gc' })
-        eventLoopHistogram.reset()
-        eventLoopHistogram.enable()
+            // reset memory and event loop measures
+            previousEventLoopUtilization = eventLoopUtilization
+            memoryCounters = initializeMemoryCounters()
+            gcObserver.observe({ entryTypes: ['gc'] })
+            eventLoopHistogram.reset()
+            eventLoopHistogram.enable()
+        } catch (e) {
+            log(`An unexpected error occurred: ${e.stack}`)
+        }
     }, herokuMetricsInterval)
 
     // `setInterval` actually returns a Timeout object but this isn't recognized by the type-checker which
@@ -171,19 +173,31 @@ function initializeMemoryCounters(){
  * @param {PerformanceEntry} performanceEntry
  */
 function updateMemoryCounters(memoryCounters, performanceEntry) {
-    // only record entries with that contain a 'detail' object with 'kind' property
-    // since these are only available for NodeGCPerformanceDetail entries
-    if ('detail' in performanceEntry && 'kind' in performanceEntry.detail) {
-        const nsDuration = millisecondsToNanoseconds(performanceEntry.duration)
-        memoryCounters['node.gc.collections'] += 1
-        memoryCounters['node.gc.pause.ns'] += nsDuration
-        if (performanceEntry.detail.kind === constants.NODE_PERFORMANCE_GC_MINOR) {
-            memoryCounters['node.gc.young.collections'] += 1
-            memoryCounters['node.gc.young.pause.ns'] += nsDuration
-        } else {
-            memoryCounters['node.gc.old.collections'] += 1
-            memoryCounters['node.gc.old.pause.ns'] += nsDuration
-        }
+    const nsDuration = millisecondsToNanoseconds(performanceEntry.duration)
+    memoryCounters['node.gc.collections'] += 1
+    memoryCounters['node.gc.pause.ns'] += nsDuration
+    if (getGcPerformanceEntryKind(performanceEntry) === constants.NODE_PERFORMANCE_GC_MINOR) {
+        memoryCounters['node.gc.young.collections'] += 1
+        memoryCounters['node.gc.young.pause.ns'] += nsDuration
+    } else {
+        memoryCounters['node.gc.old.collections'] += 1
+        memoryCounters['node.gc.old.pause.ns'] += nsDuration
+    }
+}
+
+/**
+ * Reads the `kind` field for the 'gc' performance entry in a backwards-compatible way
+ * @param {PerformanceEntry} performanceEntry
+ * @returns {number}
+ */
+function getGcPerformanceEntryKind(performanceEntry) {
+    // using try/catch to avoid triggering deprecation warnings
+    try {
+        // for v16 and up
+        return performanceEntry.detail.kind
+    } catch (e) {
+        // fallback for v14 & v15
+        return performanceEntry.kind
     }
 }
 
@@ -209,7 +223,7 @@ function captureEventLoopGauges(eventLoopUtilization, eventLoopHistogram) {
  * @return {number}
  */
 function millisecondsToNanoseconds(ms) {
-    return ms * 1_000_000
+    return ms * 1e6 // 1_000_000
 }
 
 /**
@@ -218,26 +232,47 @@ function millisecondsToNanoseconds(ms) {
  * @return {number}
  */
 function nanosecondsToMilliseconds(ns) {
-    return ns / 1_000_000
+    return ns / 1e6 // 1_000_000
 }
 
 /**
  * Sends the collected metrics to the given endpoint using a POST request.
  * @param {URL} url
  * @param {MetricsPayload} payload
- * @returns {Promise<void>}
+ * @returns void
  */
 function sendMetrics(url, payload) {
+    const request = url.protocol === 'https:' ? secureRequest : insecureRequest
+    const payloadAsJson = JSON.stringify(payload)
+
     log(`Sending metrics to ${url.toString()}`)
-    return fetch(url, {
+    const clientRequest = request({
         method: 'POST',
-        headers: { 'Content-Type': 'application/json' },
-        body: JSON.stringify(payload)
-    }).then(res => {
-        if (res.ok) {
+        protocol: url.protocol,
+        hostname: url.hostname,
+        port: url.port,
+        path: url.pathname,
+        headers: {
+            'Content-Type': 'application/json',
+            'Content-Length': Buffer.byteLength(payloadAsJson)
+        }
+    })
+
+    clientRequest.on('response', (res) => {
+        if (res.statusCode === 200) {
             log('Metrics sent successfully')
         } else {
-            log(`Tried to send metrics but response was: ${res.status} - ${res.statusText}`)
+            log(`Tried to send metrics but response was: ${res.statusCode} - ${res.statusMessage}`)
         }
+        // consume response data to free up memory
+        // see: https://nodejs.org/docs/latest/api/http.html#http_class_http_clientrequest
+        res.resume()
     })
+
+    clientRequest.on('error', (err) => {
+        log(`An error occurred while sending metrics - ${err}`)
+    })
+
+    clientRequest.write(payloadAsJson)
+    clientRequest.end()
 }

metrics/test/fixtures/clustered_app.cjs

@@ -1,10 +1,13 @@
-const { isPrimary, fork } = require('node:cluster')
+const cluster = require('cluster')
 
 require('./_cpu_and_memory_simulator.cjs')
 
-if (isPrimary) {
+if (
+    cluster.isPrimary ||
+    cluster.isMaster // deprecated in Node v16
+) {
     console.log(`Starting primary cluster ${process.pid} running with NODE_OPTIONS="${process.env.NODE_OPTIONS || ''}"`)
-    fork()
+    cluster.fork()
     process.on('SIGINT', () => {
         process.exit(0)
     })

metrics/test/fixtures/worker_threads_app.cjs

@@ -1,4 +1,4 @@
-const { Worker, isMainThread} = require('node:worker_threads')
+const { Worker, isMainThread} = require('worker_threads')
 
 require('./_cpu_and_memory_simulator.cjs')