ref(symbolicator): Replace log with tracing

[loewenheim]

As a first step towards using tracing in symbolicator, this simply replaces the various log macros with their tracing equivalents. The more difficult part is setting up the subscribers (tracing's loggers):

• The Pretty, Simplified, and Json log formats use the builtin styles pretty, compact, and Json, respectively. Notably, the LogRecord struct is obsolete. The same goes for BreadcrumbLogger, whose functionality is now handled by sentry-tracing.
• Unfortunately, tracing's LevelFilter doesn't implement Deserialize, so config.rs contains a manual deserialization function.

This PR doesn't exactly play to tracing's strengths, as there are no spans and no structured logs. It's intended to introduce tracing with minimum hassle.

[Swatinem]

This is actually pretty straight forward, I like it!

Maybe you can take a look at #515 and cherry-pick the instrumentation and sentry-tracing layer.
Other than that, please reach out to ops about whether we actually use these logs (json formatted?) somewhere. If we might change the format or if we need to keep backwards compatibility.

[Swatinem]

an alternative would be to define our own enum for this with a derived Deserialize, and convert between these two directly.

[loewenheim]

Maybe you can take a look at #515 and cherry-pick the instrumentation and sentry-tracing layer.

I'd rather add instrumentation and structure in a second PR tbh. As for the sentry-tracing layer, is there anything more that needs to be done other than add a SentryLayer to the subscriber?

[loewenheim]

So before the most recent commit, some python tests were failing with a message about how they couldn't find a port or some such. Turns out, these tests start a symbolicator process and then wait for a specific log line from actix_web from which they parse the port that symbolicator is listening on. And since I hadn't set up log integration, the actix_web logs were silently discarded and the tests never found out the port 😅

[flub]

Other than that, please reach out to ops about whether we actually use these logs (json formatted?) somewhere. If we might change the format or if we need to keep backwards compatibility.

Yes we use JSON formatted logs in production, you can get to them from the symbolicator metrics dashboard by following the "stackdriver logs" link.

[loewenheim]

The most recent commit (5142030) solves the problem of keeping log output exactly the same in the simplest way: instead of using a tracing::Subscriber, we keep the logger and convert all tracing events to log records. This has the advantage of being very easy (really just add the tracing dependency with the log feature enabled and replace all the log invocations), but the disadvantage that it doesn't get rid of log entirely. Moreover, once we want to use tracing in more sophisticated ways, we will have to use a subscriber anyway. Thoughts?

[flub]

I preferred the version where you removed log entirely. We should be able to make sure the tracing subscriber json output includes at least the same fields as we had before and then we're good.

I think in the future it would be nice to also start using the tracing macros with extra fields which would show up in the json log and make our log search much more useful.

[loewenheim]

@flub Is it clear that there's no harm in adding extra fields to the json logs?

[flub]

@flub Is it clear that there's no harm in adding extra fields to the json logs?

I'm like 95% sure... 😄 @oioki might be able to give a better answer?

[codecov-commenter]

Codecov Report

Merging #534 (3775d1c) into master (0e99a5e) will increase coverage by 0.18%.
The diff coverage is 27.77%.

@@            Coverage Diff             @@
##           master     #534      +/-   ##
==========================================
+ Coverage   74.09%   74.27%   +0.18%     
==========================================
  Files          47       47              
  Lines       10434    10419      -15     
==========================================
+ Hits         7731     7739       +8     
+ Misses       2703     2680      -23     

Impacted Files	Coverage Δ
crates/symbolicator/src/endpoints/proxy.rs	0.00% <0.00%> (ø)
crates/symbolicator/src/logging.rs	9.52% <0.00%> (+3.96%)	⬆️
crates/symbolicator/src/metrics.rs	52.05% <0.00%> (ø)
crates/symbolicator/src/services/cficaches.rs	86.42% <0.00%> (ø)
...rates/symbolicator/src/services/download/sentry.rs	22.85% <0.00%> (ø)
crates/symbolicator/src/services/objects/mod.rs	66.78% <0.00%> (+0.24%)	⬆️
crates/symbolicator/src/services/symcaches.rs	94.00% <0.00%> (ø)
crates/symbolicator/src/utils/gcs.rs	42.18% <0.00%> (ø)
crates/symbolicator/src/config.rs	85.28% <3.44%> (-10.08%)	⬇️
crates/symbolicator/src/services/shared_cache.rs	48.23% <10.00%> (+0.07%)	⬆️
... and 20 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0e99a5e...3775d1c. Read the comment docs.

[loewenheim]

Alright, I think this is finally ready for serious consideration. JSON log output doesn't line up exactly, but after talking to @oioki we think it shouldn't be a problem.
Old log line:

{"timestamp":"2022-01-25T12:44:44.202043Z","level":"INFO","logger":"symbolicator::server","message":"Starting server on 127.0.0.1:3021","module_path":"symbolicator::server","filename":"crates/symbolicator/src/server.rs","lineno":43}

New log line:

{"timestamp":"2022-01-25T12:52:19.015333Z","level":"INFO","message":"Starting server on 127.0.0.1:3021","target":"symbolicator::server","filename":"crates/symbolicator/src/server.rs","line_number":43}

[flub]

agree the json differences are fine. let's merge this 🎉