Esm: APM hooks fail to instrument libraries

[vdeturckheim]

Hey,

So I have another issue with esm and sqreen and I feel like other tools are also impacted.

I built a POC using NewRelic:

I load newrelic and esm throught the command line (using -r) and I load pg with require or import.
newrelic should override the client.query method (you can check if it that by .toString on the method and check if it contains wrapper which is the name of the function used to wrap methods in NR).

Here are my test results:

Using require

• esm then newrelic

$ node -r esm -r newrelic run_require.js

Is pg instrumented? true

• NR then esm

$ node -r newrelic -r esm run_require.js
Is pg instrumented? false

Using import

• esm then newrelic

$ node -r esm -r newrelic run_esm.js
Is pg instrumented? false

• NR then esm

$ node -r newrelic -r esm run_esm.js
Is pg instrumented? false

I think that's because Module._load is not called in the cases where patching do not happen.
Sources are available here: https://github.com/vdeturckheim/esm-nr-pg

[jdalton]

Hi @vdeturckheim!

Ah yep, ESM code, as opposed to CJS code, goes through another non Module._load method.
I can move some things around to make that work.

[vdeturckheim]

Awesome, let me know if I can help on this!

Thanks a lot for your great support @jdalton !

[jdalton]

@vdeturckheim Can you tell me a bit more about how newrelic is instrumenting the module system?

[vdeturckheim]

@jdalton

In sqreen: when a module goes through Module._load, I add it into my own cache (for safety reasons) and run the hooks I have on it if any.

In newrelic: calls to Module._load are intercepted and redirected to _postLoad method (https://github.com/newrelic/node-newrelic/blob/6b452832255f52b182082a73c03b9b1ef2f5ecbc/lib/shimmer.js#L124) and if an instrumentation is defined for the module, NR will returne a patched version.
All patches are available in the code https://github.com/newrelic/node-newrelic/tree/master/lib/instrumentation . Instrumentation is usually made with a genereic wrapper and serves two goals: measuring time and patching asynchronous method to keep context between calls).

Other APMs use the same principles: for instance: elastic uses https://github.com/opbeat/require-in-the-middle

[jdalton]

I'm wondering why require order for the CJS example changes the result. The esm loader should be going through Module._load for CJS (when I add a log to the newrelic wrapper I see modules being run through it).

[vdeturckheim]

I'm not sure either. On which file/line did you add this log?

[jdalton]

I added logging here.

\cc newrelic devs @NatalieWolfe @psvet for any insights they may have.

[vdeturckheim]

I updated it with

return function wrappedLoad(file) {
        console.log(file);
        return _postLoad(agent, load.apply(this, arguments), file, resolvedName)
      }

When running I get:

$ node -r newrelic -r esm run_require.js | grep pg
# nothing here

$ node -r newrelic run_require.js | grep pg
pg
pg-types
pgpass
pg-types
pg-connection-string
pg-types
pg-pool
pg-types

$ node -r esm -r newrelic run_require.js | grep pg
pg
pg-types
pgpass
pg-types
pg-connection-string
pg-types
pg-pool
pg-types

So there is probably something else happening here but I haven't put my finger on it yet. Is there any recommended way to run esm in dev locally to debug more easely?

[jdalton]

@vdeturckheim If you use the debug option esm will drop masking methods and stack traces.

[psvet]

Thanks for the ping! Looped in another NR dev @lykkin to investigate further.

[jdalton]

Thanks @psvet!

It's our goal to "just work" with the ecosystem today so if you find something we goofed we're totally up for fixing it to improve compat.

[jdalton]

Ok, I have a fix for the run_esm.js test case. I'll clean it up and commit this evening. For the other issue: newrelic -r order I think a separate issue would be good.

Update:

Ok, so a little more on this. When I think about it, it makes sense that loading -r esm first works. When esm is loaded via -r esm it will hook into Module._extensions and Module.runMain. Then, all JS files will be handled by esm.

When modules loaded by esm request require("module") they get the esm flavor of Module. So, when APM modules patch Module methods, they are really patching esm's Module.

What is less clear is how loading -r esm second works. The APM module will patch the built-in Module._load and friends _(non-esm flavors)_. The esm package is loaded second. It hooks Module._extensions and Module.runMain. All files loaded after will run through esm and not the patched built-in Module._load.

Patched https://github.com/standard-things/esm/commit/d14dc8d77e2067ab83abf58dc0a167e62f67954f, https://github.com/standard-things/esm/commit/c36988de6d3ffc5d85dd81a87974b4cf50b3c922, https://github.com/standard-things/esm/commit/283a5fae29ebec8599b80d4f54e7d56000a5f3e8; Test https://github.com/standard-things/esm/commit/283a5fae29ebec8599b80d4f54e7d56000a5f3e8;

Update:

Ah yep! Even with the sqreen scenario test, if sqreen is loaded first then it's not really hooked in. So while our scenario test for loading sqreen first doesn't error, it's also not running through sqreen.

I should add a note to the tips section of the readme to load esm before sqreen and newrelic.

Update:

Patched https://github.com/standard-things/esm/commit/4920b95ce953ae5fd2f12fc2ef40001a15a346b8.

[vdeturckheim]

Great @jdalton thanks for this clear summary and the fixes! I'll perform some tests with the newer version.

[jdalton]

v3.0.27 is released :tada: