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

Spans not sent if span is dropped manually or exec is called? #647

Open
zmitchell opened this issue Mar 21, 2024 · 2 comments
Open

Spans not sent if span is dropped manually or exec is called? #647

zmitchell opened this issue Mar 21, 2024 · 2 comments

Comments

@zmitchell
Copy link
Contributor

Environment

What version are you running? Etc.

  • Environment: SaaS, sentry.io
  • OS: macOS (not tested on others)
  • Version: 0.32.2, tracing feature enabled

Steps to Reproduce

This code is open source, so you can peek through it.

  1. I've used the tracing::instrument macro to instrument different commands in our CLI. Here's an example of a working command (install command).
  2. For our "activate" command we either print a script for the shell to source, or we exec a user's shell.
  3. Thinking that I didn't want to record time spent inside a user's shell, I thought that rather than using the instrument macro I would create a span manually so that I could drop it at the appropriate time.
  4. I do that here: activate command.
  5. No spans are sent for this command, unexpectedly.
  6. In a local checkout I've also tried switching back to the instrument macro in case there's some cleanup that I'm not performing (I also removed the manual drops), but there are still no spans sent for this command. I'm thinking that somehow a transaction isn't getting finished?
  7. I'm able to see the tracing logs in my terminal, so the activate span is getting created, but it's not getting reported.

Expected Result

I would expect spans to be reported for this command like all the others.

Actual Result

Sentry is initialized:

2024-03-21T21:08:25.972199Z DEBUG flox::utils::init::sentry: Initializing Sentry with DSN: <DSN>
2024-03-21T21:08:25.975892Z DEBUG sentry: enabled sentry client for DSN <DSN>

For commands that do work you later see logs like this:

2024-03-21T21:32:21.223920Z DEBUG sentry: dropping client guard -> disposing client
2024-03-21T21:32:21.224003Z DEBUG sentry: client close; request transport to shut down
...hyper/reqwest logs
2024-03-21T21:32:21.401103Z DEBUG sentry: Get response: `{"id":"1965f0595eba42109a6d6cca86bfb0ad"}`

For this activate command the second set of logs is missing.

@Swatinem
Copy link
Member

I think the problem here is that you are using exec.
Per documentation, this function never returns, and the docs also state that this means no destructors (guards) are run:
https://doc.rust-lang.org/std/os/unix/process/trait.CommandExt.html#tymethod.exec
AFAIK, execvp just replaces the current process with another one. So the original process does not exist anymore as such, and there is no way to flush anything afterwards.

I believe you have three choices to go from here:

  1. Spawn the shell as a child process, so you can both time it properly and flush the spans. The disadvantage is that the parent runs for the whole duration of the child.
  2. Spawn the shell as a child process and detach it from its parent, so the parent can flush the spans and then exit to not waste resources.
  3. Flush the span before calling exec. Disadvantage is that you now have a potentially slow flush operation in your critical path.

I believe 2. provides the best tradeoffs here, but the choice is yours :-)

@zmitchell
Copy link
Contributor Author

Unfortunately we need to call exec there. I've tried calling flush via Hub->get the client (current and main)->flush and that didn't do the trick. Is there some other way to flush the span?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants