-
Notifications
You must be signed in to change notification settings - Fork 271
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: Apache Common Log Format access logging #1319
Merged
Merged
Changes from 60 commits
Commits
Show all changes
64 commits
Select commit
Hold shift + click to select a range
41fd82d
Add access logging as requested in linkerd/linkerd2#1913
tustvold 1b7a3cb
Merge branch 'main' into pr/tustvold/601
olix0r acbe77e
fixup pin-project dependency
olix0r 11d2076
fixup fuzzer cargo lock files
olix0r cd80bf4
review feedback
tustvold d4c5337
misc style cleanup
hawkw e9c5892
enable/disable with env var
hawkw 6b5fb78
add client info to access log
hawkw dce15dd
ensure the tracing filter enables access log spans
hawkw 4d76632
change access log spans to `INFO`
hawkw 0990eb9
review feedback
tustvold 126ffc2
Merge remote-tracking branch 'upstream/main' into access-logging
tustvold c46bf15
load access log setting from environment
tustvold b5de8d8
remove filtering from AccessLogWriter layer
tustvold d5fb34b
fix replay test compilation
tustvold 93af5d9
update fuzz lockfiles
tustvold da3332f
Merge remote-tracking branch 'upstream/main' into access-logging
tustvold 777e0e5
mark inline; use CONTENT_LENGTH constant
olix0r 449fef0
tracing: Simplify initialization
olix0r 88bbd3b
clone golf
olix0r 892bc63
clippay
olix0r f829918
simplify env filter construction
olix0r 992647e
malkovich
olix0r ebf7813
Merge branch 'ver/tracing-functions' into pr/tustvold/601
olix0r c53ce37
Move struct defintions to the top
olix0r 72132a3
Merge branch 'ver/tracing-functions' into pr/tustvold/601
olix0r 4b56f3d
Reintroduce access logging with a TODO
olix0r cf3440d
Merge branch 'main' into pr/tustvold/601
olix0r af63421
Split the access-log module and the log writer
olix0r b97ac8e
Constify the special tracing target for access logs
olix0r 705d437
+inline
olix0r ad9b54c
lowercase headers
olix0r 2b7bd42
Only capture time when tracing is enabled
olix0r 2ac1804
Make the access log conditional
olix0r 53e45b8
fuzzer deps
olix0r b6005d9
Only app::inbound need depend on access-log
olix0r bf48a56
Rename the module to linkerd-http-access-log
olix0r da3d1ae
forbid unsafe code
olix0r 65d372a
Merge branch 'main' into pr/tustvold/601
olix0r 72ecb24
Merge branch 'main' into access-logging
hawkw 9e5ecf6
wip plf integration
hawkw 219b220
tracing: simplify subscriber construction with `Box`ed layers
hawkw 2d20daa
Merge branch 'eliza/box-layers' into access-logging
hawkw 00d56ed
finish wiring it up
hawkw f69fbdf
...actually we should probably always filter out
hawkw af72a69
allow enabling the access log in tests
hawkw b89dc5f
hmm so having a layer filter there breaks it?
hawkw e86e64d
make access log layer format its own fields
hawkw 69c4cef
implement apache common log format
hawkw 6968620
Merge branch 'main' into eliza/access-logging-2
hawkw c391b7b
Update linkerd/http-access-log/src/lib.rs
hawkw 00b7235
Merge branch 'main' into eliza/access-logging-2
hawkw 21e2a78
remove `chrono` dep
hawkw 128d4a1
update access log to `tracing-subscriber` 0.3
hawkw 4da351a
sort deps
hawkw b204ea0
fix unused field warning
hawkw 6117f72
Merge branch 'main' into eliza/access-logging-2
olix0r b1ceafd
Merge branch 'main' into eliza/access-logging-2
olix0r 7bf594e
Merge branch 'main' into eliza/access-logging-2
hawkw 6985abe
trace: write the access log to stderr
hawkw 8f37ccc
move env configuration out of access_log module
hawkw 74226c3
rm dead code
hawkw 52d6d0a
rm unneeded futures deps
hawkw 6c6a8a5
add some more comments
hawkw File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,19 @@ | ||
| [package] | ||
| name = "linkerd-http-access-log" | ||
| version = "0.1.0" | ||
| authors = ["Linkerd Developers <[email protected]>"] | ||
| license = "Apache-2.0" | ||
| edition = "2018" | ||
| publish = false | ||
|
|
||
| [dependencies] | ||
| futures = "0.3" | ||
| http = "0.2" | ||
| humantime = "2" | ||
| pin-project = "1" | ||
| linkerd-stack = { path = "../stack" } | ||
| linkerd-identity = { path = "../identity" } | ||
| linkerd-tls = { path = "../tls" } | ||
| linkerd-proxy-transport = { path = "../proxy/transport" } | ||
| linkerd-tracing = { path = "../tracing" } | ||
| tracing = "0.1.19" |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,192 @@ | ||
| #![deny(warnings, rust_2018_idioms)] | ||
| #![forbid(unsafe_code)] | ||
|
|
||
| use futures::TryFuture; | ||
| use linkerd_identity as identity; | ||
| use linkerd_proxy_transport::{ClientAddr, Remote}; | ||
| use linkerd_stack as svc; | ||
| use linkerd_tls as tls; | ||
| use linkerd_tracing::access_log::TRACE_TARGET; | ||
| use pin_project::pin_project; | ||
| use std::{ | ||
| future::Future, | ||
| net::SocketAddr, | ||
| pin::Pin, | ||
| task::{Context, Poll}, | ||
| time::{Duration, Instant, SystemTime}, | ||
| }; | ||
| use svc::{NewService, Param}; | ||
| use tracing::{field, span, Level, Span}; | ||
|
|
||
| #[derive(Clone, Debug)] | ||
| pub struct NewAccessLog<N> { | ||
| inner: N, | ||
| } | ||
|
|
||
| #[derive(Clone, Debug)] | ||
| pub struct AccessLogContext<S> { | ||
| inner: S, | ||
| client_addr: SocketAddr, | ||
| client_id: Option<identity::Name>, | ||
| } | ||
|
|
||
| struct ResponseFutureInner { | ||
| span: Span, | ||
| start: Instant, | ||
| processing: Duration, | ||
| } | ||
|
|
||
| #[pin_project] | ||
| pub struct AccessLogFuture<F> { | ||
| data: Option<ResponseFutureInner>, | ||
|
|
||
| #[pin] | ||
| inner: F, | ||
| } | ||
|
|
||
| impl<N> NewAccessLog<N> { | ||
| #[inline] | ||
| pub fn layer() -> impl svc::layer::Layer<N, Service = Self> { | ||
| svc::layer::mk(|inner| NewAccessLog { inner }) | ||
| } | ||
| } | ||
|
|
||
| impl<N, T> NewService<T> for NewAccessLog<N> | ||
| where | ||
| T: Param<tls::ConditionalServerTls> + Param<Remote<ClientAddr>>, | ||
| N: NewService<T>, | ||
| { | ||
| type Service = AccessLogContext<N::Service>; | ||
|
|
||
| fn new_service(&self, target: T) -> Self::Service { | ||
| let Remote(ClientAddr(client_addr)) = target.param(); | ||
| let tls: tls::ConditionalServerTls = target.param(); | ||
| let client_id = tls | ||
| .value() | ||
| .and_then(|tls| tls.client_id().map(|tls::ClientId(name)| name.clone())); | ||
| let inner = self.inner.new_service(target); | ||
| AccessLogContext { | ||
| inner, | ||
| client_addr, | ||
| client_id, | ||
| } | ||
| } | ||
| } | ||
|
|
||
| impl<S, B1, B2> svc::Service<http::Request<B1>> for AccessLogContext<S> | ||
| where | ||
| S: svc::Service<http::Request<B1>, Response = http::Response<B2>>, | ||
| { | ||
| type Response = S::Response; | ||
| type Error = S::Error; | ||
| type Future = AccessLogFuture<S::Future>; | ||
|
|
||
| #[inline] | ||
| fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), S::Error>> { | ||
| self.inner.poll_ready(cx) | ||
| } | ||
|
|
||
| fn call(&mut self, request: http::Request<B1>) -> Self::Future { | ||
| let get_header = |name: http::header::HeaderName| { | ||
| request | ||
| .headers() | ||
| .get(name) | ||
| .and_then(|x| x.to_str().ok()) | ||
| .unwrap_or_default() | ||
| }; | ||
|
|
||
| let trace_id = || { | ||
| let headers = request.headers(); | ||
| headers | ||
| .get("x-b3-traceid") | ||
| .or_else(|| headers.get("x-request-id")) | ||
| .or_else(|| headers.get("x-amzn-trace-id")) | ||
| .and_then(|x| x.to_str().ok()) | ||
| .unwrap_or_default() | ||
| }; | ||
|
|
||
| let span = span!(target: TRACE_TARGET, Level::INFO, "http", | ||
| client.addr = %self.client_addr, | ||
| client.id = self.client_id.as_ref().map(|n| n.as_str()).unwrap_or("-"), | ||
| timestamp = %now(), | ||
| method = request.method().as_str(), | ||
| uri = %request.uri(), | ||
| version = ?request.version(), | ||
| trace_id = trace_id(), | ||
| request_bytes = get_header(http::header::CONTENT_LENGTH), | ||
| status = field::Empty, | ||
| response_bytes = field::Empty, | ||
| total_ns = field::Empty, | ||
| processing_ns = field::Empty, | ||
| user_agent = get_header(http::header::USER_AGENT), | ||
| host = get_header(http::header::HOST), | ||
| ); | ||
|
|
||
| if span.is_disabled() { | ||
| return AccessLogFuture { | ||
| data: None, | ||
| inner: self.inner.call(request), | ||
| }; | ||
| } | ||
|
|
||
| AccessLogFuture { | ||
| data: Some(ResponseFutureInner { | ||
| span, | ||
| start: Instant::now(), | ||
| processing: Duration::from_secs(0), | ||
| }), | ||
| inner: self.inner.call(request), | ||
| } | ||
| } | ||
| } | ||
|
|
||
| impl<F, B2> Future for AccessLogFuture<F> | ||
| where | ||
| F: TryFuture<Ok = http::Response<B2>>, | ||
| { | ||
| type Output = Result<F::Ok, F::Error>; | ||
|
|
||
| fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> { | ||
| let mut this = self.project(); | ||
|
|
||
| let data: &mut ResponseFutureInner = match &mut this.data { | ||
| Some(data) => data, | ||
| None => return this.inner.try_poll(cx), | ||
| }; | ||
|
|
||
| let _enter = data.span.enter(); | ||
| let poll_start = Instant::now(); | ||
|
|
||
| let response: http::Response<B2> = match this.inner.try_poll(cx) { | ||
| Poll::Pending => { | ||
| data.processing += Instant::now().duration_since(poll_start); | ||
| return Poll::Pending; | ||
| } | ||
| Poll::Ready(Err(e)) => return Poll::Ready(Err(e)), | ||
| Poll::Ready(Ok(response)) => response, | ||
| }; | ||
|
|
||
| let now = Instant::now(); | ||
| let total_ns = now.duration_since(data.start).as_nanos(); | ||
| let processing_ns = (now.duration_since(poll_start) + data.processing).as_nanos(); | ||
|
|
||
| let span = &data.span; | ||
|
|
||
| response | ||
| .headers() | ||
| .get(http::header::CONTENT_LENGTH) | ||
| .and_then(|x| x.to_str().ok()) | ||
| .map(|x| span.record("response_bytes", &x)); | ||
|
|
||
| span.record("status", &response.status().as_u16()); | ||
| span.record("total_ns", &field::display(total_ns)); | ||
| span.record("processing_ns", &field::display(processing_ns)); | ||
|
|
||
| Poll::Ready(Ok(response)) | ||
| } | ||
| } | ||
|
|
||
| #[inline] | ||
| fn now() -> humantime::Rfc3339Timestamp { | ||
| humantime::format_rfc3339(SystemTime::now()) | ||
| } | ||
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think it's worth leaving a comment here making it clear that the
span!body is only materialized when access logging is enabled bylinkerd_tracing::access_log's initializer. I.e. this is expected to be free when tracing is not enabled.Maybe also worth leaving a comment on the
fn layersummarizing this, too.