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

Improve errors / debugging by not stripping, log trace if requested #3425

Merged
merged 1 commit into from Jun 30, 2023

Conversation

phiresky
Copy link
Collaborator

@phiresky phiresky commented Jun 30, 2023

Right now one of the huge issues lemmy has is that the error reporting is very bad. Tons of people are reporting random issues and it's hard to diagnose anything. For example:

2023-06-30T12:35:38.736991Z  WARN lemmy_server::root_span_builder: EOF while parsing a value at line 1 column 0
   1: lemmy_apub::activity_lists::community
             at crates/apub/src/activity_lists.rs:113
   2: lemmy_apub::activities::community::announce::receive
             at crates/apub/src/activities/community/announce.rs:46
   3: lemmy_server::root_span_builder::HTTP request
           with http.method=POST http.scheme="http" http.host=lemmy.localhost:8536 http.target=/inbox otel.kind="server" request_id=a60a15e1-4600-481d-b03b-bc1ebaa656d9
             at src/root_span_builder.rs:16

This error looks like there was a parsing error in when parsing some incoming message community right? False, the parsing error actually appears because after parsing a comment it tries to fetch the parent post, and the remote server response responded with a 404 error to that parent post request. You can't even tell the issue is with comment receiving here.

This change makes error reporting better by

  1. making anyhow print its own trace if it exists (same as it usually does if you return an anyhow error in main)
  2. making anyhow print the real backtrace if RUST_BACKTRACE=1. This is not on by default but at least now it can be enabled.
  3. not stripping symbols. symbol stripping doesn't affect performance, only binary size. It can also be done after the fact with strip lemmy_server if someone cares about binary size.
    • debug symbols allow both for heap dumps to be useful, for backtraces that are useful, and for profiling / instrumenting that is useful (see example here). Many of these things need to be done in production builds since perf there differs very much from debug, so stripping binaries there prevents issue finding.
  4. not removing debug info for debug builds. Sounds like this was done for build performance in the first place, but I just benchmarked a compile and it was 41s vs 40s. Maybe it was different in 2020?

After this change, the above error can look like this (with some anyhow contexts added, not part of this PR):

2023-06-30T12:35:38.736991Z  WARN lemmy_server::root_span_builder: get comment parents
Caused by:
    0: finding parent comment
    1: EOF while parsing a value at line 1 column 0
   1: lemmy_apub::activity_lists::community
             at crates/apub/src/activity_lists.rs:113
   2: lemmy_apub::activities::community::announce::receive
             at crates/apub/src/activities/community/announce.rs:46
   3: lemmy_server::root_span_builder::HTTP request
           with http.method=POST http.scheme="http" http.host=lemmy.localhost:8536 http.target=/inbox otel.kind="server" request_id=a60a15e1-4600-481d-b03b-bc1ebaa656d9
             at src/root_span_builder.rs:16

and with RUST_BACKTRACE=1 and without further changes it looks like this (a bit noisy, but at least you can understand what happened since you can clearly see CreateOrUpdateNote, get_parents, and dereference_from_http in the backtrace:

2023-06-30T12:35:38.736991Z  WARN lemmy_server::root_span_builder: EOF while parsing a value at line 1 column 0

Stack backtrace:
   0: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at /home/phire/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.71/src/error.rs:547:25
   1: <T as core::convert::Into<U>>::into
             at /rustc/f7ca9df69549470541fbf542f87a03eb9ed024b6/library/core/src/convert/mod.rs:716:9
   2: <lemmy_utils::error::LemmyError as core::convert::From<T>>::from
             at ./crates/utils/src/error.rs:73:14
   3: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual
             at /rustc/f7ca9df69549470541fbf542f87a03eb9ed024b6/library/core/src/result.rs:1961:27
   4: activitypub_federation::fetch::object_id::ObjectId<Kind>::dereference_from_http::{{closure}}
             at /home/phire/data/dev/2023/activitypub-federation-rust/src/fetch/object_id.rs:159:20
   5: activitypub_federation::fetch::object_id::ObjectId<Kind>::dereference::{{closure}}
             at /home/phire/data/dev/2023/activitypub-federation-rust/src/fetch/object_id.rs:116:52
   6: lemmy_apub::protocol::objects::note::Note::get_parents::{{closure}}
             at ./crates/apub/src/protocol/objects/note.rs:66:10
   7: <lemmy_apub::protocol::activities::create_or_update::note::CreateOrUpdateNote as lemmy_apub::protocol::InCommunity>::community::{{closure}}::{{closure}}
             at ./crates/apub/src/protocol/activities/create_or_update/note.rs:39:49
   8: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/phire/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
   9: <lemmy_apub::protocol::activities::create_or_update::note::CreateOrUpdateNote as lemmy_apub::protocol::InCommunity>::community::{{closure}}
             at ./crates/apub/src/protocol/activities/create_or_update/note.rs:37:3
  10: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/f7ca9df69549470541fbf542f87a03eb9ed024b6/library/core/src/future/future.rs:125:9
  11: <lemmy_apub::activity_lists::AnnouncableActivities as lemmy_apub::protocol::InCommunity>::community::{{closure}}::{{closure}}
             at ./crates/apub/src/activity_lists.rs:117:56
  12: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/phire/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
  13: <lemmy_apub::activity_lists::AnnouncableActivities as lemmy_apub::protocol::InCommunity>::community::{{closure}}
             at ./crates/apub/src/activity_lists.rs:113:3
  14: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/f7ca9df69549470541fbf542f87a03eb9ed024b6/library/core/src/future/future.rs:125:9
  15: lemmy_apub::activities::community::announce::<impl activitypub_federation::traits::ActivityHandler for lemmy_apub::protocol::activities::community::announce::RawAnnouncableActivities>::receive::{{closure}}::{{closure}}
             at ./crates/apub/src/activities/community/announce.rs:53:46
  16: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
             at /home/phire/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
  17: lemmy_apub::activities::community::announce::<impl activitypub_federation::traits::ActivityHandler for lemmy_apub::protocol::activities::community::announce::RawAnnouncableActivities>::receive::{{closure}}
             at ./crates/apub/src/activities/community/announce.rs:46:3
  18: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/f7ca9df69549470541fbf542f87a03eb9ed024b6/library/core/src/future/future.rs:125:9
  19: <activitypub_federation::protocol::context::WithContext<T> as activitypub_federation::traits::ActivityHandler>::receive::{{closure}}
             at /home/phire/data/dev/2023/activitypub-federation-rust/src/protocol/context.rs:79:34
   ...
   0: lemmy_apub::protocol::activities::create_or_update::note::community
             at crates/apub/src/protocol/activities/create_or_update/note.rs:37
   1: lemmy_apub::activity_lists::community
             at crates/apub/src/activity_lists.rs:113
   2: lemmy_apub::activities::community::announce::receive
             at crates/apub/src/activities/community/announce.rs:46
   3: lemmy_server::root_span_builder::HTTP request
           with http.method=POST http.scheme="http" http.host=lemmy.localhost:8536 http.target=/inbox otel.kind="server" request_id=a60a15e1-4600-481d-b03b-bc1ebaa656d9
             at src/root_span_builder.rs:16

@Nutomic Nutomic enabled auto-merge (squash) June 30, 2023 13:21
@Nutomic
Copy link
Member

Nutomic commented Jun 30, 2023

Looks good, thanks!

@Nutomic Nutomic merged commit cb28af5 into LemmyNet:main Jun 30, 2023
1 check passed
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

Successfully merging this pull request may close these issues.

None yet

2 participants