Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"no function to unwrap" logged when disabling Express instrumentation #970

Closed
nwalters512 opened this issue Apr 12, 2022 · 7 comments · Fixed by #972
Closed

"no function to unwrap" logged when disabling Express instrumentation #970

nwalters512 opened this issue Apr 12, 2022 · 7 comments · Fixed by #972
Assignees
Labels
bug Something isn't working

Comments

@nwalters512
Copy link
Contributor

What version of OpenTelemetry are you using?

  • @opentelemetry/api: 1.0.4
  • @opentelemetry/instrumentation-express: 0.28.0

What version of Node are you using?

$ node --version
v16.13.0

What did you do?

Reproduction available at https://github.com/nwalters512/otel-js-express-repro

Steps to reproduce:

  • Clone the repo
  • Run yarn install
  • Run node index.js

What did you expect to see?

I do not expect to see anything logged.

What did you see instead?

I see the following output:

$ node index.js 
no function to unwrap.
Error
    at ExpressInstrumentation.unwrap [as _unwrap] (/Users/nathan/git/otel-js-express-repro/node_modules/shimmer/index.js:84:13)
    at InstrumentationNodeModuleDefinition.unpatch (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation-express/build/src/instrumentation.js:72:22)
    at ExpressInstrumentation.disable (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:123:24)
    at Object.<anonymous> (/Users/nathan/git/otel-js-express-repro/index.js:11:17)
    at Module._compile (node:internal/modules/cjs/loader:1101:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
    at node:internal/main/run_main_module:17:47
no function to unwrap.
Error
    at ExpressInstrumentation.unwrap [as _unwrap] (/Users/nathan/git/otel-js-express-repro/node_modules/shimmer/index.js:84:13)
    at InstrumentationNodeModuleDefinition.unpatch (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation-express/build/src/instrumentation.js:73:22)
    at ExpressInstrumentation.disable (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:123:24)
    at Object.<anonymous> (/Users/nathan/git/otel-js-express-repro/index.js:11:17)
    at Module._compile (node:internal/modules/cjs/loader:1101:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
    at node:internal/main/run_main_module:17:47
no function to unwrap.
Error
    at ExpressInstrumentation.unwrap [as _unwrap] (/Users/nathan/git/otel-js-express-repro/node_modules/shimmer/index.js:84:13)
    at InstrumentationNodeModuleDefinition.unpatch (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation-express/build/src/instrumentation.js:74:22)
    at ExpressInstrumentation.disable (/Users/nathan/git/otel-js-express-repro/node_modules/@opentelemetry/instrumentation/build/src/platform/node/instrumentation.js:123:24)
    at Object.<anonymous> (/Users/nathan/git/otel-js-express-repro/index.js:11:17)
    at Module._compile (node:internal/modules/cjs/loader:1101:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1153:10)
    at Module.load (node:internal/modules/cjs/loader:981:32)
    at Function.Module._load (node:internal/modules/cjs/loader:822:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:81:12)
    at node:internal/main/run_main_module:17:47

Additional context

There's some weird asymmetry in the instrumentation: the patch callback effectively invokes this._wrap(moduleExports.Router, 'route'), whereas the unpatch callback invokes this._unwrap(moduleExports.Router.prototype, 'route'). I would expect to see them either both use moduleExports.Router or moduleExports.Router.prototype.

I don't know enough about how patching works to tell if that's intentional or not, and I can't see anything useful from git blame. If changing unpatch to not use the prototype is the right solution, I'd be happy to open a PR!

@rauno56
Copy link
Member

rauno56 commented Apr 13, 2022

@nwalters512, just wondering: Do you actually require disabling the instrumentation? Could you explain the usecase?
I've been wondering how common is it to turn instrumentations off during runtime.

@Flarna
Copy link
Member

Flarna commented Apr 13, 2022

Turning an instrumentation off/on at runtime is quite risky. It usually works fine in unittest like setups where a single instrumentation is used but in the wild there are quite a lot modules (not only APM tools) which monkey patch this and that. So unwrap may fail or restore the wrong function if there were some other patch afterwards.
Besides that the wrapped functions may be cached at various places so user may end up in a half patched state.

@nwalters512
Copy link
Contributor Author

Strictly speaking, we don't require it. The intent was to disable it during tests and in lower environments to avoid unnecessary overhead. This is definitely a premature optimization and not based on any profiling. I just saw that a disable() function existed, and it seemed like an easy way to save some CPU cycles. If the official recommendedation is to just leave them enabled and not worry about it, I'm happy to do that too!

@rauno56
Copy link
Member

rauno56 commented Apr 14, 2022

Thanks for the explanation! I didn't ask to critique the approach - I agree that if the disable method is there, I, as an user, would expect that to work and be reliable.

I tend to agree with what @Flarna said. Even providing it is not a good idea: maintenance overhead, flimsy implementations, broken expectations. I don't think any other SIG supports it either.

@Flarna
Copy link
Member

Flarna commented Apr 14, 2022

Linking a previous discussion/PR here for reference:
open-telemetry/opentelemetry-js#618
open-telemetry/opentelemetry-js#732

As far as I know there is no official statement/recommendation that disable/enable shouldn't be used. There are a lot cases where it works fine - in special in unittests where the environment is well known and dependencies are usually limited. But personally I would not use it in production to solve some problem. I would prefer to restart the process and skip this instrumentation from start.

@nwalters512
Copy link
Contributor Author

Thanks for the explanation! I didn't ask to critique the approach - I agree that if the disable method is there, I, as an user, would expect that to work and be reliable.

I tend to agree with what @Flarna said. Even providing it is not a good idea: maintenance overhead, flimsy implementations, broken expectations. I don't think any other SIG supports it either.

Ack! Yeah, if the unofficial guidance is "don't disable, it may not work or may break things", I would not expect that to be part of the API.

I would prefer to restart the process and skip this instrumentation from start.

This would certainly be my preference too, but there's a sort of chicken-and-egg problem here. If you store your config in something like AWS Secrets Manager or AWS AppConfig (like we do), then in order to know if OTel should be enabled, you need to require the AWS SDK, which in turn requires http and fs and dns. This violates the "you should always apply instrumentation as the first thing when starting up your process" guidance.

I guess that's something that I should ask about explicitly: is ensuring that OTel instrumentation is the first thing to load instrumented packages actually required? In other words, would something like this actually work correctly?

const dns = require('dns');

const { DnsInstrumentation } = require('@opentelemetry/instrumentation-dns');
(new DnsInstrumentation()).enable();

dns.lookup('example.org', (err, address, family) => {
  console.log('address: %j family: IPv%s', address, family);
});
// Would I get a span/trace for the above, even though `dns` was
// required before the instrumentation was enabled?

If we can indeed safely load instrumentation a bit longer after process startup, that would remove our need to disable() instrumentations later. However, if not, we'd still need/want to disable() later on.

@Flarna
Copy link
Member

Flarna commented Apr 14, 2022

For the node.js built in modules like dns the above sequence will most likely work (I haven't tried) because these modules are not cached.
For external modules like aws-sdk it wont work.

But a small change can break this:

const { lookup } = require('dns');

const { DnsInstrumentation } = require('@opentelemetry/instrumentation-dns');
(new DnsInstrumentation()).enable();

lookup('example.org', (err, address, family) => {
  console.log('address: %j family: IPv%s', address, family);
});

==> The dns object was patched but this code uses the local lookup variable which points to the unpatched lookup function. And this sample also shows when unpatch will have no effect.

As e.g. http module uses dns it's needed to look into node.js source code to find out if the require the one or the other way.

In my opinion the only production safe variant to disable an instrumentation is to implement all wrapped functions like this:

function wrappedFunc(...args) {
  if (instrumentation.disabled) {
    return Reflect.apply(originalFunc, args)
  }
  // create spans,..
}

Clearly any started but not yet ended span will not disappear, bound callbacks, bound EventEmitter,... stays bound. But at least there is no risk that cached patched functions still create spans or disable unpatches more then wanted.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants