Skip to content

Commit d9e98a2

Browse files
fix(otel): emit one correlated signal set and shut providers down cleanly
agent-identity: unknown agent-persona: generalist agent-supervisor: unavailable agent-tool: OMP agent-tool-version: 18.0.3 agent-runtime: OMP 18.0.3 tooling-profile: dotfiles@e4789b0
1 parent a3fe3d0 commit d9e98a2

3 files changed

Lines changed: 142 additions & 98 deletions

File tree

src/run.rs

Lines changed: 3 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -1800,7 +1800,6 @@ fn finish_reconcile_pass(span: &tracing::Span, report: &UpReport) {
18001800
pub fn up_once(root: &Path, this_host: &str, runner: &dyn Runner) -> anyhow::Result<UpReport> {
18011801
let task_context = TaskCompileContext::current(root.to_path_buf())?;
18021802
let mut debounce = LivenessDebounce::new(DEBOUNCE_GRACE);
1803-
let pass_span = crate::telemetry::PassSpan::start(this_host);
18041803
let started = Instant::now();
18051804
let span = reconcile_span(this_host);
18061805
let report = {
@@ -1817,7 +1816,6 @@ pub fn up_once(root: &Path, this_host: &str, runner: &dyn Runner) -> anyhow::Res
18171816
finish_reconcile_pass(&span, &report);
18181817
report
18191818
};
1820-
pass_span.finish(report.crash_loops.len(), report.unparked.len());
18211819
crate::metrics::record_reconcile_pass(started.elapsed(), !report.errors.is_empty());
18221820
Ok(report)
18231821
}
@@ -1895,7 +1893,6 @@ pub(crate) fn reconcile_pass_specs_with_sessions(
18951893
presentation_cursor: &mut PresentationPatchCursor,
18961894
) -> UpReport {
18971895
let started = Instant::now();
1898-
let pass_span = crate::telemetry::PassSpan::start(this_host);
18991896
let span = reconcile_span(this_host);
19001897
let mut report = UpReport::default();
19011898
{
@@ -1917,7 +1914,6 @@ pub(crate) fn reconcile_pass_specs_with_sessions(
19171914
}
19181915
finish_reconcile_pass(&span, &report);
19191916
}
1920-
pass_span.finish(report.crash_loops.len(), report.unparked.len());
19211917
crate::metrics::record_reconcile_pass(started.elapsed(), !report.errors.is_empty());
19221918
report
19231919
}
@@ -1960,7 +1956,8 @@ pub fn up_once_selected(
19601956
this_host: &str,
19611957
runner: &dyn Runner,
19621958
) -> anyhow::Result<UpReport> {
1963-
let pass_span = crate::telemetry::PassSpan::start(this_host);
1959+
let span = reconcile_span(this_host);
1960+
let _entered = span.enter();
19641961
let _catalog_lock = crate::CatalogLock::shared(catalog_root)
19651962
.context("acquire shared catalog-authoring lock for selected reconcile")?;
19661963
let found = crate::discovery::discover(catalog_root);
@@ -2007,7 +2004,7 @@ pub fn up_once_selected(
20072004
|| Ok(()),
20082005
)?;
20092006
report.absorb(execution);
2010-
pass_span.finish(report.crash_loops.len(), report.unparked.len());
2007+
finish_reconcile_pass(&span, &report);
20112008
Ok(report)
20122009
}
20132010

@@ -2322,7 +2319,6 @@ fn up_loop_until(
23222319
let mut pre = UpReport::default();
23232320
park_channel.grant_requests(&mut cap, &mut pre);
23242321
let mut report = {
2325-
let pass_span = crate::telemetry::PassSpan::start(this_host);
23262322
let started = Instant::now();
23272323
let span = reconcile_span(this_host);
23282324
let pass = {
@@ -2339,7 +2335,6 @@ fn up_loop_until(
23392335
finish_reconcile_pass(&span, &pass);
23402336
pass
23412337
};
2342-
pass_span.finish(pass.crash_loops.len(), pass.unparked.len());
23432338
crate::metrics::record_reconcile_pass(started.elapsed(), !pass.errors.is_empty());
23442339
pass
23452340
};

src/telemetry.rs

Lines changed: 19 additions & 70 deletions
Original file line numberDiff line numberDiff line change
@@ -13,11 +13,9 @@
1313
//! carry its trace/span ids.
1414
1515
use std::io::IsTerminal as _;
16-
use std::sync::atomic::{AtomicBool, Ordering};
1716

18-
use opentelemetry::trace::{Span as _, Tracer as _};
19-
use opentelemetry::KeyValue;
2017
use opentelemetry::trace::TracerProvider as _;
18+
use opentelemetry::KeyValue;
2119
use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
2220
use opentelemetry_otlp::{LogExporter, MetricExporter, SpanExporter, WithExportConfig};
2321
use opentelemetry_sdk::logs::SdkLoggerProvider;
@@ -26,15 +24,6 @@ use opentelemetry_sdk::trace::SdkTracerProvider;
2624
use tracing_opentelemetry::OpenTelemetryLayer;
2725
use tracing_subscriber::layer::{Layer as _, SubscriberExt};
2826

29-
static ENABLED: AtomicBool = AtomicBool::new(false);
30-
31-
/// Process-wide export gate. Spans and other instrumented work check this before allocating
32-
/// anything, so the unset-endpoint path stays allocation-free (the provider guard alone cannot
33-
/// remove no-op span construction on the supervisor hot path).
34-
pub fn enabled() -> bool {
35-
ENABLED.load(Ordering::Relaxed)
36-
}
37-
3827
/// Seconds-scale explicit bucket boundaries for the duration histograms. The SDK's default
3928
/// boundaries are millisecond-tuned (`[0, 5, 10, …, 10000]`), so sub-second reconcile passes
4029
/// and session spawns would collapse into the lowest buckets and be indistinguishable.
@@ -57,9 +46,9 @@ fn duration_view(instrument: &Instrument) -> Option<Stream> {
5746
}
5847
}
5948

60-
/// Guard holding the tracer, meter, and logger providers for a process lifetime. Dropping it
61-
/// flushes and shuts all three exporters down so short-lived CLI invocations still deliver
62-
/// their spans, metric points, and log records.
49+
/// Guard holding the tracer, meter, and logger providers for a process lifetime. Explicit
50+
/// shutdown delivers pending telemetry from short-lived CLI invocations; the process-global
51+
/// log bridge requires slightly different logger-provider lifetime handling (see [`Self::shutdown`]).
6352
pub struct Telemetry {
6453
tracer_provider: Option<SdkTracerProvider>,
6554
meter_provider: Option<SdkMeterProvider>,
@@ -133,8 +122,8 @@ impl Telemetry {
133122
// best-effort: if its exporter fails to build (e.g. malformed
134123
// `OTEL_EXPORTER_OTLP_METRICS_ENDPOINT`), metrics are disabled but span and log
135124
// export must continue. The periodic reader's default interval only governs
136-
// background collection — `shutdown` below force-flushes, so short-lived CLI runs
137-
// still deliver their points.
125+
// background collection — provider shutdown below performs the final collection, so
126+
// short-lived CLI runs still deliver their points.
138127
let meter_provider = match build_metric_exporter() {
139128
Ok(exporter) => {
140129
let reader = opentelemetry_sdk::metrics::PeriodicReader::builder(exporter).build();
@@ -145,7 +134,6 @@ impl Telemetry {
145134
.build();
146135
opentelemetry::global::set_meter_provider(meter_provider.clone());
147136
crate::metrics::set_enabled(true);
148-
ENABLED.store(true, Ordering::Relaxed);
149137
Some(meter_provider)
150138
}
151139
Err(err) => {
@@ -154,7 +142,6 @@ impl Telemetry {
154142
}
155143
};
156144

157-
158145
// Log records share endpoint, protocol, and resource too; the appender bridge maps
159146
// `tracing` events onto OTLP logs and stamps the current span context onto them.
160147
let logger_provider = match build_log_exporter() {
@@ -189,23 +176,28 @@ impl Telemetry {
189176
self.tracer_provider.is_some()
190177
}
191178

192-
/// Flush pending spans, metric points, and log records, then stop all exporters. Safe to
193-
/// call multiple times.
179+
/// Deliver pending spans, metric points, and log records, then stop bounded exporter
180+
/// workers. Safe to call multiple times.
194181
pub fn shutdown(&mut self) {
182+
// `PeriodicReader::shutdown` performs a final collect-and-export itself. Calling
183+
// `force_flush` first would export the same cumulative counter and histogram snapshot
184+
// twice for every short-lived process.
195185
if let Some(provider) = self.meter_provider.take() {
196-
let _ = provider.force_flush();
197186
let _ = provider.shutdown();
198187
crate::metrics::set_enabled(false);
199188
}
200-
if let Some(provider) = self.logger_provider.take() {
201-
let _ = provider.force_flush();
189+
if let Some(provider) = self.tracer_provider.take() {
202190
let _ = provider.shutdown();
203191
}
204-
if let Some(provider) = self.tracer_provider.take() {
192+
// The OpenTelemetry log bridge is installed in the process-global tracing subscriber
193+
// and retains a logger from this provider. That subscriber cannot be uninstalled, so
194+
// shutting the provider down here exposes a stopped BatchLogProcessor to subsequent
195+
// events (including HTTP-client events produced by exporter shutdown). Force-flush last
196+
// to deliver the correlated completion log, then leave the provider alive through the
197+
// global bridge until process exit.
198+
if let Some(provider) = self.logger_provider.take() {
205199
let _ = provider.force_flush();
206-
let _ = provider.shutdown();
207200
}
208-
ENABLED.store(false, Ordering::Relaxed);
209201
}
210202
}
211203

@@ -215,49 +207,6 @@ impl Drop for Telemetry {
215207
}
216208
}
217209

218-
/// A root `st2.reconcile_pass` span for one bounded pass, or nothing when telemetry is
219-
/// disabled (construction is skipped entirely — see [`enabled`]). Each pass gets its own
220-
/// trace; the supervisor loop never holds an endless root open.
221-
pub struct PassSpan(Option<opentelemetry::global::BoxedSpan>);
222-
223-
impl PassSpan {
224-
pub fn start(this_host: &str) -> Self {
225-
if !enabled() {
226-
return Self(None);
227-
}
228-
let tracer = opentelemetry::global::tracer("st2");
229-
let span = tracer
230-
.span_builder("st2.reconcile_pass")
231-
.with_attributes(vec![KeyValue::new("st2.host", this_host.to_string())])
232-
.start(&tracer);
233-
Self(Some(span))
234-
}
235-
236-
/// Record pass outcomes and end the span. Early-drop paths end it without attributes.
237-
pub fn finish(mut self, crash_loops: usize, unparked: usize) {
238-
if let Some(span) = self.0.as_mut() {
239-
let to_i64 = |n: usize| i64::try_from(n).unwrap_or(i64::MAX);
240-
span.set_attribute(KeyValue::new("st2.crash_loops", to_i64(crash_loops)));
241-
span.set_attribute(KeyValue::new("st2.unparked", to_i64(unparked)));
242-
}
243-
self.end();
244-
}
245-
}
246-
247-
impl Drop for PassSpan {
248-
fn drop(&mut self) {
249-
self.end();
250-
}
251-
}
252-
253-
impl PassSpan {
254-
fn end(&mut self) {
255-
if let Some(mut span) = self.0.take() {
256-
span.end();
257-
}
258-
}
259-
}
260-
261210
/// Install the global subscriber once: stderr fmt (always), span exporter layer, and log-record
262211
/// bridge behind the endpoint guard. A second `Telemetry::init` in the same process cannot
263212
/// replace it (`set_global_default` errors), which is fine: init runs once per entrypoint.

0 commit comments

Comments
 (0)