|
| 1 | +#![deny(warnings, rust_2018_idioms)] |
| 2 | +#![forbid(unsafe_code)] |
| 3 | + |
| 4 | +use futures_core::TryFuture; |
| 5 | +use linkerd_identity as identity; |
| 6 | +use linkerd_proxy_transport::{ClientAddr, Remote}; |
| 7 | +use linkerd_stack as svc; |
| 8 | +use linkerd_tls as tls; |
| 9 | +use linkerd_tracing::access_log::TRACE_TARGET; |
| 10 | +use pin_project::pin_project; |
| 11 | +use std::{ |
| 12 | + future::Future, |
| 13 | + net::SocketAddr, |
| 14 | + pin::Pin, |
| 15 | + task::{Context, Poll}, |
| 16 | + time::{Duration, Instant, SystemTime}, |
| 17 | +}; |
| 18 | +use svc::{NewService, Param}; |
| 19 | +use tracing::{field, span, Level, Span}; |
| 20 | + |
| 21 | +#[derive(Clone, Debug)] |
| 22 | +pub struct NewAccessLog<N> { |
| 23 | + inner: N, |
| 24 | +} |
| 25 | + |
| 26 | +#[derive(Clone, Debug)] |
| 27 | +pub struct AccessLogContext<S> { |
| 28 | + inner: S, |
| 29 | + client_addr: SocketAddr, |
| 30 | + client_id: Option<identity::Name>, |
| 31 | +} |
| 32 | + |
| 33 | +struct ResponseFutureInner { |
| 34 | + span: Span, |
| 35 | + start: Instant, |
| 36 | + processing: Duration, |
| 37 | +} |
| 38 | + |
| 39 | +#[pin_project] |
| 40 | +pub struct AccessLogFuture<F> { |
| 41 | + data: Option<ResponseFutureInner>, |
| 42 | + |
| 43 | + #[pin] |
| 44 | + inner: F, |
| 45 | +} |
| 46 | + |
| 47 | +impl<N> NewAccessLog<N> { |
| 48 | + /// Returns a new `NewAccessLog` layer that wraps an inner service with |
| 49 | + /// access logging middleware. |
| 50 | + /// |
| 51 | + /// The access log is recorded by adding a `tracing` span to the service's |
| 52 | + /// future. If access logging is not enabled by the `tracing` subscriber, |
| 53 | + /// this span will never be enabled, and it can be skipped cheaply. When |
| 54 | + /// access logging *is* enabled, additional data will be recorded when the |
| 55 | + /// response future completes. |
| 56 | + /// |
| 57 | + /// Recording the access log will introduce additional overhead in the |
| 58 | + /// request path, but this is largely avoided when access logging is not |
| 59 | + /// enabled. |
| 60 | + #[inline] |
| 61 | + pub fn layer() -> impl svc::layer::Layer<N, Service = Self> { |
| 62 | + svc::layer::mk(|inner| NewAccessLog { inner }) |
| 63 | + } |
| 64 | +} |
| 65 | + |
| 66 | +impl<N, T> NewService<T> for NewAccessLog<N> |
| 67 | +where |
| 68 | + T: Param<tls::ConditionalServerTls> + Param<Remote<ClientAddr>>, |
| 69 | + N: NewService<T>, |
| 70 | +{ |
| 71 | + type Service = AccessLogContext<N::Service>; |
| 72 | + |
| 73 | + fn new_service(&self, target: T) -> Self::Service { |
| 74 | + let Remote(ClientAddr(client_addr)) = target.param(); |
| 75 | + let tls: tls::ConditionalServerTls = target.param(); |
| 76 | + let client_id = tls |
| 77 | + .value() |
| 78 | + .and_then(|tls| tls.client_id().map(|tls::ClientId(name)| name.clone())); |
| 79 | + let inner = self.inner.new_service(target); |
| 80 | + AccessLogContext { |
| 81 | + inner, |
| 82 | + client_addr, |
| 83 | + client_id, |
| 84 | + } |
| 85 | + } |
| 86 | +} |
| 87 | + |
| 88 | +impl<S, B1, B2> svc::Service<http::Request<B1>> for AccessLogContext<S> |
| 89 | +where |
| 90 | + S: svc::Service<http::Request<B1>, Response = http::Response<B2>>, |
| 91 | +{ |
| 92 | + type Response = S::Response; |
| 93 | + type Error = S::Error; |
| 94 | + type Future = AccessLogFuture<S::Future>; |
| 95 | + |
| 96 | + #[inline] |
| 97 | + fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), S::Error>> { |
| 98 | + self.inner.poll_ready(cx) |
| 99 | + } |
| 100 | + |
| 101 | + fn call(&mut self, request: http::Request<B1>) -> Self::Future { |
| 102 | + let get_header = |name: http::header::HeaderName| { |
| 103 | + request |
| 104 | + .headers() |
| 105 | + .get(name) |
| 106 | + .and_then(|x| x.to_str().ok()) |
| 107 | + .unwrap_or_default() |
| 108 | + }; |
| 109 | + |
| 110 | + let trace_id = || { |
| 111 | + let headers = request.headers(); |
| 112 | + headers |
| 113 | + .get("x-b3-traceid") |
| 114 | + .or_else(|| headers.get("x-request-id")) |
| 115 | + .or_else(|| headers.get("x-amzn-trace-id")) |
| 116 | + .and_then(|x| x.to_str().ok()) |
| 117 | + .unwrap_or_default() |
| 118 | + }; |
| 119 | + |
| 120 | + let span = span!(target: TRACE_TARGET, Level::INFO, "http", |
| 121 | + client.addr = %self.client_addr, |
| 122 | + client.id = self.client_id.as_ref().map(|n| n.as_str()).unwrap_or("-"), |
| 123 | + timestamp = %now(), |
| 124 | + method = request.method().as_str(), |
| 125 | + uri = %request.uri(), |
| 126 | + version = ?request.version(), |
| 127 | + trace_id = trace_id(), |
| 128 | + request_bytes = get_header(http::header::CONTENT_LENGTH), |
| 129 | + status = field::Empty, |
| 130 | + response_bytes = field::Empty, |
| 131 | + total_ns = field::Empty, |
| 132 | + processing_ns = field::Empty, |
| 133 | + user_agent = get_header(http::header::USER_AGENT), |
| 134 | + host = get_header(http::header::HOST), |
| 135 | + ); |
| 136 | + |
| 137 | + // The access log span is only enabled by the `tracing` subscriber if |
| 138 | + // access logs are being recorded. If it's disabled, we can skip |
| 139 | + // recording additional data in the response future. |
| 140 | + if span.is_disabled() { |
| 141 | + return AccessLogFuture { |
| 142 | + data: None, |
| 143 | + inner: self.inner.call(request), |
| 144 | + }; |
| 145 | + } |
| 146 | + |
| 147 | + AccessLogFuture { |
| 148 | + data: Some(ResponseFutureInner { |
| 149 | + span, |
| 150 | + start: Instant::now(), |
| 151 | + processing: Duration::from_secs(0), |
| 152 | + }), |
| 153 | + inner: self.inner.call(request), |
| 154 | + } |
| 155 | + } |
| 156 | +} |
| 157 | + |
| 158 | +impl<F, B2> Future for AccessLogFuture<F> |
| 159 | +where |
| 160 | + F: TryFuture<Ok = http::Response<B2>>, |
| 161 | +{ |
| 162 | + type Output = Result<F::Ok, F::Error>; |
| 163 | + |
| 164 | + fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> { |
| 165 | + let mut this = self.project(); |
| 166 | + |
| 167 | + let data: &mut ResponseFutureInner = match &mut this.data { |
| 168 | + Some(data) => data, |
| 169 | + None => return this.inner.try_poll(cx), |
| 170 | + }; |
| 171 | + |
| 172 | + let _enter = data.span.enter(); |
| 173 | + let poll_start = Instant::now(); |
| 174 | + |
| 175 | + let response: http::Response<B2> = match this.inner.try_poll(cx) { |
| 176 | + Poll::Pending => { |
| 177 | + data.processing += Instant::now().duration_since(poll_start); |
| 178 | + return Poll::Pending; |
| 179 | + } |
| 180 | + Poll::Ready(Err(e)) => return Poll::Ready(Err(e)), |
| 181 | + Poll::Ready(Ok(response)) => response, |
| 182 | + }; |
| 183 | + |
| 184 | + let now = Instant::now(); |
| 185 | + let total_ns = now.duration_since(data.start).as_nanos(); |
| 186 | + let processing_ns = (now.duration_since(poll_start) + data.processing).as_nanos(); |
| 187 | + |
| 188 | + let span = &data.span; |
| 189 | + |
| 190 | + response |
| 191 | + .headers() |
| 192 | + .get(http::header::CONTENT_LENGTH) |
| 193 | + .and_then(|x| x.to_str().ok()) |
| 194 | + .map(|x| span.record("response_bytes", &x)); |
| 195 | + |
| 196 | + span.record("status", &response.status().as_u16()); |
| 197 | + span.record("total_ns", &field::display(total_ns)); |
| 198 | + span.record("processing_ns", &field::display(processing_ns)); |
| 199 | + |
| 200 | + Poll::Ready(Ok(response)) |
| 201 | + } |
| 202 | +} |
| 203 | + |
| 204 | +#[inline] |
| 205 | +fn now() -> humantime::Rfc3339Timestamp { |
| 206 | + humantime::format_rfc3339(SystemTime::now()) |
| 207 | +} |
0 commit comments