core modules imported with require('node:...') are not instrumented

[trentm]

Instrumentation for the following does not work because node:http is required instead of http.

// node-prefixed-core-modules.js
require('./').start() // elastic-apm-node
const http = require('node:http')
const server = http.createServer((req, res) => {
  req.resume()
  res.statusCode = 200
  res.end('pong')
})
server.listen(3000, () => {
  http.get('http://localhost:3000', res => {
    console.log('CLIENT: res.headers:', res.headers)
    res.resume()
    res.on('end', () => {
      console.log('CLIENT: res "end"')
      server.close()
    })
  })
})

Support for node:-prefixed imports to explicitly mean core modules was added in node v16.0.0 (and maybe in v14.8.0?). See nodejs/node#37246

With require-in-the-middle debug logging:

% DEBUG=require-in-the-middle node foo.js
  require-in-the-middle registering require hook +0ms
  require-in-the-middle processing non-core module require('./system-cpu'): /Users/trentm/el/apm-agent-nodejs/lib/metrics/platforms/generic/system-cpu.js +3ms
  require-in-the-middle processing core module require('os'): os +1ms
  require-in-the-middle ignoring core module not on whitelist: os +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/metrics/platforms/generic/system-cpu.js +1ms
  require-in-the-middle processing non-core module require('node:http'): node:http +3ms
  require-in-the-middle could not parse filename: node:http +0ms
CLIENT: res.headers: {
  date: 'Fri, 08 Jul 2022 21:53:22 GMT',
  connection: 'close',
  'content-length': '4'
}
CLIENT: res "end"

The issue is that require-in-the-middle's isCore fails:

    const filename = Module._resolveFilename(id, this)   // filename = 'node:http'
    const core = isCore(filename)  // core = false

We'll need to update require-in-the-middle to fix this. We should watch out for not separately wrapping require('http') and require('node:http'), so perhaps a good answer would be to normalize the filename. E.g. a first naive stab could just drop the leading node: if any. ... Yup, making this change in require-in-the-middle/index.js works:

    let filename = Module._resolveFilename(id, this)
    if (filename.startsWith('node:')) {
      filename = filename.slice(5)
    }
    const core = isCore(filename)

[trentm]

Aside: This hack results in working instrumentation:

diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js
index d2a5f587..e5e10035 100644
--- a/lib/instrumentation/index.js
+++ b/lib/instrumentation/index.js
@@ -43,7 +43,7 @@ var MODULES = [
   'graphql',
   'handlebars',
   ['hapi', '@hapi/hapi'],
-  'http',
+  ['http', 'node:http'],
   'https',
   'http2',
   'ioredis',

However, debug output from require-in-the-middle shows that (of course) it still doesn't recognize that 'node:http' is a "core" module:

% DEBUG=require-in-the-middle node node-prefixed-core-modules.js
  require-in-the-middle registering require hook +0ms
  require-in-the-middle processing non-core module require('./system-cpu'): /Users/trentm/el/apm-agent-nodejs/lib/metrics/platforms/generic/system-cpu.js +3ms
  require-in-the-middle processing core module require('os'): os +0ms
  require-in-the-middle ignoring core module not on whitelist: os +1ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/metrics/platforms/generic/system-cpu.js +0ms
  require-in-the-middle processing non-core module require('node:http'): node:http +4ms
  require-in-the-middle calling require hook: node:http +0ms
  require-in-the-middle processing non-core module require('./modules/http.js'): /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/modules/http.js +1ms
  require-in-the-middle processing non-core module require('../http-shared'): /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/http-shared.js +0ms
  require-in-the-middle processing core module require('url'): url +1ms
  require-in-the-middle ignoring core module not on whitelist: url +0ms
  require-in-the-middle processing non-core module require('end-of-stream'): /Users/trentm/el/apm-agent-nodejs/node_modules/end-of-stream/index.js +0ms
  require-in-the-middle resolved filename to module: end-of-stream (id: end-of-stream, resolved: end-of-stream, basedir: /Users/trentm/el/apm-agent-nodejs/node_modules/end-of-stream) +1ms
  require-in-the-middle processing non-core module require('../parsers'): /Users/trentm/el/apm-agent-nodejs/lib/parsers.js +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/parsers.js +0ms
  require-in-the-middle processing non-core module require('./context'): /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/context.js +0ms
  require-in-the-middle processing non-core module require('../parsers'): /Users/trentm/el/apm-agent-nodejs/lib/parsers.js +1ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/parsers.js +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/context.js +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/http-shared.js +0ms
  require-in-the-middle processing non-core module require('../shimmer'): /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/shimmer.js +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/shimmer.js +0ms
  require-in-the-middle could not parse filename: /Users/trentm/el/apm-agent-nodejs/lib/instrumentation/modules/http.js +0ms
  require-in-the-middle returning module: node:http +1ms
CLIENT: res.headers: {
  date: 'Mon, 08 Aug 2022 23:41:49 GMT',
  connection: 'close',
  'content-length': '4'
}
CLIENT: res "end"

We should be sure that would have no surprises before considering this approach. So far the initial suggestion (fixing require-in-the-middle's concept of what is a "core" module) sounds more promising.