fix: otel resiliency (#26857)

Improving the breadth of collected data, and ensuring that the collected
data is more likely to be successfully reported.

- Use `log` crate in more places
- Hook up `log` crate to otel
- Switch to process-wide otel processors
- Handle places that use `process::exit`

Also adds a more robust testing framework, with a deterministic tracing
setting.

Refs: https://github.com/denoland/deno/issues/26852

Cargo.toml

@@ -141,7 +141,7 @@ jsonc-parser = { version = "=0.26.2", features = ["serde"] }
 lazy-regex = "3"
 libc = "0.2.126"
 libz-sys = { version = "1.1.20", default-features = false }
-log = "0.4.20"
+log = { version = "0.4.20", features = ["kv"] }
 lsp-types = "=0.97.0" # used by tower-lsp and "proposed" feature is unstable in patch releases
 memmem = "0.1.1"
 monch = "=0.5.0"

cli/args/flags.rs

@@ -36,6 +36,7 @@ use deno_path_util::normalize_path;
 use deno_path_util::url_to_file_path;
 use deno_runtime::deno_permissions::PermissionsOptions;
 use deno_runtime::deno_permissions::SysDescriptor;
+use deno_runtime::ops::otel::OtelConfig;
 use log::debug;
 use log::Level;
 use serde::Deserialize;
@@ -967,6 +968,24 @@ impl Flags {
     args
   }
 
+  pub fn otel_config(&self) -> Option<OtelConfig> {
+    if self
+      .unstable_config
+      .features
+      .contains(&String::from("otel"))
+    {
+      Some(OtelConfig {
+        runtime_name: Cow::Borrowed("deno"),
+        runtime_version: Cow::Borrowed(crate::version::DENO_VERSION_INFO.deno),
+        deterministic: std::env::var("DENO_UNSTABLE_OTEL_DETERMINISTIC")
+          .is_ok(),
+        ..Default::default()
+      })
+    } else {
+      None
+    }
+  }
+
   /// Extract the paths the config file should be discovered from.
   ///
   /// Returns `None` if the config file should not be auto-discovered.

cli/args/mod.rs

@@ -823,10 +823,8 @@ impl CliOptions {
       };
       let msg =
         format!("DANGER: TLS certificate validation is disabled {}", domains);
-      #[allow(clippy::print_stderr)]
       {
-        // use eprintln instead of log::warn so this always gets shown
-        eprintln!("{}", colors::yellow(msg));
+        log::error!("{}", colors::yellow(msg));
       }
     }
 
@@ -1131,20 +1129,7 @@ impl CliOptions {
   }
 
   pub fn otel_config(&self) -> Option<OtelConfig> {
-    if self
-      .flags
-      .unstable_config
-      .features
-      .contains(&String::from("otel"))
-    {
-      Some(OtelConfig {
-        runtime_name: Cow::Borrowed("deno"),
-        runtime_version: Cow::Borrowed(crate::version::DENO_VERSION_INFO.deno),
-        ..Default::default()
-      })
-    } else {
-      None
-    }
+    self.flags.otel_config()
   }
 
   pub fn env_file_name(&self) -> Option<&String> {

cli/clippy.toml

@@ -1,5 +1,6 @@
 disallowed-methods = [
   { path = "reqwest::Client::new", reason = "create an HttpClient via an HttpClientProvider instead" },
+  { path = "std::process::exit", reason = "use deno_runtime::exit instead" },
 ]
 disallowed-types = [
   { path = "reqwest::Client", reason = "use crate::http_util::HttpClient instead" },

cli/graph_util.rs

@@ -188,7 +188,7 @@ pub fn graph_exit_integrity_errors(graph: &ModuleGraph) {
 fn exit_for_integrity_error(err: &ModuleError) {
   if let Some(err_message) = enhanced_integrity_error_message(err) {
     log::error!("{} {}", colors::red("error:"), err_message);
-    std::process::exit(10);
+    deno_runtime::exit(10);
   }
 }
 

cli/lsp/parent_process_checker.rs

@@ -11,7 +11,7 @@ pub fn start(parent_process_id: u32) {
     std::thread::sleep(Duration::from_secs(10));
 
     if !is_process_active(parent_process_id) {
-      std::process::exit(1);
+      deno_runtime::exit(1);
     }
   });
 }

cli/main.rs

@@ -350,18 +350,17 @@ fn setup_panic_hook() {
     eprintln!("Args: {:?}", env::args().collect::<Vec<_>>());
     eprintln!();
     orig_hook(panic_info);
-    std::process::exit(1);
+    deno_runtime::exit(1);
   }));
 }
 
