[http] Fix repeated traces on Node < v9 when tracing `https` requests. #268

alloy · 2018-09-01T23:36:07Z

When your application loads both the http and https modules while running on Node < v9, the https.request function internally calls http.request and ends up being double-counted https://github.com/nodejs/node/blob/v8.11.4/lib/https.js#L239

This patch fixes that situation by marking objects as already being traced and ignoring them when encountered again.

alloy · 2018-09-01T23:37:03Z

test/plugins/http.spec.js


-    describe('with service configuration', () => {
-      let config
+        it('should only record a request once', done => {


Here starts the actual new test

alloy · 2018-09-01T23:37:28Z

LICENSE-3rdparty.csv

@@ -48,6 +48,7 @@ dev,proxyquire,MIT,Copyright 2013 Thorsten Lorenz
 dev,redis,MIT,Copyright 2016 NodeRedis
 dev,require-dir,MIT,2012-2015 Aseem Kishore
 dev,retry,MIT,Copyright 2011 Tim Koschützki Felix Geisendörfer
+dev,selfsigned,MIT,Paolo Fragomeni and Charles Bushong


Added a dev dependency here, hope that’s ok

It's ok but it's missing Copyright <years> in front of the names.

I can add the Copyright part because that’s implicit, but they have not put any years on that themselves. (Or at least I couldn’t find a copyright line.)

I’ll ask them in an issue.

jfromaniello/selfsigned#28

rochdev · 2018-09-04T15:47:28Z

src/plugins/http.js

+      }
+      // Here we mark the `req` object, as opposed to also marking the `options` object like we do in `get`. The problem
+      // is that if we’d mark `options` here, it would get lost while upstream `request` derives a clone from it and
+      // thus would never get to the recursive invocation of `request`.


I think the code could be refactored to make the behavior clearer without the need for comments that detailed by using different code paths for the different scenarios. I tried to use the same code for both http and https but it seems it didn't necessarily make sense.

That’s definitely what I tried to do 😅

Maybe the comments are just making it harder to follow along? Or do you have more concrete suggestions of how to split them up?

Mentioned an idea in the get/request discussion below, hopefully it makes sense :)

rochdev · 2018-09-04T15:47:34Z

src/plugins/http.js

-        }
-      })
+      // Prevent from double-counting in `request`.
+      markAsTraced(options)


Why not just wait until req is returned and mark it there? (same as request)

~~Because get calls end on the req object before returning it, which is too late to inject headers.~~

(Misread, will leave a new comment)

Because get() internally calls request() we need to signal to our patched version of request() that this request is already being traced so it can skip it.

Hmm it seems there is another problem with this, in that the span is created after calling request() and thus would exclude its execution time.

if we’d mark options here, it would get lost while upstream request derives a clone from it

Is this done by the plugin or by the https module?

