/build/source/nativelink-util/src/telemetry.rs
Line | Count | Source |
1 | | // Copyright 2025 The NativeLink Authors. All rights reserved. |
2 | | // |
3 | | // Licensed under the Functional Source License, Version 1.1, Apache 2.0 Future License (the "License"); |
4 | | // you may not use this file except in compliance with the License. |
5 | | // You may obtain a copy of the License at |
6 | | // |
7 | | // See LICENSE file for details |
8 | | // |
9 | | // Unless required by applicable law or agreed to in writing, software |
10 | | // distributed under the License is distributed on an "AS IS" BASIS, |
11 | | // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
12 | | // See the License for the specific language governing permissions and |
13 | | // limitations under the License. |
14 | | |
15 | | use core::default::Default; |
16 | | use std::collections::HashMap; |
17 | | use std::env; |
18 | | use std::sync::{Arc, OnceLock}; |
19 | | |
20 | | use base64::Engine; |
21 | | use base64::prelude::BASE64_STANDARD_NO_PAD; |
22 | | use ginepro::LoadBalancedChannel; |
23 | | use hyper::http::Response; |
24 | | use nativelink_error::{Code, ResultExt, make_err}; |
25 | | use nativelink_proto::build::bazel::remote::execution::v2::RequestMetadata; |
26 | | use opentelemetry::propagation::TextMapCompositePropagator; |
27 | | use opentelemetry::trace::{TraceContextExt, Tracer, TracerProvider}; |
28 | | use opentelemetry::{KeyValue, global}; |
29 | | use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge; |
30 | | use opentelemetry_http::HeaderExtractor; |
31 | | use opentelemetry_otlp::{ |
32 | | LogExporter, MetricExporter, Protocol, SpanExporter, WithExportConfig, WithTonicConfig, |
33 | | }; |
34 | | use opentelemetry_sdk::Resource; |
35 | | use opentelemetry_sdk::logs::SdkLoggerProvider; |
36 | | use opentelemetry_sdk::metrics::SdkMeterProvider; |
37 | | use opentelemetry_sdk::propagation::{BaggagePropagator, TraceContextPropagator}; |
38 | | use opentelemetry_sdk::trace::SdkTracerProvider; |
39 | | use opentelemetry_semantic_conventions::attribute::ENDUSER_ID; |
40 | | use prost::Message; |
41 | | use tracing::debug; |
42 | | use tracing::metadata::LevelFilter; |
43 | | use tracing_opentelemetry::{MetricsLayer, layer}; |
44 | | use tracing_subscriber::filter::Directive; |
45 | | use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt; |
46 | | use tracing_subscriber::util::SubscriberInitExt; |
47 | | use tracing_subscriber::{EnvFilter, Layer, Registry, fmt, registry}; |
48 | | use uuid::Uuid; |
49 | | |
50 | | use crate::metrics::record_rpc_served; |
51 | | use crate::origin_event::{BAZEL_METADATA_KEY, request_metadata_to_baggage}; |
52 | | |
53 | | /// The OTLP "service.name" field for all nativelink services. |
54 | | const NATIVELINK_SERVICE_NAME: &str = "nativelink"; |
55 | | |
56 | | // An `EnvFilter` to filter out non-nativelink information. |
57 | | // |
58 | | // See: https://github.com/open-telemetry/opentelemetry-rust/issues/2877 |
59 | | // |
60 | | // Note that `EnvFilter` doesn't implement `clone`, so create a new one for |
61 | | // each telemetry kind. |
62 | 0 | fn otlp_filter() -> EnvFilter { |
63 | 0 | fn expect_parse(directive: &str) -> Directive { |
64 | 0 | directive |
65 | 0 | .parse() |
66 | 0 | .unwrap_or_else(|_| panic!("Static directive '{directive}' failed to parse")) |
67 | 0 | } |
68 | | |
69 | 0 | EnvFilter::builder() |
70 | 0 | .with_default_directive(LevelFilter::INFO.into()) |
71 | 0 | .from_env_lossy() |
72 | 0 | .add_directive(expect_parse("hyper=off")) |
73 | 0 | .add_directive(expect_parse("tonic=off")) |
74 | 0 | .add_directive(expect_parse("h2=off")) |
75 | 0 | .add_directive(expect_parse("reqwest=off")) |
76 | 0 | .add_directive(expect_parse("tower=off")) |
77 | 0 | } |
78 | | |
79 | | // Create a tracing layer intended for stdout printing. |
80 | | // |
81 | | // The output of this layer is configurable via the `NL_LOG` environment |
82 | | // variable. |
83 | 0 | fn tracing_stdout_layer() -> impl Layer<Registry> { |
84 | 0 | let nl_log_fmt = env::var("NL_LOG").unwrap_or_else(|_| "pretty".to_string()); |
85 | | |
86 | 0 | let stdout_filter = otlp_filter(); |
87 | | |
88 | 0 | match nl_log_fmt.as_str() { |
89 | 0 | "compact" => fmt::layer() |
90 | 0 | .compact() |
91 | 0 | .with_timer(fmt::time::time()) |
92 | 0 | .with_filter(stdout_filter) |
93 | 0 | .boxed(), |
94 | 0 | "json" => fmt::layer() |
95 | 0 | .json() |
96 | 0 | .with_timer(fmt::time::time()) |
97 | 0 | .with_filter(stdout_filter) |
98 | 0 | .boxed(), |
99 | 0 | _ => fmt::layer() |
100 | 0 | .pretty() |
101 | 0 | .with_timer(fmt::time::time()) |
102 | 0 | .with_filter(stdout_filter) |
103 | 0 | .boxed(), |
104 | | } |
105 | 0 | } |
106 | | |
107 | | /// Initialize tracing with OpenTelemetry support. |
108 | | /// |
109 | | /// # Errors |
110 | | /// |
111 | | /// Returns `Err` if logging was already initialized or if the exporters can't |
112 | | /// be initialized. |
113 | 0 | pub async fn init_tracing() -> Result<(), nativelink_error::Error> { |
114 | | static INITIALIZED: OnceLock<()> = OnceLock::new(); |
115 | | |
116 | | if INITIALIZED.get().is_some() { |
117 | | return Err(make_err!(Code::Internal, "Logging already initialized")); |
118 | | } |
119 | | |
120 | | // We currently use a UUIDv4 for "service.instance.id" as per: |
121 | | // https://opentelemetry.io/docs/specs/semconv/attributes-registry/service/ |
122 | | // This might change as we get a better understanding of its use cases in the |
123 | | // context of broader observability infrastructure. |
124 | | let resource = Resource::builder() |
125 | | .with_service_name(NATIVELINK_SERVICE_NAME) |
126 | | .with_attribute(KeyValue::new( |
127 | | "service.instance.id", |
128 | | Uuid::new_v4().to_string(), |
129 | | )) |
130 | | .build(); |
131 | | |
132 | | let propagator = TextMapCompositePropagator::new(vec![ |
133 | | Box::new(BaggagePropagator::new()), |
134 | | Box::new(TraceContextPropagator::new()), |
135 | | ]); |
136 | | global::set_text_map_propagator(propagator); |
137 | | |
138 | | let maybe_channel = maybe_load_balanced_channel().await; |
139 | | |
140 | | // Logs |
141 | | let mut log_exporter_builder = LogExporter::builder().with_tonic(); |
142 | | if let Some(channel) = maybe_channel.clone() { |
143 | | log_exporter_builder = log_exporter_builder.with_channel(channel.into()); |
144 | | } |
145 | | let otlp_log_layer = OpenTelemetryTracingBridge::new( |
146 | | &SdkLoggerProvider::builder() |
147 | | .with_resource(resource.clone()) |
148 | | .with_batch_exporter( |
149 | | log_exporter_builder |
150 | | .with_protocol(Protocol::Grpc) |
151 | | .build() |
152 | | .map_err(|e| make_err!(Code::Internal, "{e}")) |
153 | | .err_tip(|| "While creating OpenTelemetry OTLP Log exporter")?, |
154 | | ) |
155 | | .build(), |
156 | | ) |
157 | | .with_filter(otlp_filter()); |
158 | | |
159 | | // Traces |
160 | | let mut span_exporter_builder = SpanExporter::builder().with_tonic(); |
161 | | if let Some(channel) = maybe_channel.clone() { |
162 | | span_exporter_builder = span_exporter_builder.with_channel(channel.into()); |
163 | | } |
164 | | let otlp_trace_layer = layer() |
165 | | .with_tracer( |
166 | | SdkTracerProvider::builder() |
167 | | .with_resource(resource.clone()) |
168 | | .with_batch_exporter( |
169 | | span_exporter_builder |
170 | | .with_protocol(Protocol::Grpc) |
171 | | .build() |
172 | | .map_err(|e| make_err!(Code::Internal, "{e}")) |
173 | | .err_tip(|| "While creating OpenTelemetry OTLP Span exporter")?, |
174 | | ) |
175 | | .build() |
176 | | .tracer(NATIVELINK_SERVICE_NAME), |
177 | | ) |
178 | | .with_filter(otlp_filter()); |
179 | | |
180 | | // Metrics |
181 | | let mut metric_exporter_builder = MetricExporter::builder().with_tonic(); |
182 | | if let Some(channel) = maybe_channel { |
183 | | metric_exporter_builder = metric_exporter_builder.with_channel(channel.into()); |
184 | | } |
185 | | let meter_provider = SdkMeterProvider::builder() |
186 | | .with_resource(resource) |
187 | | .with_periodic_exporter( |
188 | | metric_exporter_builder |
189 | | .with_protocol(Protocol::Grpc) |
190 | | .build() |
191 | | .map_err(|e| make_err!(Code::Internal, "{e}")) |
192 | | .err_tip(|| "While creating OpenTelemetry OTLP Metric exporter")?, |
193 | | ) |
194 | | .build(); |
195 | | |
196 | | global::set_meter_provider(meter_provider.clone()); |
197 | | |
198 | | let otlp_metrics_layer = MetricsLayer::new(meter_provider).with_filter(otlp_filter()); |
199 | | |
200 | | registry() |
201 | | .with(tracing_stdout_layer()) |
202 | | .with(otlp_log_layer) |
203 | | .with(otlp_trace_layer) |
204 | | .with(otlp_metrics_layer) |
205 | | .init(); |
206 | | |
207 | | INITIALIZED.set(()).unwrap_or(()); |
208 | | |
209 | | Ok(()) |
210 | | } |
211 | | |
212 | | /// Environment variable pointing OTLP exporters at a load-balanced endpoint. |
213 | | pub const NL_OTEL_ENDPOINT: &str = "NL_OTEL_ENDPOINT"; |
214 | | |
215 | | /// Creates a load-balanced gRPC channel for the endpoint configured via |
216 | | /// [`NL_OTEL_ENDPOINT`], or returns `None` if the variable isn't set. |
217 | | /// |
218 | | /// Public so that integration tests can verify that exporters behave the |
219 | | /// same with and without the load-balanced channel. |
220 | 2 | pub async fn maybe_load_balanced_channel() -> Option<LoadBalancedChannel> { |
221 | 2 | match env::var(NL_OTEL_ENDPOINT) { |
222 | 0 | Ok(endpoint) => { |
223 | 0 | let url = Url::parse(endpoint.as_str()) |
224 | 0 | .map_err(|e| { |
225 | 0 | make_err!(Code::Internal, "Unable to parse endpoint {endpoint}: {e:?}") |
226 | 0 | }) |
227 | 0 | .unwrap(); |
228 | | |
229 | 0 | let host = url |
230 | 0 | .host() |
231 | 0 | .err_tip(|| format!("Unable to get host from endpoint {endpoint}")) |
232 | 0 | .unwrap(); |
233 | 0 | let port = url |
234 | 0 | .port() |
235 | 0 | .err_tip(|| format!("Unable to get port from endpoint {endpoint}")) |
236 | 0 | .unwrap(); |
237 | | |
238 | | Some( |
239 | 0 | LoadBalancedChannel::builder((host.to_string(), port)) |
240 | 0 | .channel() |
241 | 0 | .await |
242 | 0 | .map_err(|e| make_err!(Code::Internal, "Invalid hostname '{endpoint}': {e}")) |
243 | 0 | .unwrap(), |
244 | | ) |
245 | | } |
246 | 2 | Err(_) => None, |
247 | | } |
248 | 2 | } |
249 | | /// This is the header that bazel sends when using the `--remote_header` flag. |
250 | | /// TODO(palfrey): Bazel supports other headers, and we should optimize their usage. |
251 | | const BAZEL_REQUESTMETADATA_HEADER: &str = "build.bazel.remote.execution.v2.requestmetadata-bin"; |
252 | | |
253 | | use opentelemetry::baggage::BaggageExt; |
254 | | use opentelemetry::context::FutureExt; |
255 | | use url::Url; |
256 | | |
257 | | /// ASCII headers from an inbound client request, stored in the task context |
258 | | /// so that outgoing upstream calls can forward them (e.g. JWT auth tokens). |
259 | | #[derive(Clone, Debug, Default)] |
260 | | pub struct ClientHeaders(pub Arc<HashMap<String, String>>); |
261 | | |
262 | | #[derive(Debug, Clone)] |
263 | | pub struct OtlpMiddleware<S> { |
264 | | inner: S, |
265 | | identity_required: bool, |
266 | | } |
267 | | |
268 | | impl<S> OtlpMiddleware<S> { |
269 | 3 | const fn new(inner: S, identity_required: bool) -> Self { |
270 | 3 | Self { |
271 | 3 | inner, |
272 | 3 | identity_required, |
273 | 3 | } |
274 | 3 | } |
275 | | } |
276 | | |
277 | | impl<S, ReqBody, ResBody> tower::Service<hyper::http::Request<ReqBody>> for OtlpMiddleware<S> |
278 | | where |
279 | | S: tower::Service<hyper::http::Request<ReqBody>, Response = Response<ResBody>> |
280 | | + Clone |
281 | | + Send |
282 | | + 'static, |
283 | | S::Future: Send + 'static, |
284 | | ReqBody: core::fmt::Debug + Send + 'static, |
285 | | ResBody: From<String> + Send + 'static + Default, |
286 | | { |
287 | | type Response = S::Response; |
288 | | type Error = S::Error; |
289 | | type Future = futures::future::BoxFuture<'static, Result<Self::Response, Self::Error>>; |
290 | | |
291 | 3 | fn poll_ready( |
292 | 3 | &mut self, |
293 | 3 | cx: &mut core::task::Context<'_>, |
294 | 3 | ) -> core::task::Poll<Result<(), Self::Error>> { |
295 | 3 | self.inner.poll_ready(cx) |
296 | 3 | } |
297 | | |
298 | 3 | fn call(&mut self, req: hyper::http::Request<ReqBody>) -> Self::Future { |
299 | | // We must take the current `inner` and not the clone. |
300 | | // See: <https://docs.rs/tower/latest/tower/trait.Service.html#be-careful-when-cloning-inner-services> |
301 | 3 | let clone = self.inner.clone(); |
302 | 3 | let mut inner = core::mem::replace(&mut self.inner, clone); |
303 | | |
304 | | // Capture all ASCII-valued request headers before req is consumed, so |
305 | | // they can be forwarded to upstream services (e.g. JWT auth tokens). |
306 | 3 | let client_headers = ClientHeaders(Arc::new( |
307 | 3 | req.headers() |
308 | 3 | .iter() |
309 | 3 | .filter_map(|(name, value)| {2 |
310 | 2 | value |
311 | 2 | .to_str() |
312 | 2 | .ok() |
313 | 2 | .map(|v| (name.as_str().to_lowercase(), v.to_string())) |
314 | 2 | }) |
315 | 3 | .collect(), |
316 | | )); |
317 | | |
318 | 3 | let parent_cx = global::get_text_map_propagator(|propagator| { |
319 | 3 | propagator.extract(&HeaderExtractor(req.headers())) |
320 | 3 | }); |
321 | | |
322 | 3 | let identity = parent_cx |
323 | 3 | .baggage() |
324 | 3 | .get(ENDUSER_ID) |
325 | 3 | .map(|value| value.as_str()1 .to_string1 ()) |
326 | 3 | .unwrap_or_default(); |
327 | | |
328 | 3 | if identity.is_empty() { |
329 | 2 | if self.identity_required { |
330 | 0 | return Box::pin(async move { |
331 | 0 | Ok(tonic::Status::failed_precondition( |
332 | 0 | r" |
333 | 0 |
|
334 | 0 | NativeLink instance configured to require this OpenTelemetry Baggage header: |
335 | 0 |
|
336 | 0 | `Baggage: enduser.id=YOUR_IDENTITY` |
337 | 0 |
|
338 | 0 | ", |
339 | 0 | ) |
340 | 0 | .into_http()) |
341 | 0 | }); |
342 | 2 | } |
343 | | } else { |
344 | 1 | debug!("Baggage enduser.id: {identity}"); |
345 | | } |
346 | | |
347 | 3 | let tracer = global::tracer("origin_middleware"); |
348 | 3 | let span = tracer |
349 | 3 | .span_builder("origin_request") |
350 | 3 | .with_kind(opentelemetry::trace::SpanKind::Server) |
351 | 3 | .start_with_context(&tracer, &parent_cx); |
352 | | |
353 | 3 | let mut cx = parent_cx.with_span(span); |
354 | | |
355 | 3 | if let Some(bazel_header0 ) = req.headers().get(BAZEL_REQUESTMETADATA_HEADER) |
356 | 0 | && let Ok(decoded) = BASE64_STANDARD_NO_PAD.decode(bazel_header.as_bytes()) |
357 | 0 | && let Ok(metadata) = RequestMetadata::decode(decoded.as_slice()) |
358 | | { |
359 | 0 | let metadata_str = format!("{metadata:?}"); |
360 | 0 | debug!("Baggage Bazel request metadata: {metadata_str}"); |
361 | 0 | cx = cx.with_baggage(vec![ |
362 | 0 | KeyValue::new(BAZEL_METADATA_KEY, request_metadata_to_baggage(&metadata)), |
363 | 0 | KeyValue::new(ENDUSER_ID, identity), |
364 | | ]); |
365 | 3 | } |
366 | | |
367 | 3 | let cx = cx.with_value(client_headers); |
368 | | // Rate, errors and latency for every gRPC service, taken here because |
369 | | // this layer already wraps all of them. |
370 | 3 | let route = req.uri().path().to_string(); |
371 | 3 | let started = std::time::Instant::now(); |
372 | 3 | Box::pin(async move { |
373 | 3 | let result = inner.call(req).with_context(cx).await; |
374 | 3 | if let Ok(response) = &result { |
375 | 3 | record_rpc_served( |
376 | 3 | &route, |
377 | 3 | grpc_status_of(response.headers()), |
378 | 3 | started.elapsed().as_secs_f64(), |
379 | 3 | ); |
380 | 3 | }0 |
381 | 3 | result |
382 | 3 | }) |
383 | 3 | } |
384 | | } |
385 | | |
386 | | /// Reads the gRPC status from a response. |
387 | | /// |
388 | | /// Tonic puts `grpc-status` in the headers when it fails before streaming and |
389 | | /// in the trailers otherwise. Trailers are not available here without |
390 | | /// consuming the body, so a call that got far enough to stream is reported as |
391 | | /// OK. Transport-level failures never reach this point at all. |
392 | 3 | fn grpc_status_of(headers: &hyper::http::HeaderMap) -> i32 { |
393 | 3 | headers |
394 | 3 | .get("grpc-status") |
395 | 3 | .and_then(|value| value0 .to_str0 ().ok0 ()) |
396 | 3 | .and_then(|value| value0 .parse0 ::<i32>().ok0 ()) |
397 | 3 | .unwrap_or(0) |
398 | 3 | } |
399 | | |
400 | | #[derive(Debug, Clone, Copy)] |
401 | | pub struct OtlpLayer { |
402 | | identity_required: bool, |
403 | | } |
404 | | |
405 | | impl OtlpLayer { |
406 | 0 | pub const fn new(identity_required: bool) -> Self { |
407 | 0 | Self { identity_required } |
408 | 0 | } |
409 | | } |
410 | | |
411 | | impl<S> tower::Layer<S> for OtlpLayer { |
412 | | type Service = OtlpMiddleware<S>; |
413 | | |
414 | 3 | fn layer(&self, service: S) -> Self::Service { |
415 | 3 | OtlpMiddleware::new(service, self.identity_required) |
416 | 3 | } |
417 | | } |
418 | | |
419 | | #[cfg(test)] |
420 | | mod tests { |
421 | | use nativelink_macro::nativelink_test; |
422 | | use serial_test::serial; |
423 | | |
424 | | use super::*; |
425 | | |
426 | | // ginepro's default resolver (hickory-dns) reads /etc/resolv.conf, which |
427 | | // doesn't exist in sandboxed environments (e.g. Nix builds). |
428 | | #[cfg(unix)] |
429 | 1 | fn dns_configured() -> bool { |
430 | 1 | std::path::Path::new("/etc/resolv.conf").exists() |
431 | 1 | } |
432 | | #[cfg(not(unix))] |
433 | | const fn dns_configured() -> bool { |
434 | | true |
435 | | } |
436 | | |
437 | | // Env vars are process-global, so concurrent writes would be a data race |
438 | | // on Unix. `#[serial(env)]` serializes all env-mutating tests. |
439 | | #[serial(env)] |
440 | | #[nativelink_test("crate")] |
441 | | async fn channel_absent_when_env_not_set() { |
442 | | // SAFETY: `#[serial(env)]` serializes all env-var writes across tests. |
443 | | unsafe { env::remove_var(NL_OTEL_ENDPOINT) }; |
444 | | assert!( |
445 | | maybe_load_balanced_channel().await.is_none(), |
446 | | "Expected None when {NL_OTEL_ENDPOINT} is unset" |
447 | | ); |
448 | | } |
449 | | |
450 | | #[serial(env)] |
451 | | #[nativelink_test("crate")] |
452 | | async fn channel_present_when_valid_endpoint_set() { |
453 | | if !dns_configured() { |
454 | | eprintln!( |
455 | | "Skipping channel_present_when_valid_endpoint_set: no DNS configuration \ |
456 | | available (e.g. sandboxed Nix build)" |
457 | | ); |
458 | | return; |
459 | | } |
460 | | // SAFETY: `#[serial(env)]` serializes all env-var writes across tests. |
461 | | unsafe { env::set_var(NL_OTEL_ENDPOINT, "http://localhost:4317") }; |
462 | | let result = maybe_load_balanced_channel().await; |
463 | | // SAFETY: `#[serial(env)]` serializes all env-var writes across tests. |
464 | | unsafe { env::remove_var(NL_OTEL_ENDPOINT) }; |
465 | | assert!( |
466 | | result.is_some(), |
467 | | "Expected Some(channel) when {NL_OTEL_ENDPOINT} points to a valid URL" |
468 | | ); |
469 | | } |
470 | | } |