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

trace: Allow trace instrumentation to emit log records #992

Merged
merged 38 commits into from
Mar 26, 2019

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Mar 19, 2019

Motivation

tokio-trace currently offers a strategy for compatibility with the
log crate: its macros can be dropped in as a replacement for log's
macros, and a subscriber can be used that translates trace events to log
records. However, this requires the application to be aware of
tokio-trace and manually set up this subscriber.

Many libraries currently emit log records, and would like to be able
to emit tokio-trace instrumentation instead. The tokio runtimes are
one such example. However, with the current log compatibility strategy,
replacing existing logging with trace instrumentation would break
tokio's logs for any downstream user which is using only log and not
tokio-trace. It is desirable for libraries to have the option to emit
both log and tokio-trace diagnostics from the same instrumentation
points.

Solution

This branch adds a log feature flag to the tokio-trace crate, which
when set, causes tokio-trace instrumentation to emit log records as well
as tokio-trace instrumentation.

In addition, emitting tokio-trace instrumentation now requires compiling
with the environment variable TOKIO_TRACE_ENABLED set. If this is not
set and log output is not enabled, but a tokio-trace subscriber would
have enabled a span, we output a warning message stating that this env
var must be set to enable tokio-trace.

Notes

In an ideal world, we would just detect if there is an active trace
subscriber, and emit log records if there is not. However, we can't
currently distinguish between a NoSubscriber and a subscriber that
has chosen not to record a particular callsite, without the downcasting
API proposed in #974. It might be worth waiting for that PR to land, and
modifying the log compat feature to emit log records if the current
subscriber is NoSubscriber, obviating the use of the environment
variables in most cases.

In order to allow spans to log their names when they are entered and
exited even when the span is disabled, this branch adds an
&'static Metadata to the Span type. This was previously stored in
the Inner type and was thus only present when the span was enabled.
This makes disabled spans one word longer, but enabled spans remain
the same size.

Fixes: #949

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

@hawkw hawkw added C-enhancement Category: A PR with an enhancement or bugfix. tokio-trace labels Mar 19, 2019
@hawkw hawkw self-assigned this Mar 19, 2019
@hawkw hawkw requested a review from carllerche March 19, 2019 18:34
@hawkw hawkw changed the title Eliza/log backcompat trace: Allow trace instrumentation to emit log records Mar 19, 2019
hawkw added 4 commits March 19, 2019 15:02
It looks weird if the callsite also adds punctuation of its own...
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw force-pushed the eliza/log-backcompat branch 2 times, most recently from 810353a to 1443463 Compare March 20, 2019 19:40
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw force-pushed the eliza/log-backcompat branch from 1443463 to eb90924 Compare March 20, 2019 19:40
@carllerche
Copy link
Member

I mentioned this in Slack, but repeating here.

My gut reaction is that the combination of feature flags / env vars is confusing. The goal of the env var is to be able to introduce tokio-trace in tokio without exposing it at all from the public API. As such, there should only be one feature: log. If set, the tokio-trace macros should dispatch to log. In all cases, a compile time check for an env var is made to determine if the macros output to tokio-trace-core or not.

@hawkw
Copy link
Member Author

hawkw commented Mar 21, 2019

@carllerche Okay, I'm happy to simplify the env var/feature flag relationship.

My personal opinion is that emitting tokio-trace-core instrumentation should only require the compile time env var when the log feature is enabled. Otherwise, the library's default behavior is to do nothing. This leads to a pretty confusing new-user experience.

To me, it seems like there's enough interest in tokio-trace for this to matter --- I'd prefer it if people who want to try out tokio-trace don't have the experience of adding a dependency in a test application, doing everything correctly, and then finding that nothing is actually recorded because the env var wasn't set. Similarly, I think it creates a pretty bad impression if tokio-trace's example code doesn't work out of the box.

Since the goal of the env var is to allow libraries (such as tokio) to expose tokio-trace-core instrumentation experimentally, they can add the log feature flag, and thus require the env var to opt-in to consuming their instrumentation points using tokio-trace.

What do you think?

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw force-pushed the eliza/log-backcompat branch from e7038f1 to 996b7fb Compare March 21, 2019 18:49
@hawkw
Copy link
Member Author

hawkw commented Mar 21, 2019

@carllerche okay, I've updated this branch so that the env var is always required to enable trace instrumentation. A warning message is printed when a subscriber would enable a span if trace instrumentation and log output are both disabled.

@hawkw hawkw force-pushed the eliza/log-backcompat branch from a34de98 to eb5a1a0 Compare March 22, 2019 19:01
@hawkw hawkw requested a review from seanmonstar March 22, 2019 20:28
@hawkw
Copy link
Member Author

hawkw commented Mar 22, 2019

@carllerche I think this branch is ready to be reviewed --- I've updated the PR description to reflect the current behavior as well.

hawkw added 5 commits March 22, 2019 13:39
This prevents them from resulting in `DebugValue(foo)` and so on in log
messages.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
This reverts commit dd99ea3. This
change wasn't intended to be committed to this branch.
Copy link
Member

@carllerche carllerche left a comment

Choose a reason for hiding this comment

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

LGTM. I would merge if @seanmonstar is good with it as well (we want hyper to adopt it too).

@hawkw
Copy link
Member Author

hawkw commented Mar 25, 2019

I believe the FreeBSD CI build is failing for the same reasons described here #987 (comment)

@hawkw
Copy link
Member Author

hawkw commented Mar 25, 2019

Okay, 3ca54ff ought to fix the FreeBSD build failing.

@seanmonstar I would still love to get your approval before merging (as Carl suggested in #992 (review))...

@hawkw hawkw merged commit d8177f8 into master Mar 26, 2019
@hawkw hawkw added this to the tokio-trace v0.1 milestone Mar 27, 2019
@carllerche carllerche deleted the eliza/log-backcompat branch April 22, 2019 21:26
hawkw added a commit that referenced this pull request Jun 25, 2019
## Motivation

`tokio-trace` currently offers a strategy for compatibility with the
`log` crate: its macros can be dropped in as a replacement for `log`'s
macros, and a subscriber can be used that translates trace events to log
records. However, this requires the application to be aware of
`tokio-trace` and manually set up this subscriber.

Many libraries currently emit `log` records, and would like to be able
to emit `tokio-trace` instrumentation instead. The `tokio` runtimes are
one such example. However, with the current log compatibility strategy,
replacing existing logging with trace instrumentation would break
`tokio`'s logs for any downstream user which is using only `log` and not
`tokio-trace`. It is desirable for libraries to have the option to emit
both `log` _and_ `tokio-trace` diagnostics from the same instrumentation
points.

## Solution

This branch adds a `log` feature flag to the `tokio-trace` crate, which
when set, causes `tokio-trace` instrumentation to emit log records as well
as `tokio-trace` instrumentation. 

## Notes

In order to allow spans to log their names when they are entered and 
exited even when the span is disabled, this branch adds an 
`&'static Metadata` to the `Span` type. This was previously stored in
the `Inner` type and was thus only present when the span was enabled.
This makes disabled spans one word longer, but enabled spans remain
the same size.

Fixes: #949

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
C-enhancement Category: A PR with an enhancement or bugfix.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants