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

startSpan('A'); startSpan('B') in the same async op: B should be a child of A, but isn't #1889

Closed
4 tasks
trentm opened this issue Nov 25, 2020 · 1 comment
Closed
4 tasks
Assignees
Labels
agent-nodejs Make available for APM Agents project planning.
Milestone

Comments

@trentm
Copy link
Member

trentm commented Nov 25, 2020

If you start a span (B) in the same async operation as a preceding span (A), the current agent (v3.8.0) will make A and B siblings. I think B should be a child span of A.

If you'd like to test your own expectations, here is a sort of survey: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536

Works as expected: each span in separate async ops

The common case (at least I assume) in node.js is that code significant enough to be a traced span are in separate async ops on the node.js event loop. E.g.:

app.get('/my-endpoint', (req, res) => {
  var A = apm.startSpan('this is span A')
  setTimeout(function () {
    var B = apm.startSpan('this is span B')
    setTimeout(function () {
      B.end()
      A.end()
    }, 10)
  }, 10)
})

For this case, the APM agent generates a trace like this (where indentation denotes a parent/child relationship):

- transaction: GET /my-endpoint
    - span: this is span A
        - span: this is span B

This works as I'd expect.

The contested case: multiple spans started in the same async op

app.get('/my-endpoint', (req, res) => {
  var A = apm.startSpan('this is span A')

  var B = apm.startSpan('this is span B')
  B.end()

  A.end()
})

For this code, the current APM agent generates a trace like this:

- transaction: GET /my-endpoint
    - span: this is span A
    - span: this is span B

I think this is a bug, or at least should be considered. My expectation for the above code is a trace like this:

- transaction: GET /my-endpoint
    - span: this is span A
        - span: this is span B

The patch

If you want to try it out, here is a patch to lib/instrumentation/index.js that changes to my expected behaviour: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536#file-the-diff
I'll start a draft PR in a little bit with that.

Proposal

  • Get a feel for the test suite fall out.
  • Discuss with others whether their expectations are the same (so far it is just @astorm and I).
  • Try to come up with counter examples where the current behaviour is preferred.
  • If considering changing this behaviour, do we consider it a breaking changing? I'm not aware of specific documentation on this scenario, but I haven't looked very hard. The patch does result in at least a few failing tests.
@trentm trentm self-assigned this Nov 25, 2020
@github-actions github-actions bot added the agent-nodejs Make available for APM Agents project planning. label Nov 25, 2020
trentm added a commit that referenced this issue Nov 25, 2020
This commit is just a start. There are still tests and discussion to be
had.

Fixes #1889
@trentm trentm added this to the next-major milestone Dec 18, 2020
@trentm
Copy link
Member Author

trentm commented Dec 18, 2020

User evidence supporting this ticket:

Dario
I also don’t fully understand why sometimes there is a parent-child relationship between spans and sometimes there isn’t. it seems kind of random?

Dario
if I await Promise.resolve() after creating a span and calling client.search, a parent-child relationship is created between the span I created and the HTTP/ES spans. 

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
agent-nodejs Make available for APM Agents project planning.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant