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: never log access log spans to stdout #2244

Merged
merged 1 commit into from
Feb 17, 2023
Merged

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Feb 17, 2023

Currently, tracing spans are used to record HTTP access log entries. These spans are recorded at the INFO level, in order to allow the use of fast-path filtering for the more verbose DEBUG and TRACE levels when running with the default tracing filter configuration (linkerd=info) --- if no events will ever be enabled at a given level, tracing can skip them more efficiently than when events with some targets are enabled at that level. The access log spans are recorded with a separate _access_log target, so that the default linkerd=info filter does not enable them.

However, when running with a custom filter configuration that enables info for all targets, the access log spans will be enabled even if access logging is disabled. This means that these spans will be recorded when they may not be needed to generate an access log. They also make logs significantly more verbose when DEBUG events are enabled (only debug and higher events will occur in these spans), which can make the logs harder to parse.

This branch changes the per-layer filter used by the stdout logging layer to explicitly disable the _access_log trace target, regardless of the rest of the filter configuration. This way, a custom filter configuration that globally enables the INFO level will not enable the access log spans, and the spans will not be included in stdout logs even if access logging is enabled. Since the layer that actually generates the access log has its own, separate per-layer filter, the access log spans will still be enabled for that layer, if and only if access logging is actually enabled.

A potential longer-term solution is to rewrite the access logging code to not use tracing, as was originally proposed. At the time, we opted to use tracing to generate the access log because it seemed desirable to have a single set of diagnostics that can generate different outputs. However, in practice, it's probably better to keep general-purpose debugging logs and access logging separate, as they are separate concerns. A purpose-built implementation of access logging could avoid issues like this one, and would also probably be more efficient --- it wouldn't need to allocate strings to represent access log spans, and could instead just store structured data that's formatted directly to the output. But, the filtering change solves the immediate problem.

Currently, `tracing` spans are used to record HTTP access log entries.
These spans are recorded at the `INFO` level, in order to allow the use
of fast-path filtering for the more verbose `DEBUG` and `TRACE` levels
when running with the default tracing filter configuration
(`linkerd=info`) --- if no events will ever be enabled at a given level,
`tracing` can skip them more efficiently than when events with some
targets are enabled at that level. The access log spans are recorded
with a separate `_access_log` target, so that the default `linkerd=info`
filter does not enable them.

However, when running with a custom filter configuration that enables
`info` for all targets, the access log spans will be enabled even if
access logging is disabled. This means that these spans will be recorded
when they may not be needed to generate an access log. They also make
logs significantly more verbose when `DEBUG` events are enabled (only
debug and higher events will occur in these spans), which can make the
logs harder to parse.

This branch changes the per-layer filter used by the stdout logging
layer to explicitly disable the `_access_log` trace target, regardless
of the rest of the filter configuration. This way, a custom filter
configuration that globally enables the `INFO` level will not enable the
access log spans, and the spans will not be included in stdout logs even
if access logging is enabled. Since the layer that actually generates
the access log has its own, separate per-layer filter, the access log
spans will still be enabled _for that layer_, if and only if access
logging is actually enabled.

A potential longer-term solution is to rewrite the access logging code
to not use `tracing`, as was originally proposed. At the time, we opted
to use `tracing` to generate the access log because it seemed desirable
to have a single set of diagnostics that can generate different outputs.
However, in practice, it's probably better to keep general-purpose
debugging logs and access logging separate, as they are separate
concerns. A purpose-built implementation of access logging could avoid
issues like this one, and would also probably be more efficient --- it
wouldn't need to allocate strings to represent access log spans, and
could instead just store structured data that's formatted directly to
the output. But, the filtering change solves the immediate problem.
@hawkw hawkw requested a review from a team as a code owner February 17, 2023 19:16
@olix0r olix0r merged commit de97063 into main Feb 17, 2023
@olix0r olix0r deleted the eliza/no-access-log branch February 17, 2023 21:25
olix0r added a commit to linkerd/linkerd2 that referenced this pull request Feb 24, 2023
This release updates the proxy to require control-plane-discovered
policies for all inbound connections. Previously, the proxy would
use a locally-configured default policy while it synced policies from
the control plane.

---