Also, wouldn't it be possible to simply detect the protocol in the http patch, so that if it's https it skips instrumentation (since it's the handler specifically for http). Then thehttp handler could simply use the https handler and wrap it with this check.

Hmm it seems there is another problem with this, in that the span is created after calling request() and thus would exclude its execution time.

The span is created on line 50 before invoking the actual implementation on lines 53 or 57.

if we’d mark options here, it would get lost while upstream request derives a clone from it

Is this done by the plugin or by the https module?

The https module https://github.com/nodejs/node/blob/v8.11.4/lib/https.js#L226-L237

Also, wouldn't it be possible to simply detect the protocol in the http patch, so that if it's https it skips instrumentation (since it's the handler specifically for http). Then the http handler could simply use the https handler and wrap it with this check.

Ah yes, I forgot to include this in my initial post, but my very first attempt basically did something along those lines, but it meant that:

When patching the https module we also need to activate the http plugin to ensure that both would be patched. This worked fine, but led to friction when deciding what/how to unpatch.

Because things work differently on Node < and >= v9, we’d need to conditionally patch some modules in some cases and not others. In and of itself this wasn’t really a big issue, because other plugins have version requirements too, it just added to the growing feeling of this not being the cleanest solution. (I had patched instrumenter.js to use the node version when a module couldn’t be located in node_modules.)

There was another hard issue I ran into but can’t remember offhand any longer, but it was probably the straw that broke the camel’s back and made me decide to take another stab at it from a different approach that would be agnostic to version specific issues, which is this PR.

The span is created on line 50 before invoking the actual implementation on lines 53 or 57.

Sorry for the confusion I actually meant line 15

The https module https://github.com/nodejs/node/blob/v8.11.4/lib/https.js#L226-L237

Since we always convert the options to an object, the property would be copied if defined as enumerable (or with a simple assignment). The reasoning behind using Object.defineProperties was to hide very large data that we might add from console.log such as a span. Also, in this case, the options object is a copy anyway so any value assigned here will never be seen by the user.

When patching the https module we also need to activate the http plugin to ensure that both would be patched. This worked fine, but led to friction when deciding what/how to unpatch.

I don't see why this would be the case if each of them have their own individual wrappers.

Because things work differently on Node < and >= v9, we’d need to conditionally patch some modules in some cases and not others.

I would argue that I'd prefer a clear line of code to do that then unclear code and a comment.

Sorry for the confusion I actually meant line 15

Ah right, it should be ok because, as I understand, the request won’t actually start until end() is called.

The reasoning behind using Object.defineProperties was to hide very large data that we might add from console.log such as a span.

That’s good to know 👍

I would argue that I'd prefer a clear line of code to do that then unclear code and a comment.

Touché 😏

I’ll take another stab at that once I’m done with a patch for receiving sampling priority from the agent on top of #217.

once I’m done with a patch for receiving sampling priority from the agent

@alloy Please definitely let me know when you start working on that to avoid duplicating work as we were planning on adding that in the next few days.

@alloy Did you make any progress on sampling priority? Otherwise that was the next item on my priority list.

A little bit. I’ll hit you up in Slack in a few minutes

rochdev · 2018-09-04T15:53:52Z

test/plugins/http.spec.js

+
+            appListener = server(app, port, () => {
+              // Activate a new parent span so we capture any double counting that may happen
+              const span = tracer.startSpan('http-test')


Why is this needed?

Because the two spans that are being emitted in the current release are siblings, thus the test would stop after the first one came in. Adding a parent span for them both makes sure the test takes all emitted spans into consideration.

rochdev · 2018-09-04T15:55:24Z

LICENSE-3rdparty.csv

@@ -48,6 +48,7 @@ dev,proxyquire,MIT,Copyright 2013 Thorsten Lorenz
 dev,redis,MIT,Copyright 2016 NodeRedis
 dev,require-dir,MIT,2012-2015 Aseem Kishore
 dev,retry,MIT,Copyright 2011 Tim Koschützki Felix Geisendörfer
+dev,selfsigned,MIT,Paolo Fragomeni and Charles Bushong


It's ok but it's missing Copyright <years> in front of the names.

timrogers · 2018-09-05T13:52:31Z

I'd be keen to get this one out - we're seeing all of these double recordings of our traces 😦 : Let me know if I can do anything to help.

alloy · 2018-09-06T10:35:59Z

@timrogers FYI that we’re running this on our fork in production just fine, so that may be an option for you until this is finished and released.

timrogers · 2018-09-06T10:40:59Z

@alloy Good shout! I'll do that.

alloy · 2018-09-13T13:37:52Z

src/plugins/http.js

+         */
+        require('http')
+      }
+    },
    unpatch
  }


@rochdev Ok this is the simplified version that just checks the Node version and patches the http module instead of the https module. You said in Slack that you think the unpatching part is fine to be left untouched like this?

Hold off, I’m investigating some issues on at least Node v10.

If I'm not mistaken the signature changed in Node 10 too.

Ok, fixed, I forgot that the instrumenter expects the functions to bind to it.

Interesting, still appears to be an issue on Node v6. Looking into it.

v10 is good btw https://github.com/nodejs/node/blob/v10.10.0/lib/https.js#L280

What I meant is that Node 10 accepts 3 parameters while Node 8 accepts only 2:

https://nodejs.org/docs/latest-v10.x/api/http.html#http_http_request_url_options_callback
https://nodejs.org/docs/latest-v8.x/api/http.html#http_http_request_options_callback

This is unrelated and can be done in another PR, but if it's an easy fix it would be great to fix all Node versions at once :)

Ah I see. Yeah sure, I can get that done too 👍

alloy · 2018-09-13T15:04:24Z

src/plugins/http.js

+         * not use externally patched versions, which is why we need to also patch `get` here separately.
+         */
+        patch.call(this, http, 'get', tracer, config)
+      }


@rochdev I tried to scour the Node release notes for when/how this changed by searching for things like ‘module’ and ‘binding’ but came up short. In any case, I tried to describe the behaviour I was able to deduce as well as possible, let me know if you’d like to amend this.

I would probably rephrase it simpler. Something like "Patch http.get as well in Node >=8 since it doesn't call http.request"

Oh but it does https://github.com/nodejs/node/blob/v10.10.0/lib/https.js#L284. It’s just that something changed in Node between v6 and v8 that somehow makes it so that other functions exported from a module (such as get) than the patched function (such as request) still refer to the original unpatched implementation. So get needs to explicitly be patched here to trace it.

I wasn’t able to find anything in the Node changelog, but also didn’t have a great idea of what to search for.

Well, it does call the internal request yes, but it doesn't call http.request.

alloy · 2018-09-13T18:31:14Z

src/plugins/http.js

+      options.headers = options.headers || {}
+      return { uri, options, callback }
+    }
+  }


Did it this way to cut down on runtime work.

I don't think the performance gain of optimizing such an already fast operation warrants increased code complexity. Did you benchmark this?

Nope. I’ll update 👍

rochdev · 2018-09-13T19:32:03Z

src/plugins/http.js

+         * Below Node v9 the `https` module invokes `http.request`, which would end up counting requests twice.
+         * So rather then patch the `https` module, we ensure the `http` module is patched and we count only there.
+         */
+        require('http')


If https requires http, why does it need to be additionally required here?

This is probably related to the change described here
https://github.com/DataDog/dd-trace-js/pull/268/files#r217523774. That is, even though https itself loads http it’s internally still referring to the unpatched version.

So maybe the Node change is that it makes an HTTP request very early on (before even running the user’s code?), before DataDog has the opportunity to patch anything? 🤔

Hmm it should be impossible that it refers to the unpatched version, unless we load http at some other point in the tracer before it's instrumented. This happened with other instrumented modules in the past. In that case the module cache should be wiped before the test. I'll take a look to try and find what could be causing this.

It seems built-in modules are never stored in the cache, so they cannot be wiped. I'm still not 100% comfortable with this solution, but I don't see any other ways either.

I hear you, this type of faffing is why after going down this route the first time I figured to use an approach that did not do conditional patching. But you were right that that made the code a lot more complex.

rochdev · 2018-09-13T19:33:05Z

src/plugins/http.js

+      options.headers = options.headers || {}
+      return { uri, options, callback }
+    }
+  }


I don't think the performance gain of optimizing such an already fast operation warrants increased code complexity. Did you benchmark this?

rochdev · 2018-09-13T19:36:33Z

src/plugins/http.js

+         * not use externally patched versions, which is why we need to also patch `get` here separately.
+         */
+        patch.call(this, http, 'get', tracer, config)
+      }


I would probably rephrase it simpler. Something like "Patch http.get as well in Node >=8 since it doesn't call http.request"

…n-v9

alloy commented Sep 1, 2018

View reviewed changes

[http] Fix repeated traces on Node < v9 when tracing https requests.

1f990c1

alloy force-pushed the fix-http-double-counting-on-node-older-than-v9 branch from e237277 to 1f990c1 Compare September 2, 2018 06:35

alloy mentioned this pull request Sep 2, 2018

[tracer] Further improvements artsy/metaphysics#1261

Merged

rochdev requested changes Sep 4, 2018

View reviewed changes

rochdev added bug Something isn't working community integrations labels Sep 4, 2018

alloy mentioned this pull request Sep 4, 2018

Copyright clarification jfromaniello/selfsigned#28

Closed

[http] Address PR feedback

02d8626

alloy added 2 commits September 13, 2018 15:00

[http] Revert changes to upstream version

cfaead0

[http] Simplify double-counting fix by not patching the https module.

7dd2210

alloy commented Sep 13, 2018

View reviewed changes

alloy added 2 commits September 13, 2018 15:48

[http] Use correct binding for patch closure.

ddfaf05

[http] Only patch get on newer Node versions.

0324cf7

alloy commented Sep 13, 2018

View reviewed changes

[http] Add support for 3 parameter signature in Node v10.

7ff4458

alloy commented Sep 13, 2018

View reviewed changes

rochdev requested changes Sep 13, 2018

View reviewed changes

alloy and others added 2 commits September 13, 2018 22:55

[http] Simplify argument normalization.

93f1f53

Merge branch 'master' into fix-http-double-counting-on-node-older-tha…

2bf6aeb

…n-v9

rochdev approved these changes Sep 14, 2018

View reviewed changes

rochdev merged commit 2d8f49f into DataDog:master Sep 14, 2018

alloy deleted the fix-http-double-counting-on-node-older-than-v9 branch September 17, 2018 12:01

[http] Fix repeated traces on Node < v9 when tracing https requests. #268

[http] Fix repeated traces on Node < v9 when tracing https requests. #268

Conversation

alloy commented Sep 1, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alloy Sep 4, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alloy Sep 5, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rochdev Sep 7, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timrogers commented Sep 5, 2018

alloy commented Sep 6, 2018

timrogers commented Sep 6, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

[http] Fix repeated traces on Node < v9 when tracing `https` requests. #268

[http] Fix repeated traces on Node < v9 when tracing `https` requests. #268

alloy Sep 4, 2018 •

edited

alloy Sep 5, 2018 •

edited

rochdev Sep 7, 2018 •

edited