fix: rewrite ioredis instrumentation: run-context, add destination context, captureError #2460

trentm · 2021-11-19T22:35:56Z

This fixes run-context handling for proper parent/child relationships.
The run-context in code in the same tick and the optional callback are
no longer changed.
Add destination context, so ioredis usage shows redis on the Service Map.
Capture an error and set the span outcome to "failure" if the command
errors.
No longer double-instrument queued ioredis commands.

Checklist

perhaps fix ioredis: offline-queued commands are double-instrumented #2459
Implement code
Add tests
Add CHANGELOG.asciidoc entry
Commit message follows commit guidelines

…ntext, captureError - This fixes run-context handling for proper parent/child relationships. The run-context in code in the same tick and the optional callback are no longer changed. - Add destination context, so ioredis usage shows redis on the Service Map. - Capture an error and set the span outcome to "failure" if the command errors. Refs: #2430

trentm · 2021-11-19T22:39:35Z

This passed a full TAV=ioredis ./node_modules/.bin/tav on my machine using node v12.22.6.

…ongest to run

apmmachine · 2021-11-19T22:57:30Z

💚 Build Succeeded

the below badges are clickable and redirect to their specific view in the CI or DOCS

Expand to view the summary

Build stats

Start Time: 2021-11-24T18:01:03.525+0000
Duration: 20 min 49 sec
Commit: f63efc0

Test stats 🧪

Test	Results
Failed	0
Passed	22
Skipped	0
Total	22

🤖 GitHub comments

To re-run your PR in the CI, just comment with:

/test : Re-trigger the build.
run module tests for <modules> : Run TAV tests for one or more modules, where <modules> can be either a comma separated list of modules (e.g. memcached,redis) or the string literal ALL to test all modules
run benchmark tests : Run the benchmark test only.
run elasticsearch-ci/docs : Re-trigger the docs validation. (use unformatted text in the comment!)

Fixes: #2459

trentm · 2021-11-20T01:21:58Z

lib/instrumentation/modules/ioredis.js

-  agent.logger.debug('shimming ioredis.Command.prototype.initPromise')
-  shimmer.wrap(ioredis.Command && ioredis.Command.prototype, 'initPromise', wrapInitPromise)
-
-  if (!enabled) return ioredis


REVIEW NOTE: This update of the ioredis instrumentation no longer wraps Command.prototype.initPromise; it still wraps Redis.prototype.sendCommand. The only utility of having wrapped initPromise before was something about "continuation patches" that may have been necessary in the past. This is why the previous instrumentation still wrapped initPromise even if enabled=false (from disableInstrumentations use). I believe this is no longer necessary after the run-context work. See #2444 (a draft PR where I intend to remove this "half-disabling" of instrumentations) for some more discussion.

I believe this is no longer necessary after the run-context work.

Does remove the initPromise wrapping have any effect on the spans/span-tree if someone's using the patch-async /asyncHooks:false? If so are you OK with changing that functionality and/or should we mention it somewhere?

Does remove the initPromise wrapping have any effect on the spans/span-tree if someone's using the patch-async /asyncHooks:false?

No, I don't believe it has any effect. The removed wrappedInitPromise didn't do any promise-y context propagation or binding. My quoting of "continuation patches" was from this single comment on the change that added the "enabled" flag to instrumentations: #353 (comment) It provides no more details.

The test suite passes with asyncHooks: false. Also the parent/child output from ELASTIC_APM_ASYNC_HOOKS=false node examples/trace-ioredis.js is as expected:

transaction 035eaa "t1" `- span 46aff5 "SET" `- span 4824ad "GET" `- span 77b874 "GET" `- span 0d4192 "MULTI" `- span 537be3 "SET" `- span 35b9c7 "GET" `- span 3a4fa9 "EXEC" `- span 6610bb "HSET" `- span 21c383 "GET" `- error 579426 "WRONGTYPE Operation against a key holding the wrong kind of value"

trentm · 2021-11-20T01:30:47Z

lib/instrumentation/modules/ioredis.js

-  // wrappedSendCommand, but the finally call will not get fired until the tick
-  // after the command.callback have fired, so if the transaction is ended in
-  // the same tick as the call to command.callback, we'll lose the last span
-  // as it hasn't yet ended.


REVIEW NOTE: In ioredis, sendCommand(cmd) is called with a Command object that always has a .promise and can optionally have a user-supplied .callback function. When the command is complete: (a) the callback is called, if any, and (b) the promise is resolved or rejected. Because this is a Promise that resolve/reject is in the next tick.

A change this update makes is to only instrument the promise. The code before this would instrument both, and span.end() on the first one. This means that a slight behaviour change with this update is that when a user-supplied callback is called, then span is not yet ended. It will be ended in the next tick with the promise. Not that the run-context fixes in this change mean that the span is intentionally not the currentSpan in the user-callback, so the slight change on end time doesn't have any impact that I can see.

