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

tracing: don't emit log events if a subscriber has been set #346

Merged
merged 7 commits into from Sep 13, 2019

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Sep 12, 2019

Motivation

Currently, when tracing's log feature is enabled, all spans and
events will emit log records as well as tracing events. When
tracing-log is being used to convert log records into tracing
events, this results in duplicate events being observed: those emitted
by the event macros directly, and those generated from the log records
they emit by tracing-log.

Solution

In tracing-core 0.1.6, we added an internal API for checking if a
tracing subscriber has ever been set. In addition to the performance
optimizations which this was initially intended to enable, this also
gives us a way for tracing macros in libraries to check if a
downstream application that depends on those libraries is actually using
tracing. If tracing is in use and a subscriber has been set, the
macros can be disabled.

In a handful of cases, users may wish to collect log records and
tracing events totally separately. For example, log records might be
output to the console while tracing is used to generate metrics or for
performance profiling. In this case, there is an additional log-always
feature flag which applications can set to enable all of tracing's log
records regardless of whether a subscriber is in use. In most cases
where the log feature is currently used (libraries that want to emit
both tracing and log diagnostics for their users), this will not be
necessary.

Fixes #204

Signed-off-by: Eliza Weisman eliza@buoyant.io

Motivation:

Currently, when `tracing`'s `log` feature is enabled, all spans and
events will emit `log` records as well as `tracing` events. When
`tracing-log` is being used to convert `log` records into `tracing`
events, this results in duplicate events being observed: those emitted
by the event macros directly, and those generated from the log records
they emit by `tracing-log`.

Solution:

In `tracing-core` 0.1.6, we added an internal API for checking if a
`tracing` subscriber has ever been set. In addition to the performance
optimizations which this was initially intended to enable, this also
gives us a way for `tracing` macros in libraries to check if a
downstream application that depends on those libraries is actually using
`tracing`. If `tracing` is in use and a subscriber has been set, the
macros can be disabled.

In a handful of cases, users _may_ wish to collect `log` records and
`tracing` events totally separately. For example, `log` records might be
output to the console while `tracing` is used to generate metrics or for
performance profiling. In this case, there is an additional `log-always`
feature flag which applications can set to enable all of `tracing`'s log
records regardless of whether a subscriber is in use. In most cases
where the `log` feature is currently used (libraries that want to emit
both `tracing` and `log` diagnostics for their users), this will not be
necessary.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw added the kind/feature New feature or request label Sep 12, 2019
@hawkw hawkw requested review from tobz, yaahc, LucioFranco and a team September 12, 2019 21:35
@hawkw hawkw self-assigned this Sep 12, 2019
@github-actions github-actions bot added the crate/tracing Related to the `tracing` crate label Sep 12, 2019
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Copy link
Contributor

@samscott89 samscott89 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks nice! Will save us from enumerating all our crates in the ignore_all method.

One suggestion: does there really need to be both __tracing_should_log and if_log? It sort of looks like they could be merged into one?

Also, should if_log be in src/macros?

@hawkw
Copy link
Member Author

hawkw commented Sep 12, 2019

One suggestion: does there really need to be both __tracing_should_log and if_log? It sort of looks like they could be merged into one?

Also, should if_log be in src/macros?

The intention was that the macros module contain the public API macros (and other doc(hidden) public macros they depend on). I agree that having two macros that are similar is probably not ideal; i'll see if they can be unifed.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
Copy link
Member Author

hawkw commented Sep 12, 2019

as of 2baaee3 there is now only one macro because i am ✨mad with power

tracing/src/macros.rs Outdated Show resolved Hide resolved
hawkw and others added 3 commits September 12, 2019 15:51
Co-Authored-By: Sam Scott <sam@osohq.com>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Copy link
Member

@tobz tobz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM!

@hawkw hawkw merged commit 22a285a into master Sep 13, 2019
hawkw added a commit that referenced this pull request Sep 13, 2019
Fixed:

- Fixed `#[instrument]`ed async functions not compiling on
  `nightly-2019-09-11` or newer (#342)

Changed:

- Significantly reduced performance impact of skipped spans and events
  when a `Subscriber` is not in use (#326)
- The `log` feature will now only cause `tracing` spans and events to
  emit log records when a `Subscriber` is not in use (#346)

Added:

- Added support for overriding the name of the span generated by
  `#[instrument]` (#330)
- `log-always` feature flag to emit log records even when a `Subscriber`
  is set (#346)

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Sep 13, 2019
### Fixed

- Fixed `#[instrument]`ed async functions not compiling on
  `nightly-2019-09-11` or newer (#342)

### Changed

- Significantly reduced performance impact of skipped spans and events
  when a `Subscriber` is not in use (#326)
- The `log` feature will now only cause `tracing` spans and events to
  emit log records when a `Subscriber` is not in use (#346)

### Added

- Added support for overriding the name of the span generated by
  `#[instrument]` (#330)
- `log-always` feature flag to emit log records even when a `Subscriber`
  is set (#346)

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit to linkerd/linkerd2-proxy that referenced this pull request Sep 13, 2019
Updating to the latest versions of the `tracing` and
`tracing-subscriber` crates picks up a few changes that might be
relevant to us:

- tokio-rs/tracing#333: Fix an issue where filtering directives could
  sometimes be ignored
- tokio-rs/tracing#344: Fix for filters not applying to events generated
  from `log` records
- tokio-rs/tracing#346: Dependencies using `tracing`'s `log` back-compat
  alongside the `log` record to `tracing` event conversion layer will no
  longer result in duplicate events

Additionally, `tracing-subscriber` 0.1.2 removed some dependencies that
were previously on by default, and feature flagged others; I've tweaked
the feature flags that we enable so we now have fewer transitive deps in
our lockfile :D

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit to linkerd/linkerd2-proxy that referenced this pull request Sep 18, 2019
* logging: update `tracing` and `tracing-subscriber`

Updating to the latest versions of the `tracing` and
`tracing-subscriber` crates picks up a few changes that might be
relevant to us:

- tokio-rs/tracing#333: Fix an issue where filtering directives could
  sometimes be ignored
- tokio-rs/tracing#344: Fix for filters not applying to events generated
  from `log` records
- tokio-rs/tracing#346: Dependencies using `tracing`'s `log` back-compat
  alongside the `log` record to `tracing` event conversion layer will no
  longer result in duplicate events

Additionally, `tracing-subscriber` 0.1.2 removed some dependencies that
were previously on by default, and feature flagged others; I've tweaked
the feature flags that we enable so we now have fewer transitive deps in
our lockfile :D

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
panthervis added a commit to panthervis/linkerd2-proxy that referenced this pull request Oct 8, 2021
* logging: update `tracing` and `tracing-subscriber`

Updating to the latest versions of the `tracing` and
`tracing-subscriber` crates picks up a few changes that might be
relevant to us:

- tokio-rs/tracing#333: Fix an issue where filtering directives could
  sometimes be ignored
- tokio-rs/tracing#344: Fix for filters not applying to events generated
  from `log` records
- tokio-rs/tracing#346: Dependencies using `tracing`'s `log` back-compat
  alongside the `log` record to `tracing` event conversion layer will no
  longer result in duplicate events

Additionally, `tracing-subscriber` 0.1.2 removed some dependencies that
were previously on by default, and feature flagged others; I've tweaked
the feature flags that we enable so we now have fewer transitive deps in
our lockfile :D

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/tracing Related to the `tracing` crate kind/feature New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Better support for using tracing-log with the log feature
3 participants