* trace: never log access log spans to stdout (linkerd/linkerd2-proxy#2244)
* build(deps): bump thread_local from 1.1.4 to 1.1.7 (linkerd/linkerd2-proxy#2243)
* build(deps): bump tj-actions/changed-files from 35.5.4 to 35.5.5 (linkerd/linkerd2-proxy#2242)
* build(deps): bump serde_json from 1.0.91 to 1.0.93 (linkerd/linkerd2-proxy#2217)
* dev: Remove docker config mount (linkerd/linkerd2-proxy#2246)
* build(deps): bump anyhow from 1.0.68 to 1.0.69 (linkerd/linkerd2-proxy#2216)
* build(deps): bump actions/checkout from 3.2.0 to 3.3.0 (linkerd/linkerd2-proxy#2130)
* http: Use `ExtractParam` in `NewNormalizeUri` (linkerd/linkerd2-proxy#2245)
* http: Replace `classify::CanClassify` with `Param` (linkerd/linkerd2-proxy#2247)
* http: Improve timeout module (linkerd/linkerd2-proxy#2248)
* outbound: Decouple outbound HTTP server from logical target (linkerd/linkerd2-proxy#2249)
* build(deps): bump http from 0.2.8 to 0.2.9 (linkerd/linkerd2-proxy#2253)
* build(deps): bump fastrand from 1.8.0 to 1.9.0 (linkerd/linkerd2-proxy#2252)
* build(deps): bump signal-hook-registry from 1.4.0 to 1.4.1 (linkerd/linkerd2-proxy#2254)
* Use `ExtractParam` in `http::NewHeaderFromTarget` (linkerd/linkerd2-proxy#2255)
* outbound: Introduce a new outbound-route watch type (linkerd/linkerd2-proxy#2250)
* build(deps): bump tj-actions/changed-files from 35.5.5 to 35.5.6 (linkerd/linkerd2-proxy#2256)
* build(deps): bump hyper from 0.14.23 to 0.14.24 (linkerd/linkerd2-proxy#2257)
* build(deps): bump once_cell from 1.17.0 to 1.17.1 (linkerd/linkerd2-proxy#2258)
* build(deps): bump clang-sys from 1.4.0 to 1.6.0 (linkerd/linkerd2-proxy#2259)
* outbound: Add a policy router (linkerd/linkerd2-proxy#2251)
* inbound: connections wait for ServerPolicy discovery (linkerd/linkerd2-proxy#2186)
* inbound: Remove default policies (linkerd/linkerd2-proxy#2204)
* inbound: Introduce a `policy::LookupAddr` type (linkerd/linkerd2-proxy#2264)
* build(deps): bump futures from 0.3.25 to 0.3.26 (linkerd/linkerd2-proxy#2263)
* build(deps): bump proc-macro2 from 1.0.50 to 1.0.51 (linkerd/linkerd2-proxy#2261)
* build(deps): bump tinyvec_macros from 0.1.0 to 0.1.1 (linkerd/linkerd2-proxy#2262)

Signed-off-by: Oliver Gould <ver@buoyant.io>
olix0r added a commit to linkerd/linkerd2 that referenced this pull request Mar 1, 2023
* proxy: v2.191.0

This release updates the proxy to require control-plane-discovered
policies for all inbound connections. Previously, the proxy would
use a locally-configured default policy while it synced policies from
the control plane.

---

* trace: never log access log spans to stdout (linkerd/linkerd2-proxy#2244)
* build(deps): bump thread_local from 1.1.4 to 1.1.7 (linkerd/linkerd2-proxy#2243)
* build(deps): bump tj-actions/changed-files from 35.5.4 to 35.5.5 (linkerd/linkerd2-proxy#2242)
* build(deps): bump serde_json from 1.0.91 to 1.0.93 (linkerd/linkerd2-proxy#2217)
* dev: Remove docker config mount (linkerd/linkerd2-proxy#2246)
* build(deps): bump anyhow from 1.0.68 to 1.0.69 (linkerd/linkerd2-proxy#2216)
* build(deps): bump actions/checkout from 3.2.0 to 3.3.0 (linkerd/linkerd2-proxy#2130)
* http: Use `ExtractParam` in `NewNormalizeUri` (linkerd/linkerd2-proxy#2245)
* http: Replace `classify::CanClassify` with `Param` (linkerd/linkerd2-proxy#2247)
* http: Improve timeout module (linkerd/linkerd2-proxy#2248)
* outbound: Decouple outbound HTTP server from logical target (linkerd/linkerd2-proxy#2249)
* build(deps): bump http from 0.2.8 to 0.2.9 (linkerd/linkerd2-proxy#2253)
* build(deps): bump fastrand from 1.8.0 to 1.9.0 (linkerd/linkerd2-proxy#2252)
* build(deps): bump signal-hook-registry from 1.4.0 to 1.4.1 (linkerd/linkerd2-proxy#2254)
* Use `ExtractParam` in `http::NewHeaderFromTarget` (linkerd/linkerd2-proxy#2255)
* outbound: Introduce a new outbound-route watch type (linkerd/linkerd2-proxy#2250)
* build(deps): bump tj-actions/changed-files from 35.5.5 to 35.5.6 (linkerd/linkerd2-proxy#2256)
* build(deps): bump hyper from 0.14.23 to 0.14.24 (linkerd/linkerd2-proxy#2257)
* build(deps): bump once_cell from 1.17.0 to 1.17.1 (linkerd/linkerd2-proxy#2258)
* build(deps): bump clang-sys from 1.4.0 to 1.6.0 (linkerd/linkerd2-proxy#2259)
* outbound: Add a policy router (linkerd/linkerd2-proxy#2251)
* inbound: connections wait for ServerPolicy discovery (linkerd/linkerd2-proxy#2186)
* inbound: Remove default policies (linkerd/linkerd2-proxy#2204)
* inbound: Introduce a `policy::LookupAddr` type (linkerd/linkerd2-proxy#2264)
* build(deps): bump futures from 0.3.25 to 0.3.26 (linkerd/linkerd2-proxy#2263)
* build(deps): bump proc-macro2 from 1.0.50 to 1.0.51 (linkerd/linkerd2-proxy#2261)
* build(deps): bump tinyvec_macros from 0.1.0 to 0.1.1 (linkerd/linkerd2-proxy#2262)

Signed-off-by: Oliver Gould <ver@buoyant.io>

* proxy: v2.191.2

Revert inbound policy discovery behavior changes (from v2.191.0) and
update dependencies, especially h2.

---

* Revert inbound policy discovery changes (linkerd/linkerd2-proxy#2267)
* Bump v38 to v39 (linkerd/linkerd2-proxy#2269)
* dev: override CXX for rust-analyzer (linkerd/linkerd2-proxy#2270)
* build(deps): bump syn from 1.0.107 to 1.0.109 (linkerd/linkerd2-proxy#2274)
* build(deps): bump tokio-util from 0.7.4 to 0.7.7 (linkerd/linkerd2-proxy#2272)
* build(deps): bump tj-actions/changed-files from 35.5.6 to 35.6.0 (linkerd/linkerd2-proxy#2271)
* build(deps): bump prost-build from 0.11.6 to 0.11.8 (linkerd/linkerd2-proxy#2273)
* ci: Add a linkerd install workflow (linkerd/linkerd2-proxy#2268)
* allow `opaque_hidden_inferred_bound` warning on nightly (linkerd/linkerd2-proxy#2275)
* build(deps): bump h2 from 0.3.15 to 0.3.16 (linkerd/linkerd2-proxy#2278)
* build(deps): bump tempfile from 3.3.0 to 3.4.0 (linkerd/linkerd2-proxy#2277)
* build(deps): bump tokio-stream from 0.1.11 to 0.1.12 (linkerd/linkerd2-proxy#2276)
* stack: Make `failfast::Gate` general purpose (linkerd/linkerd2-proxy#2279)
* build(deps): bump slab from 0.4.7 to 0.4.8 (linkerd/linkerd2-proxy#2283)
* build(deps): bump async-stream from 0.3.3 to 0.3.4 (linkerd/linkerd2-proxy#2282)
* build(deps): bump jobserver from 0.1.25 to 0.1.26 (linkerd/linkerd2-proxy#2281)
* build(deps): bump tj-actions/changed-files from 35.6.0 to 35.6.1 (linkerd/linkerd2-proxy#2280)

Signed-off-by: Oliver Gould <ver@buoyant.io>

---------

Signed-off-by: Oliver Gould <ver@buoyant.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants