Migrate to universal context local storage #14

pglombardo · 2017-11-02T08:52:39Z

This PR updates the sensor to use the cls-hooked package which supports both older and the most recent versions of Node.

- Unified context & span concepts under 'span' only - Span creation now done in cls module; less/more centralized/consistent code - Instrumentation code is now more concise - No longer need to track the destroy of old uid/contexts - `cls.startSpan(spanName, traceId, spanId)` - start new span in this context - `cls.getCurrentSpan()` - get current in this context - `cls.isTracing()` - returns boolean if we have a current span - Update instrumentation to use new exports - Revamp cls tests - Store per request tracing level in request context (with cls exports to access) - `cls.setTracingLevel(level)` - to set the level - `cls.tracingLevel()` - to access the level - `cls.tracingSuppressed()` - boolean return; false if 0; true otherwise - Keep a registry of exit span types and offer function to query spans - `cls.isExitSpan(span)` - boolean return if this span is an exit span

pglombardo · 2017-11-12T16:47:17Z

PR summary in 6caa0ca but I'll re-post here:

Cleaner, leaner & meaner CLS implementation

Unified context & span concepts under 'span' only
- Span creation now done in cls module
- More centralized/consistent code
- Instrumentation code is now more concise
- No longer need to track the destroy of old uid/contexts
- cls.startSpan(spanName, traceId, spanId) - start new span in this context
- cls.getCurrentSpan() - get current span in this context
- cls.isTracing() - returns boolean if we have a current span
Update instrumentation to use new exports
Revamp cls tests
Store per request tracing level in request context (with cls exports to access)
- cls.setTracingLevel(level) - to set the level
- cls.tracingLevel() - to access the level
- cls.tracingSuppressed() - boolean return; false if 0; true otherwise
Keep a registry of exit span types and offer function to query spans
- cls.isExitSpan(span) - boolean return if this span is an exit span

bripkens

Damn @pglombardo, this is looking really, really good! I just have a bunch of small remarks.

bripkens · 2017-11-13T10:32:05Z

.eslintrc

+ env:
+ node: true
+ mocha: true
+ es6: true


We aren't using any es6 features besides lambdas and retaining some basic Node.js 0.12 support is also good. Hence I would say let's please disable es6

bripkens · 2017-11-13T10:32:36Z

.eslintrc

@@ -1,16 +1,29 @@
 ---
 extends: airbnb/legacy
+ env:
+ node: true
+ mocha: true


Enabling mocha globally has unintended side effects, e.g. it registering some globals that we do not want. Please disable it.

bripkens · 2017-11-13T10:32:53Z

.eslintrc

 rules:
+ no-shadow: 0
+ require-yield: 0


Why did you disable all these rules?

bripkens · 2017-11-13T10:37:48Z

src/tracing/cls.js

+ */
+var exitSpans = ['node.http.client', 'elasticsearch', 'mongo', 'mysql'];
+exports.isExitSpan = function isExitSpan(span) {
+ return (exitSpans.indexOf(span.n) > -1);


How about we start reporting the k field as part of the span? Values would be:

1: Entry

2: Exit

3: Intermediate, local

This check would then be really simple :).

I'm not sure if I understand this @bripkens. We have a type field for SDK spans but a k field?

Added in 08e90c5

bripkens · 2017-11-13T10:39:07Z

src/tracing/index.js