The comment above about "we'll lose the last span" is wrong: the Elastic APM system can handle a trace with a span ending after the transaction ends just fine. It looks like this:

I like that the code is less complex: only needing to command.promise.then() to handle span.end().

trentm · 2021-11-20T01:31:40Z

test/instrumentation/modules/ioredis.test.js

    setTimeout(function () {
      t.notOk(unhandledRejection)
      t.end()
    }, 0)
  })
-  agent.captureError = function (err) { throw err }


REVIEW NOTE: This and the agent.captureError = override below were removed because they conflict with testing now that the ioredis instrumentation is actually using agent.captureError().

…to the span (i.e. it is a child of the span). Before this it was setting parent_id to the *transaction*.

astorm

Generally looks ok -- does what it says on the tin. One question below before signing off.

astorm · 2021-11-23T18:50:52Z

lib/instrumentation/modules/ioredis.js

-  agent.logger.debug('shimming ioredis.Command.prototype.initPromise')
-  shimmer.wrap(ioredis.Command && ioredis.Command.prototype, 'initPromise', wrapInitPromise)
-
-  if (!enabled) return ioredis


I believe this is no longer necessary after the run-context work.

Does remove the initPromise wrapping have any effect on the spans/span-tree if someone's using the patch-async /asyncHooks:false? If so are you OK with changing that functionality and/or should we mention it somewhere?

astorm

👍 approving.

trentm self-assigned this Nov 19, 2021

github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Nov 19, 2021

limit the number of ioredis versions tested, it is one of the top 5 l…

c8c4046

…ongest to run

fix: no longer double-instrument queued ioredis commands

809ba6a

Fixes: #2459

changelog entry

1b878c7

trentm mentioned this pull request Nov 20, 2021

ioredis: offline-queued commands are double-instrumented #2459

Closed

trentm marked this pull request as ready for review November 20, 2021 01:09

trentm requested a review from astorm November 20, 2021 01:09

trentm commented Nov 20, 2021

View reviewed changes

trentm mentioned this pull request Nov 20, 2021

run-context for spans created by instrumentations should not bleed out to user code #2430

Closed

38 tasks

Ensure that the error captured for an ioredis span has parent_id set …

488780a

…to the span (i.e. it is a child of the span). Before this it was setting parent_id to the *transaction*.

astorm reviewed Nov 23, 2021

View reviewed changes

trentm requested a review from astorm November 23, 2021 21:49

trentm added 3 commits November 24, 2021 09:41

Merge branch 'master' into trentm/run-context-ioredis

110e17f

Merge branch 'master' into trentm/run-context-ioredis

2b015bb

fix changelog after merge from master

f63efc0

astorm approved these changes Nov 24, 2021

View reviewed changes

trentm merged commit 1ed110e into master Nov 24, 2021

trentm deleted the trentm/run-context-ioredis branch November 24, 2021 23:45

trentm mentioned this pull request Dec 1, 2021

fix: ensure correct run context for mysql2 instrumentation #2487

Merged

3 tasks

trentm mentioned this pull request Jul 26, 2022

"ioredis" module instrumentation is missing "destination" context #1896

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: rewrite ioredis instrumentation: run-context, add destination context, captureError #2460

fix: rewrite ioredis instrumentation: run-context, add destination context, captureError #2460

trentm commented Nov 19, 2021 •

edited

Loading

trentm commented Nov 19, 2021 •

edited

Loading

apmmachine commented Nov 19, 2021 •

edited

Loading

Build stats

Test stats 🧪

trentm Nov 20, 2021

astorm Nov 23, 2021

trentm Nov 23, 2021

astorm Nov 24, 2021

trentm Nov 20, 2021

trentm Nov 20, 2021

astorm left a comment

astorm Nov 23, 2021

astorm left a comment

fix: rewrite ioredis instrumentation: run-context, add destination context, captureError #2460

fix: rewrite ioredis instrumentation: run-context, add destination context, captureError #2460

Conversation

trentm commented Nov 19, 2021 • edited Loading

Checklist

trentm commented Nov 19, 2021 • edited Loading

apmmachine commented Nov 19, 2021 • edited Loading

💚 Build Succeeded

Build stats

Test stats 🧪

🤖 GitHub comments

trentm Nov 20, 2021

Choose a reason for hiding this comment

astorm Nov 23, 2021

Choose a reason for hiding this comment

trentm Nov 23, 2021

Choose a reason for hiding this comment

astorm Nov 24, 2021

Choose a reason for hiding this comment

trentm Nov 20, 2021

Choose a reason for hiding this comment

trentm Nov 20, 2021

Choose a reason for hiding this comment

astorm left a comment

Choose a reason for hiding this comment

astorm Nov 23, 2021

Choose a reason for hiding this comment

astorm left a comment

Choose a reason for hiding this comment

trentm commented Nov 19, 2021 •

edited

Loading

trentm commented Nov 19, 2021 •

edited

Loading

apmmachine commented Nov 19, 2021 •

edited

Loading