-#[allow(clippy::print_stderr)]
 fn exit_with_message(message: &str, code: i32) -> ! {
-  eprintln!(
+  log::error!(
     "{}: {}",
     colors::red_bold("error"),
     message.trim_start_matches("error: ")
   );
-  std::process::exit(code);
+  deno_runtime::exit(code);
 }
 
 fn exit_for_error(error: AnyError) -> ! {
@@ -380,13 +379,12 @@ fn exit_for_error(error: AnyError) -> ! {
   exit_with_message(&error_string, error_code);
 }
 
-#[allow(clippy::print_stderr)]
 pub(crate) fn unstable_exit_cb(feature: &str, api_name: &str) {
-  eprintln!(
+  log::error!(
     "Unstable API '{api_name}'. The `--unstable-{}` flag must be provided.",
     feature
   );
-  std::process::exit(70);
+  deno_runtime::exit(70);
 }
 
 pub fn main() {
@@ -419,7 +417,7 @@ pub fn main() {
   drop(profiler);
 
   match result {
-    Ok(exit_code) => std::process::exit(exit_code),
+    Ok(exit_code) => deno_runtime::exit(exit_code),
     Err(err) => exit_for_error(err),
   }
 }
@@ -433,12 +431,21 @@ fn resolve_flags_and_init(
       if err.kind() == clap::error::ErrorKind::DisplayVersion =>
     {
       // Ignore results to avoid BrokenPipe errors.
+      util::logger::init(None);
       let _ = err.print();
-      std::process::exit(0);
+      deno_runtime::exit(0);
+    }
+    Err(err) => {
+      util::logger::init(None);
+      exit_for_error(AnyError::from(err))
     }
-    Err(err) => exit_for_error(AnyError::from(err)),
   };
 
+  if let Some(otel_config) = flags.otel_config() {
+    deno_runtime::ops::otel::init(otel_config)?;
+  }
+  util::logger::init(flags.log_level);
+
   // TODO(bartlomieju): remove in Deno v2.5 and hard error then.
   if flags.unstable_config.legacy_flag_enabled {
     log::warn!(
@@ -467,7 +474,6 @@ fn resolve_flags_and_init(
   deno_core::JsRuntime::init_platform(
     None, /* import assertions enabled */ false,
   );
-  util::logger::init(flags.log_level);
 
   Ok(flags)
 }

cli/mainrt.rs

@@ -40,23 +40,21 @@ use std::env::current_exe;
 
 use crate::args::Flags;
 
-#[allow(clippy::print_stderr)]
 pub(crate) fn unstable_exit_cb(feature: &str, api_name: &str) {
-  eprintln!(
+  log::error!(
     "Unstable API '{api_name}'. The `--unstable-{}` flag must be provided.",
     feature
   );
-  std::process::exit(70);
+  deno_runtime::exit(70);
 }
 
-#[allow(clippy::print_stderr)]
 fn exit_with_message(message: &str, code: i32) -> ! {
-  eprintln!(
+  log::error!(
     "{}: {}",
     colors::red_bold("error"),
     message.trim_start_matches("error: ")
   );
-  std::process::exit(code);
+  deno_runtime::exit(code);
 }
 
 fn unwrap_or_exit<T>(result: Result<T, AnyError>) -> T {
@@ -89,13 +87,19 @@ fn main() {
   let future = async move {
     match standalone {
       Ok(Some(data)) => {
+        if let Some(otel_config) = data.metadata.otel_config.clone() {
+          deno_runtime::ops::otel::init(otel_config)?;
+        }
         util::logger::init(data.metadata.log_level);
         load_env_vars(&data.metadata.env_vars_from_env_file);
         let exit_code = standalone::run(data).await?;
-        std::process::exit(exit_code);
+        deno_runtime::exit(exit_code);
       }
       Ok(None) => Ok(()),
-      Err(err) => Err(err),
+      Err(err) => {
+        util::logger::init(None);
+        Err(err)
+      }
     }
   };
 

cli/standalone/binary.rs

@@ -517,7 +517,7 @@ impl<'a> DenoCompileBinaryWriter<'a> {
       Some(bytes) => bytes,
       None => {
         log::info!("Download could not be found, aborting");
-        std::process::exit(1)
+        deno_runtime::exit(1);
       }
     };
 

cli/tools/lint/mod.rs

@@ -191,7 +191,7 @@ pub async fn lint(
       linter.finish()
     };
     if !success {
-      std::process::exit(1);
+      deno_runtime::exit(1);
     }
   }
 

cli/tools/test/mod.rs

@@ -1357,6 +1357,7 @@ pub async fn report_tests(
         if let Err(err) = reporter.flush_report(&elapsed, &tests, &test_steps) {
           eprint!("Test reporter failed to flush: {}", err)
         }
+        #[allow(clippy::disallowed_methods)]
         std::process::exit(130);
       }
     }
@@ -1642,6 +1643,7 @@ pub async fn run_tests_with_watch(
     loop {
       signal::ctrl_c().await.unwrap();
       if !HAS_TEST_RUN_SIGINT_HANDLER.load(Ordering::Relaxed) {
+        #[allow(clippy::disallowed_methods)]
         std::process::exit(130);
       }
     }

cli/tools/upgrade.rs

@@ -540,7 +540,7 @@ pub async fn upgrade(
   let Some(archive_data) = download_package(&client, download_url).await?
   else {
     log::error!("Download could not be found, aborting");
-    std::process::exit(1)
+    deno_runtime::exit(1)
   };
 
   log::info!(

cli/util/file_watcher.rs

@@ -73,7 +73,6 @@ impl DebouncedReceiver {
   }
 }
 
-#[allow(clippy::print_stderr)]
 async fn error_handler<F>(watch_future: F) -> bool
 where
   F: Future<Output = Result<(), AnyError>>,
@@ -84,7 +83,7 @@ where
       Some(e) => format_js_error(e),
       None => format!("{err:?}"),
     };
-    eprintln!(
+    log::error!(
       "{}: {}",
       colors::red_bold("error"),
       error_string.trim_start_matches("error: ")

cli/util/logger.rs

@@ -29,6 +29,7 @@ impl log::Log for CliLogger {
       // thread's state
       DrawThread::hide();
       self.0.log(record);
+      deno_runtime::ops::otel::handle_log(record);
       DrawThread::show();
     }
   }

cli/util/v8.rs

@@ -46,15 +46,14 @@ pub fn init_v8_flags(
     .skip(1)
     .collect::<Vec<_>>();
 
-  #[allow(clippy::print_stderr)]
   if !unrecognized_v8_flags.is_empty() {
     for f in unrecognized_v8_flags {
-      eprintln!("error: V8 did not recognize flag '{f}'");
+      log::error!("error: V8 did not recognize flag '{f}'");
     }
-    eprintln!("\nFor a list of V8 flags, use '--v8-flags=--help'");
-    std::process::exit(1);
+    log::error!("\nFor a list of V8 flags, use '--v8-flags=--help'");
+    deno_runtime::exit(1);
   }
   if v8_flags_includes_help {
-    std::process::exit(0);
+    deno_runtime::exit(0);
   }
 }

ext/napi/node_api.rs

@@ -140,7 +140,6 @@ fn napi_fatal_exception(env: &mut Env, err: napi_value) -> napi_status {
 }
 
 #[napi_sym]
-#[allow(clippy::print_stderr)]
 fn napi_fatal_error(
   location: *const c_char,
   location_len: usize,
@@ -173,9 +172,9 @@ fn napi_fatal_error(
   };
 
   if let Some(location) = location {
-    eprintln!("NODE API FATAL ERROR: {} {}", location, message);
+    log::error!("NODE API FATAL ERROR: {} {}", location, message);
   } else {
-    eprintln!("NODE API FATAL ERROR: {}", message);
+    log::error!("NODE API FATAL ERROR: {}", message);
   }
 
   std::process::abort();

ext/napi/uv.rs

@@ -5,10 +5,9 @@ use deno_core::parking_lot::Mutex;
 use std::mem::MaybeUninit;
 use std::ptr::addr_of_mut;
 
-#[allow(clippy::print_stderr)]
 fn assert_ok(res: c_int) -> c_int {
   if res != 0 {
-    eprintln!("bad result in uv polyfill: {res}");
+    log::error!("bad result in uv polyfill: {res}");
     // don't panic because that might unwind into
     // c/c++
     std::process::abort();

runtime/clippy.toml

@@ -42,4 +42,5 @@ disallowed-methods = [
   { path = "std::fs::write", reason = "File system operations should be done using FileSystem trait" },
   { path = "std::path::Path::canonicalize", reason = "File system operations should be done using FileSystem trait" },
   { path = "std::path::Path::exists", reason = "File system operations should be done using FileSystem trait" },
+  { path = "std::process::exit", reason = "use deno_runtime::exit instead" },
 ]

runtime/js/telemetry.js

@@ -22,11 +22,14 @@ const {
   ReflectApply,
   SymbolFor,
   Error,
+  NumberPrototypeToString,
+  StringPrototypePadStart,
 } = primordials;
 const { AsyncVariable, setAsyncContext } = core;
 
 const CURRENT = new AsyncVariable();
 let TRACING_ENABLED = false;
+let DETERMINISTIC = false;
 
 const SPAN_ID_BYTES = 8;
 const TRACE_ID_BYTES = 16;
@@ -45,7 +48,19 @@ const hexSliceLookupTable = (function () {
   return table;
 })();
 
+let counter = 1;
+
+const INVALID_SPAN_ID = "0000000000000000";
+const INVALID_TRACE_ID = "00000000000000000000000000000000";
+
 function generateId(bytes) {
+  if (DETERMINISTIC) {
+    return StringPrototypePadStart(
+      NumberPrototypeToString(counter++, 16),
+      bytes * 2,
+      "0",
+    );
+  }
   let out = "";
   for (let i = 0; i < bytes / 4; i += 1) {
     const r32 = (MathRandom() * 2 ** 32) >>> 0;
@@ -112,8 +127,6 @@ function submit(span) {
 
 const now = () => (performance.timeOrigin + performance.now()) / 1000;
 
-const INVALID_SPAN_ID = "0000000000000000";
-const INVALID_TRACE_ID = "00000000000000000000000000000000";
 const NO_ASYNC_CONTEXT = {};
 
 class Span {
@@ -362,9 +375,10 @@ const otelConsoleConfig = {
 
 export function bootstrap(config) {
   if (config.length === 0) return;
-  const { 0: consoleConfig } = config;
+  const { 0: consoleConfig, 1: deterministic } = config;
 
   TRACING_ENABLED = true;
+  DETERMINISTIC = deterministic === 1;
 
   switch (consoleConfig) {
     case otelConsoleConfig.capture:

runtime/lib.rs

@@ -140,6 +140,12 @@ pub static UNSTABLE_GRANULAR_FLAGS: &[UnstableGranularFlag] = &[
   },
 ];
 
+pub fn exit(code: i32) -> ! {
+  crate::ops::otel::flush();
+  #[allow(clippy::disallowed_methods)]
+  std::process::exit(code);
+}
+
 #[cfg(test)]
 mod test {
   use super::*;

runtime/ops/os/mod.rs

@@ -186,10 +186,8 @@ fn op_get_exit_code(state: &mut OpState) -> i32 {
 
 #[op2(fast)]
 fn op_exit(state: &mut OpState) {
-  crate::ops::otel::otel_drop_state(state);
-
   let code = state.borrow::<ExitCode>().get();
-  std::process::exit(code)
+  crate::exit(code)
 }
 
 #[op2]

runtime/ops/otel.rs

@@ -13,6 +13,9 @@ use deno_core::op2;
 use deno_core::v8;
 use deno_core::OpState;
 use once_cell::sync::Lazy;
+use once_cell::sync::OnceCell;
+use opentelemetry::logs::AnyValue;
+use opentelemetry::logs::LogRecord as LogRecordTrait;
 use opentelemetry::logs::Severity;
 use opentelemetry::trace::SpanContext;
 use opentelemetry::trace::SpanId;
@@ -58,15 +61,15 @@ type LogProcessor = BatchLogProcessor<OtelSharedRuntime>;
 
 deno_core::extension!(
   deno_otel,
-  ops = [op_otel_log, op_otel_span_start, op_otel_span_continue, op_otel_span_attribute, op_otel_span_attribute2, op_otel_span_attribute3, op_otel_span_flush],
-  options = {
-    otel_config: Option<OtelConfig>, // `None` means OpenTelemetry is disabled.
-  },
-  state = |state, options| {
-    if let Some(otel_config) = options.otel_config {
-      otel_create_globals(otel_config, state).unwrap();
-    }
-  }
+  ops = [
+    op_otel_log,
+    op_otel_span_start,
+    op_otel_span_continue,
+    op_otel_span_attribute,
+    op_otel_span_attribute2,
+    op_otel_span_attribute3,
+    op_otel_span_flush,
+  ],
 );
 
 #[derive(Debug, Clone, Serialize, Deserialize)]
@@ -74,6 +77,7 @@ pub struct OtelConfig {
   pub runtime_name: Cow<'static, str>,
   pub runtime_version: Cow<'static, str>,
   pub console: OtelConsoleConfig,
+  pub deterministic: bool,
 }
 
 #[derive(Debug, Clone, Copy, Serialize, Deserialize)]
@@ -90,6 +94,7 @@ impl Default for OtelConfig {
       runtime_name: Cow::Borrowed(env!("CARGO_PKG_NAME")),
       runtime_version: Cow::Borrowed(env!("CARGO_PKG_VERSION")),
       console: OtelConsoleConfig::Capture,
+      deterministic: false,
     }
   }
 }
@@ -295,10 +300,10 @@ mod hyper_client {
   }
 }
 
-fn otel_create_globals(
-  config: OtelConfig,
-  op_state: &mut OpState,
-) -> anyhow::Result<()> {
+static OTEL_PROCESSORS: OnceCell<(SpanProcessor, LogProcessor)> =
+  OnceCell::new();
+
+pub fn init(config: OtelConfig) -> anyhow::Result<()> {
   // Parse the `OTEL_EXPORTER_OTLP_PROTOCOL` variable. The opentelemetry_*
   // crates don't do this automatically.
   // TODO(piscisaureus): enable GRPC support.
@@ -318,7 +323,7 @@ fn otel_create_globals(
       return Err(anyhow!(
         "Failed to read env var OTEL_EXPORTER_OTLP_PROTOCOL: {}",
         err
-      ))
+      ));
     }
   };
 
@@ -372,7 +377,6 @@ fn otel_create_globals(
   let mut span_processor =
     BatchSpanProcessor::builder(span_exporter, OtelSharedRuntime).build();
   span_processor.set_resource(&resource);
-  op_state.put::<SpanProcessor>(span_processor);
 
   let log_exporter = HttpExporterBuilder::default()
     .with_http_client(client)
@@ -381,36 +385,92 @@ fn otel_create_globals(
   let log_processor =
     BatchLogProcessor::builder(log_exporter, OtelSharedRuntime).build();
   log_processor.set_resource(&resource);
-  op_state.put::<LogProcessor>(log_processor);
+
+  OTEL_PROCESSORS
+    .set((span_processor, log_processor))
+    .map_err(|_| anyhow!("failed to init otel"))?;
 
   Ok(())
 }
 
 /// This function is called by the runtime whenever it is about to call
-/// `os::process::exit()`, to ensure that all OpenTelemetry logs are properly
+/// `process::exit()`, to ensure that all OpenTelemetry logs are properly
 /// flushed before the process terminates.
-pub fn otel_drop_state(state: &mut OpState) {
-  if let Some(processor) = state.try_take::<SpanProcessor>() {
-    let _ = processor.force_flush();
-    drop(processor);
+pub fn flush() {
+  if let Some((span_processor, log_processor)) = OTEL_PROCESSORS.get() {
+    let _ = span_processor.force_flush();
+    let _ = log_processor.force_flush();
   }
-  if let Some(processor) = state.try_take::<LogProcessor>() {
-    let _ = processor.force_flush();
-    drop(processor);
+}
+
+pub fn handle_log(record: &log::Record) {
+  use log::Level;
+
+  let Some((_, log_processor)) = OTEL_PROCESSORS.get() else {
+    return;
+  };
+
+  let mut log_record = LogRecord::default();
+
+  log_record.set_observed_timestamp(SystemTime::now());
+  log_record.set_severity_number(match record.level() {
+    Level::Error => Severity::Error,
+    Level::Warn => Severity::Warn,
+    Level::Info => Severity::Info,
+    Level::Debug => Severity::Debug,
+    Level::Trace => Severity::Trace,
+  });
+  log_record.set_severity_text(record.level().as_str());
+  log_record.set_body(record.args().to_string().into());
+  log_record.set_target(record.metadata().target().to_string());
+
+  struct Visitor<'s>(&'s mut LogRecord);
+
+  impl<'s, 'kvs> log::kv::VisitSource<'kvs> for Visitor<'s> {
+    fn visit_pair(
+      &mut self,
+      key: log::kv::Key<'kvs>,
+      value: log::kv::Value<'kvs>,
+    ) -> Result<(), log::kv::Error> {
+      #[allow(clippy::manual_map)]
+      let value = if let Some(v) = value.to_bool() {
+        Some(AnyValue::Boolean(v))
+      } else if let Some(v) = value.to_borrowed_str() {
+        Some(AnyValue::String(v.to_owned().into()))
+      } else if let Some(v) = value.to_f64() {
+        Some(AnyValue::Double(v))
+      } else if let Some(v) = value.to_i64() {
+        Some(AnyValue::Int(v))
+      } else {
+        None
+      };
+
+      if let Some(value) = value {
+        let key = Key::from(key.as_str().to_owned());
+        self.0.add_attribute(key, value);
       }
+
+      Ok(())
+    }
+  }
+
+  let _ = record.key_values().visit(&mut Visitor(&mut log_record));
+
+  log_processor.emit(
+    &mut log_record,
+    &InstrumentationScope::builder("deno").build(),
+  );
 }
 
 #[op2(fast)]
 fn op_otel_log(
-  state: &mut OpState,
   #[string] message: String,
   #[smi] level: i32,
   #[string] trace_id: &str,
   #[string] span_id: &str,
   #[smi] trace_flags: u8,
 ) {
-  let Some(logger) = state.try_borrow::<LogProcessor>() else {
-    log::error!("op_otel_log: OpenTelemetry Logger not available");
+  let Some((_, log_processor)) = OTEL_PROCESSORS.get() else {
     return;
   };
 
@@ -425,23 +485,21 @@ fn op_otel_log(
 
   let mut log_record = LogRecord::default();
 
-  log_record.observed_timestamp = Some(SystemTime::now());
-  log_record.body = Some(message.into());
-  log_record.severity_number = Some(severity);
-  log_record.severity_text = Some(severity.name());
+  log_record.set_observed_timestamp(SystemTime::now());
+  log_record.set_body(message.into());
+  log_record.set_severity_number(severity);
+  log_record.set_severity_text(severity.name());
   if let (Ok(trace_id), Ok(span_id)) =
     (TraceId::from_hex(trace_id), SpanId::from_hex(span_id))
   {
-    let span_context = SpanContext::new(
+    log_record.set_trace_context(
       trace_id,
       span_id,
-      TraceFlags::new(trace_flags),
-      false,
-      Default::default(),
+      Some(TraceFlags::new(trace_flags)),
     );
-    log_record.trace_context = Some((&span_context).into());
   }
-  logger.emit(
+
+  log_processor.emit(
     &mut log_record,
     &InstrumentationScope::builder("deno").build(),
   );
@@ -463,7 +521,7 @@ fn op_otel_span_start<'s>(
   end_time: f64,
 ) -> Result<(), anyhow::Error> {
   if let Some(temporary_span) = state.try_take::<TemporarySpan>() {
-    let Some(span_processor) = state.try_borrow::<SpanProcessor>() else {
+    let Some((span_processor, _)) = OTEL_PROCESSORS.get() else {
       return Ok(());
     };
     span_processor.on_end(temporary_span.0);
@@ -678,7 +736,7 @@ fn op_otel_span_flush(state: &mut OpState) {
     return;
   };
 
-  let Some(span_processor) = state.try_borrow::<SpanProcessor>() else {
+  let Some((span_processor, _)) = OTEL_PROCESSORS.get() else {
     return;
   };
 

runtime/snapshot.rs

@@ -312,7 +312,7 @@ pub fn create_runtime_snapshot(
     ),
     ops::fs_events::deno_fs_events::init_ops(),
     ops::os::deno_os::init_ops(Default::default()),
-    ops::otel::deno_otel::init_ops(None),
+    ops::otel::deno_otel::init_ops(),
     ops::permissions::deno_permissions::init_ops(),
     ops::process::deno_process::init_ops(None),
     ops::signal::deno_signal::init_ops(),

runtime/web_worker.rs

@@ -512,9 +512,7 @@ impl WebWorker {
       ),
       ops::fs_events::deno_fs_events::init_ops_and_esm(),
       ops::os::deno_os_worker::init_ops_and_esm(),
-      ops::otel::deno_otel::init_ops_and_esm(
-        options.bootstrap.otel_config.clone(),
-      ),
+      ops::otel::deno_otel::init_ops_and_esm(),
       ops::permissions::deno_permissions::init_ops_and_esm(),
       ops::process::deno_process::init_ops_and_esm(
         services.npm_process_state_provider,
@@ -831,13 +829,12 @@ impl WebWorker {
 
         // TODO(mmastrac): we don't want to test this w/classic workers because
         // WPT triggers a failure here. This is only exposed via --enable-testing-features-do-not-use.
-        #[allow(clippy::print_stderr)]
         if self.worker_type == WebWorkerType::Module {
           panic!(
             "coding error: either js is polling or the worker is terminated"
           );
         } else {
-          eprintln!("classic worker terminated unexpectedly");
+          log::error!("classic worker terminated unexpectedly");
           Poll::Ready(Ok(()))
         }
       }
@@ -905,7 +902,6 @@ impl WebWorker {
   }
 }
 
-#[allow(clippy::print_stderr)]
 fn print_worker_error(
   error: &AnyError,
   name: &str,
@@ -918,7 +914,7 @@ fn print_worker_error(
     },
     None => error.to_string(),
   };
-  eprintln!(
+  log::error!(
     "{}: Uncaught (in worker \"{}\") {}",
     colors::red_bold("error"),
     name,

runtime/worker.rs

@@ -422,9 +422,7 @@ impl MainWorker {
       ),
       ops::fs_events::deno_fs_events::init_ops_and_esm(),
       ops::os::deno_os::init_ops_and_esm(exit_code.clone()),
-      ops::otel::deno_otel::init_ops_and_esm(
-        options.bootstrap.otel_config.clone(),
-      ),
+      ops::otel::deno_otel::init_ops_and_esm(),
       ops::permissions::deno_permissions::init_ops_and_esm(),
       ops::process::deno_process::init_ops_and_esm(
         services.npm_process_state_provider,

runtime/worker_bootstrap.rs

@@ -226,7 +226,7 @@ impl BootstrapOptions {
       serve_is_main,
       serve_worker_count,
       if let Some(otel_config) = self.otel_config.as_ref() {
-        Box::new([otel_config.console as u8])
+        Box::new([otel_config.console as u8, otel_config.deterministic as u8])
       } else {
         Box::new([])
       },

tests/specs/cli/otel_basic/__test__.jsonc

@@ -1,4 +1,32 @@
 {
-  "args": "run -A main.ts",
-  "output": "processed\n"
+  "steps": [
+    {
+      "args": "run -A main.ts basic.ts",
+      "envs": {
+        "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1"
+      },
+      "output": "basic.out"
+    },
+    {
+      "args": "run -A main.ts natural_exit.ts",
+      "envs": {
+        "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1"
+      },
+      "output": "natural_exit.out"
+    },
+    {
+      "args": "run -A main.ts deno_dot_exit.ts",
+      "envs": {
+        "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1"
+      },
+      "output": "deno_dot_exit.out"
+    },
+    {
+      "args": "run -A main.ts uncaught.ts",
+      "envs": {
+        "DENO_UNSTABLE_OTEL_DETERMINISTIC": "1"
+      },
+      "output": "uncaught.out"
+    }
+  ]
 }

tests/specs/cli/otel_basic/basic.out

@@ -0,0 +1,76 @@
+{
+  "spans": [
+    {
+      "traceId": "00000000000000000000000000000002",
+      "spanId": "0000000000000003",
+      "traceState": "",
+      "parentSpanId": "0000000000000001",
+      "flags": 1,
+      "name": "inner span",
+      "kind": 1,
+      "startTimeUnixNano": "[WILDCARD]",
+      "endTimeUnixNano": "[WILDCARD]",
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "events": [],
+      "droppedEventsCount": 0,
+      "links": [],
+      "droppedLinksCount": 0,
+      "status": {
+        "message": "",
+        "code": 0
+      }
+    },
+    {
+      "traceId": "00000000000000000000000000000002",
+      "spanId": "0000000000000001",
+      "traceState": "",
+      "parentSpanId": "",
+      "flags": 1,
+      "name": "outer span",
+      "kind": 1,
+      "startTimeUnixNano": "[WILDCARD]",
+      "endTimeUnixNano": "[WILDCARD]",
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "events": [],
+      "droppedEventsCount": 0,
+      "links": [],
+      "droppedLinksCount": 0,
+      "status": {
+        "message": "",
+        "code": 0
+      }
+    }
+  ],
+  "logs": [
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 9,
+      "severityText": "INFO",
+      "body": {
+        "stringValue": "log 1\n"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 1,
+      "traceId": "00000000000000000000000000000002",
+      "spanId": "0000000000000003"
+    },
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 9,
+      "severityText": "INFO",
+      "body": {
+        "stringValue": "log 2\n"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 1,
+      "traceId": "00000000000000000000000000000002",
+      "spanId": "0000000000000003"
+    }
+  ]
+}

tests/specs/cli/otel_basic/basic.ts

@@ -7,10 +7,14 @@ async function inner() {
   console.log("log 2");
 }
 
-Deno.serve({
+const server = Deno.serve({
   port: 0,
-  onListen({ port }) {
-    console.log(port.toString());
+  async onListen({ port }) {
+    try {
+      await fetch(`http://localhost:${port}`);
+    } finally {
+      server.shutdown();
+    }
   },
   handler: async (_req) => {
     using _span = new Deno.tracing.Span("outer span");

tests/specs/cli/otel_basic/deno_dot_exit.out

@@ -0,0 +1,19 @@
+{
+  "spans": [],
+  "logs": [
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 9,
+      "severityText": "INFO",
+      "body": {
+        "stringValue": "log 1\n"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 0,
+      "traceId": "",
+      "spanId": ""
+    }
+  ]
+}

tests/specs/cli/otel_basic/deno_dot_exit.ts

@@ -0,0 +1,2 @@
+console.log("log 1");
+Deno.exit(0);

tests/specs/cli/otel_basic/main.ts

@@ -1,76 +1,38 @@
 // Copyright 2018-2024 the Deno authors. All rights reserved. MIT license.
 
-import { assert, assertEquals } from "@std/assert";
-import { TextLineStream } from "@std/streams/text-line-stream";
+const data = {
+  spans: [],
+  logs: [],
+};
 
-const logs = [];
-const spans = [];
-let child: Deno.ChildProcess;
-
-Deno.serve(
+const server = Deno.serve(
   {
     port: 0,
-    async onListen({ port }) {
+    onListen({ port }) {
       const command = new Deno.Command(Deno.execPath(), {
-        args: ["run", "-A", "--unstable-otel", "child.ts"],
+        args: ["run", "-A", "--unstable-otel", Deno.args[0]],
         env: {
           OTEL_EXPORTER_OTLP_PROTOCOL: "http/json",
           OTEL_EXPORTER_OTLP_ENDPOINT: `http://localhost:${port}`,
-          OTEL_BSP_SCHEDULE_DELAY: "10",
-          OTEL_BLRP_SCHEDULE_DELAY: "10",
         },
-        stdin: "piped",
-        stdout: "piped",
-        stderr: "inherit",
+        stdout: "null",
+      });
+      const child = command.spawn();
+      child.output().then(() => {
+        server.shutdown();
+
+        console.log(JSON.stringify(data, null, 2));
       });
-      child = command.spawn();
-      const lines = child.stdout
-        .pipeThrough(new TextDecoderStream())
-        .pipeThrough(new TextLineStream())
-        .getReader();
-      const line = await lines.read();
-      await fetch(`http://localhost:${line.value}/`);
     },
     async handler(req) {
-      try {
       const body = await req.json();
       if (body.resourceLogs) {
-          logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords);
+        data.logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords);
       }
       if (body.resourceSpans) {
-          spans.push(...body.resourceSpans[0].scopeSpans[0].spans);
+        data.spans.push(...body.resourceSpans[0].scopeSpans[0].spans);
       }
-
-        if (logs.length > 2 && spans.length > 1) {
-          child.kill();
-
-          const inner = spans.find((s) => s.name === "inner span");
-          const outer = spans.find((s) => s.name === "outer span");
-
-          assertEquals(inner.traceId, outer.traceId);
-          assertEquals(inner.parentSpanId, outer.spanId);
-
-          assertEquals(logs[1].body.stringValue, "log 1\n");
-          assertEquals(logs[1].traceId, inner.traceId);
-          assertEquals(logs[1].spanId, inner.spanId);
-
-          assertEquals(logs[2].body.stringValue, "log 2\n");
-          assertEquals(logs[2].traceId, inner.traceId);
-          assertEquals(logs[2].spanId, inner.spanId);
-
-          console.log("processed");
-          Deno.exit(0);
-        }
-
       return Response.json({ partialSuccess: {} }, { status: 200 });
-      } catch (e) {
-        console.error(e);
-        Deno.exit(1);
-      }
     },
   },
 );
-
-setTimeout(() => {
-  assert(false, "test did not finish in time");
-}, 10e3);

tests/specs/cli/otel_basic/natural_exit.out

@@ -0,0 +1,19 @@
+{
+  "spans": [],
+  "logs": [
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 9,
+      "severityText": "INFO",
+      "body": {
+        "stringValue": "log 1\n"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 0,
+      "traceId": "",
+      "spanId": ""
+    }
+  ]
+}

tests/specs/cli/otel_basic/natural_exit.ts

@@ -0,0 +1 @@
+console.log("log 1");

tests/specs/cli/otel_basic/uncaught.out

@@ -0,0 +1,37 @@
+error: Uncaught (in promise) Error: uncaught
+throw new Error("uncaught");
+      ^
+    at file:///[WILDCARD]/tests/specs/cli/otel_basic/uncaught.ts:2:7
+{
+  "spans": [],
+  "logs": [
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 9,
+      "severityText": "INFO",
+      "body": {
+        "stringValue": "log 1\n"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 0,
+      "traceId": "",
+      "spanId": ""
+    },
+    {
+      "timeUnixNano": "0",
+      "observedTimeUnixNano": "[WILDCARD]",
+      "severityNumber": 17,
+      "severityText": "ERROR",
+      "body": {
+        "stringValue": "error: Uncaught (in promise) Error: uncaught\nthrow new Error(\"uncaught\");\n      ^\n    at file:///[WILDCARD]/tests/specs/cli/otel_basic/uncaught.ts:2:7"
+      },
+      "attributes": [],
+      "droppedAttributesCount": 0,
+      "flags": 0,
+      "traceId": "",
+      "spanId": ""
+    }
+  ]
+}

tests/specs/cli/otel_basic/uncaught.ts

@@ -0,0 +1,2 @@
+console.log("log 1");
+throw new Error("uncaught");

tests/util/server/src/macros.rs

@@ -33,6 +33,7 @@ macro_rules! timeout {
           use std::io::Write;
           eprintln!("Test {function} timed out after {timeout} seconds, aborting");
           _ = std::io::stderr().flush();
+          #[allow(clippy::disallowed_methods)]
           ::std::process::exit(1);
         }
       });