@@ -21,7 +21,7 @@ exports.init = function(_config) {
 require('./opentracing').init(config, automaticTracingEnabled);

 if (automaticTracingEnabled) {
- require('./hook').init(config);
+ require('./cls');


Why is it required if it doesn't need any initialization? As far as I can tell, requiring the module has no side effects, so this line can be removed.

bripkens · 2017-11-13T10:54:28Z

src/tracing/instrumentation/httpServer.js

@@ -97,7 +83,7 @@ function getExistingSpanId(req, fallback) {
 fallback = arguments.length > 1 ? fallback : null;

 var spanId = req.headers[tracingConstants.spanIdHeaderNameLowerCase];
- if (spanId == null) {
+ if (spanId === null) {


Checking with eqeqeq will not respect undefined. Was this intentional?

bripkens · 2017-11-13T10:54:32Z

src/tracing/instrumentation/httpServer.js

@@ -109,7 +95,7 @@ function getExistingTraceId(req, fallback) {
 fallback = arguments.length > 1 ? fallback : null;

 var traceId = req.headers[tracingConstants.traceIdHeaderNameLowerCase];
- if (traceId == null) {
+ if (traceId === null) {


Checking with eqeqeq will not respect undefined. Was this intentional?

bripkens · 2017-11-13T10:57:33Z

src/tracing/instrumentation/httpClient.js

- clientRequest.setHeader(tracingConstants.spanIdHeaderName, span.s);
- clientRequest.setHeader(tracingConstants.traceIdHeaderName, span.t);
- clientRequest.setHeader(tracingConstants.traceLevelHeaderName, '1');
+ cls.ns.run(() => {


We should avoid ES6 features for the sake of supporting Node.js 0.12 as mentioned above

bripkens · 2017-11-13T10:57:41Z

src/tracing/instrumentation/httpServer.js

 };

+function shimEmit(realEmit) {
+ return function(type, req, res) {
+ return cls.ns.runAndReturn(() => {


We should avoid ES6 features for the sake of supporting Node.js 0.12 as mentioned above

bripkens · 2017-11-13T10:57:45Z

src/tracing/instrumentation/kafka.js

- access: 'consume',
- service: message.topic
- }
+ cls.ns.runAndReturn(() => {


We should avoid ES6 features for the sake of supporting Node.js 0.12 as mentioned above

bripkens · 2017-11-13T13:26:31Z

src/tracing/cls.js

+var hooked = require('cls-hooked');
+var currentSpanKey = 'csKey';
+
+var exitSpans = ['node.http.client', 'elasticsearch', 'mongo', 'mysql'];


My intention was that instrumentations will set it themselves and that we therefore do not need such a list. Is this not possible?

I did it this way in Ruby which is why I made an assumption. I suppose we could instead add the span.k assignment in each instrumentation code directly but the intention was to simplify instrumentation by moving all the span creation details into CLS.

If you have a strong preference I can change it. Otherwise let's leave it and I'll revisit it on my next run through the code. lmk

Here are two coredumps that were were created on CircleCI under Node.js 8: (lldb) bt * thread #1: tid = 0, 0x0000000000915192 node`node::http2::Http2Session::ClearOutgoing(int) + 178, name = 'node', stop reason = signal SIGSEGV * frame #0: 0x0000000000915192 node`node::http2::Http2Session::ClearOutgoing(int) + 178 frame #1: 0x0000000000916047 node`node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) + 39 frame #2: 0x0000000000950ee0 node`node::StreamBase::AfterWrite(node::WriteWrap*, int) + 160 frame #3: 0x000000000099f161 node`node::TLSWrap::InvokeQueued(int, char const*) + 193 frame #4: 0x00000000009a01a8 node`node::TLSWrap::EncOut() + 232 frame #5: 0x00000000009a0bfd node`node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) + 125 frame #6: 0x0000000000950ee0 node`node::StreamBase::AfterWrite(node::WriteWrap*, int) + 160 frame #7: 0x000000000095517b node`node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) + 27 frame #8: 0x0000000000955dc4 node`node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) + 84 frame #9: 0x00000000009c5129 node`uv__write_callbacks(stream=0x00000000041b05b8) + 265 at stream.c:976 frame #10: 0x00000000009c6358 node`uv__stream_destroy(stream=0x00000000041b05b8) + 200 at stream.c:461 frame #11: 0x00000000009bb34a node`uv_run + 8 at core.c:272 frame #12: 0x00000000009bb342 node`uv_run + 277 at core.c:302 frame #13: 0x00000000009bb22d node`uv_run(loop=0x000000000218cda0, mode=UV_RUN_DEFAULT) + 413 at core.c:372 frame #14: 0x00000000008d6b65 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 1205 frame #15: 0x00000000008d5da0 node`node::Start(int, char**) + 352 frame #16: 0x00007fd77d7ed2e1 libc.so.6`__libc_start_main + 241 frame #17: 0x000000000089f601 node`_start + 41 (lldb) bt * thread #1: tid = 0, 0x0000000002c198e0, name = 'node', stop reason = signal SIGSEGV * frame #0: 0x0000000002c198e0 frame #1: 0x0000000000916047 node`node::http2::Http2Session::OnStreamAfterWriteImpl(node::WriteWrap*, int, void*) + 39 frame #2: 0x0000000000950ee0 node`node::StreamBase::AfterWrite(node::WriteWrap*, int) + 160 frame #3: 0x000000000099f161 node`node::TLSWrap::InvokeQueued(int, char const*) + 193 frame #4: 0x00000000009a01a8 node`node::TLSWrap::EncOut() + 232 frame #5: 0x00000000009a0bfd node`node::TLSWrap::OnAfterWriteImpl(node::WriteWrap*, int, void*) + 125 frame #6: 0x0000000000950ee0 node`node::StreamBase::AfterWrite(node::WriteWrap*, int) + 160 frame #7: 0x000000000095517b node`node::LibuvStreamWrap::AfterWrite(node::WriteWrap*, int) + 27 frame #8: 0x0000000000955dc4 node`node::LibuvStreamWrap::AfterUvWrite(uv_write_s*, int) + 84 frame #9: 0x00000000009c5129 node`uv__write_callbacks(stream=0x0000000002d70078) + 265 at stream.c:976 frame #10: 0x00000000009c6358 node`uv__stream_destroy(stream=0x0000000002d70078) + 200 at stream.c:461 frame #11: 0x00000000009bb34a node`uv_run + 8 at core.c:272 frame #12: 0x00000000009bb342 node`uv_run + 277 at core.c:302 frame #13: 0x00000000009bb22d node`uv_run(loop=0x000000000218cda0, mode=UV_RUN_DEFAULT) + 413 at core.c:372 frame #14: 0x00000000008d6b65 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 1205 frame #15: 0x00000000008d5da0 node`node::Start(int, char**) + 352 frame #16: 0x00007fde4be1a2e1 libc.so.6`__libc_start_main + 241 frame #17: 0x000000000089f601 node`_start + 41

# This is the 1st commit message: Added basic test apps # This is the commit message #2: improved test app a little bit # This is the commit message #3: more refactoring; wip: process, concurrency named process in test app # This is the commit message #4: added consumer as process # This is the commit message #5: wip: in the middle of another refactoring # This is the commit message #6: test app covers all 12 cases # This is the commit message #7: started instrumentation # This is the commit message #8: wip: instrumenting add() function # This is the commit message #9: wip: dealing with repeatable jobs # This is the commit message #10: Using repeat with limit. avoid using cron # This is the commit message #11: added bulk job sending # This is the commit message #12: small refactoring in sender test app # This is the commit message #13: exit span instrumented for single and repeatable jobs # This is the commit message #14: wip: bulk immediate jobs [skip ci] # This is the commit message #15: wip: testing the instrumentation of bulk > send job [skip ci] # This is the commit message #16: complete instrumentation of exit spans # This is the commit message #17: docs(changelog): prepare release 1.117.0 [skip ci] # This is the commit message #18: v1.117.0 # This is the commit message #19: fix: bypass native addon loading in worker threads Co-authored-by: Willian Carvalho <willian.carvalho@instana.com> # This is the commit message #20: docs(changelog): prepare release 1.117.1 [skip ci] # This is the commit message #21: v1.117.1 # This is the commit message #22: test(tracing): make batching test less flaky # This is the commit message #23: chore: add script for splitting CI output according to package [skip ci] # This is the commit message #24: fix: update to shimmer@1.2.1 to be able to patch async functions Specifically, that version includes this fix: othiym23/shimmer@ec15ba2 # This is the commit message #25: test(tracing): fix path for custom tags # This is the commit message #26: wip: added ENTRY span instrumentation # This is the commit message #27: renamed child process.js; removed extra execTime param from /POST; added client HTTP call # This is the commit message #28: immediate and repeatable jobs instrumented correctly [skip ci] # This is the commit message #29: small refactoring/cleanup; [skip ci] # This is the commit message #30: introduced tests [skip ci] # This is the commit message #31: Included test for Callback x Bulk [skip ci] # This is the commit message #32: wip: attempting to instrument master.js [skip ci] # This is the commit message #33: instrument child process with an extra entry span # This is the commit message #34: experimental: activate tracing immediately, without waiting for connection to agent # This is the commit message #35: send spans directly from Bull child process workers and wait for them to be offloaded # This is the commit message #36: fix linting issues # This is the commit message #37: Updating agent uuid from env var info [skip ci] # This is the commit message #38: fixed PID casting to string [skip ci] # This is the commit message #39: no more IPC, write to a file instead # This is the commit message #40: attach trace context to each individual IPC message instead of env var at process start # This is the commit message #41: avoid duplicated bull entry span # This is the commit message #42: fixed naming convention; replaced fs/promises by fs; guarantee that opts object exists # This is the commit message #43: added disabled trace tests # This is the commit message #44: lift the requirement for applying span.disableAutoEnd/span.end() # This is the commit message #45: Running tests for trace disabled and suppressed # This is the commit message #46: all instana data is removed before customer gets the processed job data # This is the commit message #47: Added test to make sure no Instana data is left in Job data # This is the commit message #48: Added withError cases # This is the commit message #49: Skipping tests for Node version < 10 # This is the commit message #50: fix(opentracing): default to type entry when no parent is referenced # This is the commit message #51: docs(changelog): prepare release 1.117.2 [skip ci] # This is the commit message #52: v1.117.2 # This is the commit message #53: fix(metrics): register gc stats loader listener immediately This fixes an issue where GC metrics would not be available when the dependency gcstats.js was already present in node_modules and the activation of the gc metrics module would happen too late. # This is the commit message #54: docs(changelog): prepare release 1.117.3 [skip ci] # This is the commit message #55: v1.117.3 # This is the commit message #56: docs(contributing): document the need to install PostgreSQL headers (Only required for local development.) Plus: Additional info about rate limited OTP when publishing. [skip ci]

pglombardo added 22 commits November 2, 2017 00:41

Switch to use cls-hooked instead of async-wrap

1b1c908

New CLS implementation useing cls-hooked.

6c38a8c

Remove node version limiter checks

14c9b0f

Update to use new CLS strategy.

548647b

Remove backup file.

1ebb911

Update to use new CLS implementation.

3596d5d

New context local storage tests.

86a9dea

New reset function for tests; lower logging to debug level.

e0b235c

Update to use new CLS implementation.

7f50c39

Save context on creation; add contextExistsByUid function

2f93a0c

Add tests for contextExistsByUid

876632d

Update to use new CLS implementation.

44580fa

Linter peace & happiness ☮️

2d739a2

Cleanup & slightly more robust http instrumentation.

0386bd8

supportsAsyncWrap is now supportedVersion

937f45e

Add helper functions: createAndSetActiveContext & isTracing

fafb80c

Remove "only" remnant

acf00fa

Fixed & simplified Mysql instrumentation

75afead

Use original function arguments; re-org & cleanup

dc6d5d4

Use original arguments.

207c0a7

Linter changes & updates

14ef844

Run message processing in context.

37c6b33

bripkens suggested changes Nov 13, 2017

View reviewed changes

pglombardo added 5 commits November 13, 2017 12:22

Update settings per feedback.

cf3ef11

Remove unnecessary require.

ab9d9f4

Don't change the call context.

1d71fdb

Remove remnant debugger log lines.

a7f7376

Use double equal operator.

933a2e0

pglombardo added 2 commits November 13, 2017 14:00

Avoid ES6 features to maintain 0.12 support.

b287466

Report k field and add/update helpers.

08e90c5

bripkens reviewed Nov 13, 2017

View reviewed changes

pglombardo added 2 commits November 13, 2017 14:39

Remove trailing blank lines to appease Mr. Linter.

239552b

Report k as integer, not string

d8eb1cd

bripkens merged commit 5dbf7ab into master Nov 13, 2017

bripkens deleted the cls branch November 13, 2017 15:57

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Migrate to universal context local storage #14

Migrate to universal context local storage #14

pglombardo commented Nov 2, 2017 •

edited

Loading

pglombardo commented Nov 12, 2017 •

edited

Loading

bripkens left a comment

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

pglombardo Nov 13, 2017

pglombardo Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

bripkens Nov 13, 2017

pglombardo Nov 13, 2017

Migrate to universal context local storage #14

Migrate to universal context local storage #14

Conversation

pglombardo commented Nov 2, 2017 • edited Loading

pglombardo commented Nov 12, 2017 • edited Loading

bripkens left a 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

pglombardo commented Nov 2, 2017 •

edited

Loading

pglombardo commented Nov 12, 2017 •

edited

Loading