Logs and errors are not showing up in web interface

Question

Logs and errors are not showing up in web interface

connormullett opened this issue a year ago · 26 comments

Environment

sentry version "0.30.0" with feature "anyhow" enabled
sentry-log "0.31.5"

Steps to Reproduce

early in main.rs

  let logger = sentry_log::SentryLogger::with_dest(env_logger::builder().build());

  log::set_boxed_logger(Box::new(logger)).unwrap();
  log::set_max_level(secrets.log_level.clone().into());

  let _guard = sentry::init((
      "my dsn",
      ClientOptions {
          release: sentry::release_name!(),
          environment: Some(secrets.environment.to_string().into()),
          sample_rate: secrets.sentry_sample_rate.parse::<f32>().unwrap_or(0.0),
          ..Default::default()
      },
  ));

in cargo.toml

sentry = { version = "0.30.0", features = ["anyhow"] }
sentry-log = "0.31.5"

using the normal log macros ( info!(), warn!(), error!() ), we're not seeing these errors appear in sentry. Instead, we've been using the capture_anyhow!() macro however the insights we get aren't the best causing debugging issues to be very slow. I've seen mixing documentation or lack thereof around integrations regarding this crate but nothing I've tried seemed to resolve this. We know errors are occurring because of logs in production. The implementation above is from the example on docs.rs, perhaps this should be updated?

Expected Result

We see errors and breadcrumbs appear in sentry when they occur.

Actual Result

Errors aren't appearing in sentry

Answer 1 · 2023-08-14T10:56:44.000Z

Thank you for the report, we will look into it as soon as possible.

Answer 2 · 2023-08-14T14:44:02.000Z

Is the code excerpt from your main function? Are you using #[tokio::main] or something similar?

Answer 3 · 2023-08-14T15:43:35.000Z

yes, we are using tokio

Answer 4 · 2023-08-14T20:17:09.000Z

Is the code excerpt from your main function? Are you using #[tokio::main] or something similar?

just to further clarify for additional help. This is from main and we are using tokio::main to init the runtime. The only code that runs prior to the initial sentry configuration is fetching our secrets (so we can configure sentry programmatically). The guard stays in scope for the entire lifetime of the application. Main proceeds to call another function that starts up the rest of the application.

Due to our code not being opensource I'm unable to share snippets beyond our sentry configuration

Answer 5 · 2023-08-16T07:09:41.000Z

Using #[tokio::main] may be the issue. We're currently updating our documentation to explain why that shouldn't be done and what to do instead. The problem is that sentry::init must be called before the async runtime is started, but #[tokio::main] prevents that.

Can you rewrite main to a form like this?

fn main() {
  let _guard = sentry::init((
      "my dsn",
      ClientOptions {
          release: sentry::release_name!(),
          environment: Some(secrets.environment.to_string().into()),
          sample_rate: secrets.sentry_sample_rate.parse::<f32>().unwrap_or(0.0),
          ..Default::default()
      },
  ));

  let logger = sentry_log::SentryLogger::with_dest(env_logger::builder().build());

  log::set_boxed_logger(Box::new(logger)).unwrap();
  log::set_max_level(secrets.log_level.clone().into());

  tokio::runtime::Builder::new_multi_thread()
        .enable_all()
        .build()
        .unwrap()
        .block_on(async {
            // the rest of main
        });
}

Answer 6 · 2023-08-16T13:52:59.000Z

This might be problematic as the way we fetch secrets needs to be async as we are leveraging a library that uses async/await. In the past we've solved this with block_on however this seems to be causing more issues when I remove the tokio::main macro.

thread 'main' panicked at 'there is no reactor running, must be called from the context of a Tokio 1.x runtime'

So now we have an issue where we can't use a macro to start the tokio runtime, but we need the tokio runtime before we fetch secrets to pass them to sentry..

Answer 7 · 2023-08-16T13:55:19.000Z

Can you extract your business logic (whatever follows sentry::init) into an async function and call it from main?

Answer 8 · 2023-08-16T13:56:42.000Z

we're already doing that for the most part. Main fetches secrets, starts sentry, initializes some dependencies, and calls an async start_xxx function which contains the core logic

Everything after sentry init is now wrapped in the runtime you provided above, which compiles, but panics at runtime with the error above in the logic that fetches our secrets to initialize sentry

Answer 9 · 2023-09-01T17:33:10.000Z

revisiting as issue still isn't resolved. @loewenheim I have implemented main as you have stated and extracted the rest of the logic after sentry configuration into start. Main now looks like the following without #[tokio::main]

fn main() {
    let secrets = secrets::fetch();

    env_logger::builder()
        .filter_level(secrets.log_level.clone().into())
        .init();

    let _guard = sentry::init((
        "redacted dsn",
        ClientOptions {
            release: sentry::release_name!(),
            environment: Some(secrets.environment.to_string().into()),
            sample_rate: secrets.sentry_sample_rate.parse::<f32>().unwrap_or(0.0),
            ..Default::default()
        },
    ));

    sentry::configure_scope(|scope| {
        scope.set_tag("redacted key", "redacted value")
    });

    _ = tokio::runtime::Builder::new_multi_thread()
        .enable_all()
        .build()
        .unwrap()
        .block_on(async { start(&secrets).await });
}

Issue still occurs. At the beginning of start() I have added an info, warn, and error log but do not show up in sentry.

Answer 10 · 2023-09-04T11:31:54.000Z

Do you have any debug-level logs of your app?

Answer 11 · 2023-09-04T11:33:47.000Z

Specifically, logs of Sentry when running with the debug: true option.

Answer 12 · 2023-09-05T13:41:43.000Z

With debug true and start() only containing the following code

async fn start(secrets: &VaultSecrets) {
    info!("this should be a breadcrumb");
    warn!("testing rust sentry runtime");
    error!("testing rust sentry runtime");
}

outputs:

[sentry] enabled sentry client for DSN <correct dsn>
[2023-09-05T13:40:01Z INFO  redacted] this should be a breadcrumb
[2023-09-05T13:40:01Z WARN  redacted] testing rust sentry runtime
[2023-09-05T13:40:01Z ERROR redacted] testing rust sentry runtime
[sentry] dropping client guard -> disposing client
[sentry] client close; request transport to shut down

Answer 13 · 2023-09-06T09:45:49.000Z

Indeed the SDK does not report any attempt to capture / send an event.

To further narrow this problem down, can you:

use both tracing::error! as well as sentry::capture_message, to know if there is an issue with the tracing integration, or if we have a problem with normal event sending.
do both also before starting the async runtime.

I see you are using sample_rate: secrets.sentry_sample_rate.parse::<f32>().unwrap_or(0.0),. Are you absolutely certain you are actually sampling some events? If in doubt, please remove that explicit setting so we are confident that the SDK is capturing all events.

Answer 14 · 2023-09-06T13:39:45.000Z

I see you are using sample_rate: secrets.sentry_sample_rate.parse::<f32>().unwrap_or(0.0),. Are you absolutely certain you are actually sampling some events? If in doubt, please remove that explicit setting so we are confident that the SDK is capturing all events.

The code that fetches these values is tested pretty thoroughly and is running in our production environment, but for sanity checking, I've replaced this with 1.0. The default of 0.0 doesnt make sense here.

use both tracing::error!

We're not using tracing (yet), we are using env_logger per the crate documentation. Could this be the reason? I've also added the capture_message and those appear in sentry before and after the runtime is initialized. We have known this works since we are using the anyhow integration.

Here's the output from the run with the new logs

[2023-09-06T13:35:15Z ERROR] testing sentry error before tokio runtime
[2023-09-06T13:35:15Z INFO] this should be a breadcrumb
[2023-09-06T13:35:15Z WARN] testing rust sentry runtime
[2023-09-06T13:35:15Z ERROR] testing rust sentry runtime
[sentry] dropping client guard -> disposing client
[sentry] client close; request transport to shut down
[sentry] Get response: `{"id":"7670..."}`
[sentry] Get response: `{"id":"c9ee..."}`

Answer 15 · 2023-09-07T11:05:52.000Z

Thanks for clearing up the confusion here, and good to see that there is no problem with normal capture_message calls.
So indeed this seems to be something going wrong with the env logger / log integration. I can have a closer look at this soon.

Answer 16 · 2023-09-07T18:38:55.000Z

Thanks for clearing up the confusion here, and good to see that there is no problem with normal capture_message calls.

No problem, all the info helps when debugging something like this

I can have a closer look at this soon.

Appreciate it, hopefully this is something simple. Thanks for looking into this

Answer 17 · 2023-09-15T11:19:07.000Z

I have been looking into this problem again, and I believe this to be a very trivial version mismatch.

If you indeed still have the following in your Cargo.toml according to your original comment:

sentry = { version = "0.30.0", features = ["anyhow"] }
sentry-log = "0.31.5"

Then this version mismatch might be the problem. Rust supports having multiple versions of the same crate compiled in one executable. sentry-log is outputting things into sentry-core@0.31.5 which is not initialized. sentry-core@0.30.0 is the one that is initialized, and which is thus also used by sentry-anyhow.

Trying different snippets, this won’t work as it does not include the sentry log integration / sink:

    env_logger::builder()
        .filter_level(secrets.log_level.clone().into())
        .init();

Using the following snippet, I can get error! to sentry without a problem, the info! and warn! turn into breadcrumbs by default.

In hindsight, splitting the SDK up into multiple crates was a mistake, as this is not the first time people (including myself) have run into problems related to version mismatches.

Answer 18 · 2023-09-15T14:23:03.000Z

Using the following snippet

What is the following snippet? I've bumped the sentry crate version to match the sentry-log version and still do not get the errors or breadcrumbs

Answer 19 · 2023-09-18T07:38:21.000Z

🙈 looks like I never copy-pasted that, and I also reverted it from my working tree.

Does it also have matching versions in the Cargo.lock file? I remember that some mismatches might slip through that way as well.

Answer 20 · 2023-09-18T13:49:11.000Z

Ok so some information was left out on my end and I apologize for that. We're using a workspace and I was using one of these runners as a guinnea pig. Found that we were still using an older sentry version to match the other runners and sentry-log was still mismatched. I've fixed this by bumping the other versions in the other runners and instead of version 0.31.5, its installing to version 0.31.7 despite the patch version being specified as 5. Ran it, still didnt show up in web interface. I then used the workspace to specify dependencies, cleared the cargo lock, re-built, saw the 0.31.7 version was built again, ran the same consumer, but this time I get the error below.

thread 'main' panicked at 'sentry crate was compiled without transport', /$HOME/.cargo/registry/src/github.com-1ecc6299db9ec823/sentry-0.31.7/src/transports/mod.rs:99:13

Answer 21 · 2023-09-18T13:52:03.000Z

🙈 looks like I never copy-pasted that, and I also reverted it from my working tree.

unfortunate

Does it also have matching versions in the Cargo.lock file? I remember that some mismatches might slip through that way as well.

with the above I've ensured that the package versions are the same

Answer 22 · 2023-09-19T08:47:24.000Z

The above panic is still pointing towards some kind of crate versioning or dependency problem. I’m unsure how to further help here?

Answer 23 · 2023-09-19T13:38:33.000Z

it doesn't seem to be a version mismatch here. I've downgraded to 0.30.0 and still nothing even though all dependencies are the same version. Am I missing something with the integration? It should just work right?I haven't changed any of the sentry configuration from above

Answer 24 · 2023-09-19T13:55:17.000Z

Yes, starting up sentry itself, and then setting the SentryLogger which forwards things to its configured destination, that should work ideally.

Answer 25 · 2023-09-22T01:19:02.000Z

Resolved and was able to figure it out. It was a version mismatch. I feel like this issue has a couple of takeaways in terms of documentation fixes that should be done. Thanks a bunch for the help all.

Answer 26 · 2023-09-22T07:45:31.000Z

Thanks for taking another look, this is helpful.

As I mentioned previously, in hindsight, splitting up the SDK into multiple sub-crates was a mistake, and I would probably merge these all into a single crate once again if/when we are making another bigger refactor of things.