diff options
37 files changed, 411 insertions, 175 deletions
diff --git a/Cargo.toml b/Cargo.toml index 6a8855629..f384b9255 100644 --- a/Cargo.toml +++ b/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" diff --git a/cli/args/flags.rs b/cli/args/flags.rs index 37f589937..720d8db3b 100644 --- a/cli/args/flags.rs +++ b/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. diff --git a/cli/args/mod.rs b/cli/args/mod.rs index 5e5bae87d..50a37b334 100644 --- a/cli/args/mod.rs +++ b/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> { diff --git a/cli/clippy.toml b/cli/clippy.toml index e20c56c47..f1c25acfb 100644 --- a/cli/clippy.toml +++ b/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" }, diff --git a/cli/graph_util.rs b/cli/graph_util.rs index 3f48449bc..6ed0506dd 100644 --- a/cli/graph_util.rs +++ b/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); } } diff --git a/cli/lsp/parent_process_checker.rs b/cli/lsp/parent_process_checker.rs index e5b2b2f23..b8a42cd1a 100644 --- a/cli/lsp/parent_process_checker.rs +++ b/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); } }); } diff --git a/cli/main.rs b/cli/main.rs index 04daff670..20d2cb6bf 100644 --- a/cli/main.rs +++ b/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) } diff --git a/cli/mainrt.rs b/cli/mainrt.rs index f5b798f81..2951aa711 100644 --- a/cli/mainrt.rs +++ b/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) + } } }; diff --git a/cli/standalone/binary.rs b/cli/standalone/binary.rs index b48e1c97c..ebcbf3ee6 100644 --- a/cli/standalone/binary.rs +++ b/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); } }; diff --git a/cli/tools/lint/mod.rs b/cli/tools/lint/mod.rs index d8edf2404..36f1cc049 100644 --- a/cli/tools/lint/mod.rs +++ b/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); } } diff --git a/cli/tools/test/mod.rs b/cli/tools/test/mod.rs index fa849614f..966b0d285 100644 --- a/cli/tools/test/mod.rs +++ b/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); } } diff --git a/cli/tools/upgrade.rs b/cli/tools/upgrade.rs index 77a9f72b8..cb85859f7 100644 --- a/cli/tools/upgrade.rs +++ b/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!( diff --git a/cli/util/file_watcher.rs b/cli/util/file_watcher.rs index 8d734af88..21ea95e06 100644 --- a/cli/util/file_watcher.rs +++ b/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: ") diff --git a/cli/util/logger.rs b/cli/util/logger.rs index d93753dfd..f76663df2 100644 --- a/cli/util/logger.rs +++ b/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(); } } diff --git a/cli/util/v8.rs b/cli/util/v8.rs index fb16e67b7..6e690e6f3 100644 --- a/cli/util/v8.rs +++ b/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); } } diff --git a/ext/napi/node_api.rs b/ext/napi/node_api.rs index 186ae42c4..2ca5c8d0b 100644 --- a/ext/napi/node_api.rs +++ b/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(); diff --git a/ext/napi/uv.rs b/ext/napi/uv.rs index 6f728a92b..ea6b53966 100644 --- a/ext/napi/uv.rs +++ b/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(); diff --git a/runtime/clippy.toml b/runtime/clippy.toml index 53676a90e..79e6bbd08 100644 --- a/runtime/clippy.toml +++ b/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" }, ] diff --git a/runtime/js/telemetry.js b/runtime/js/telemetry.js index e9eb51f7c..195839fb1 100644 --- a/runtime/js/telemetry.js +++ b/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: diff --git a/runtime/lib.rs b/runtime/lib.rs index 21b61e1c0..6fb8c5f3d 100644 --- a/runtime/lib.rs +++ b/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::*; diff --git a/runtime/ops/os/mod.rs b/runtime/ops/os/mod.rs index 790962f38..b10a2939e 100644 --- a/runtime/ops/os/mod.rs +++ b/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] diff --git a/runtime/ops/otel.rs b/runtime/ops/otel.rs index 6a4750acc..b32764d7f 100644 --- a/runtime/ops/otel.rs +++ b/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; }; diff --git a/runtime/snapshot.rs b/runtime/snapshot.rs index bb9bf9166..7f6e6b8ab 100644 --- a/runtime/snapshot.rs +++ b/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(), diff --git a/runtime/web_worker.rs b/runtime/web_worker.rs index e27229153..b056e01fc 100644 --- a/runtime/web_worker.rs +++ b/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, diff --git a/runtime/worker.rs b/runtime/worker.rs index 82df755fa..c7bfb1c5f 100644 --- a/runtime/worker.rs +++ b/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, diff --git a/runtime/worker_bootstrap.rs b/runtime/worker_bootstrap.rs index dc989a1c0..3f5c245a0 100644 --- a/runtime/worker_bootstrap.rs +++ b/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([]) }, diff --git a/tests/specs/cli/otel_basic/__test__.jsonc b/tests/specs/cli/otel_basic/__test__.jsonc index a9d4fff04..5a27e9262 100644 --- a/tests/specs/cli/otel_basic/__test__.jsonc +++ b/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" + } + ] } diff --git a/tests/specs/cli/otel_basic/basic.out b/tests/specs/cli/otel_basic/basic.out new file mode 100644 index 000000000..3f0554f96 --- /dev/null +++ b/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" + } + ] +} diff --git a/tests/specs/cli/otel_basic/child.ts b/tests/specs/cli/otel_basic/basic.ts index 72cffd9f0..5a178794a 100644 --- a/tests/specs/cli/otel_basic/child.ts +++ b/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"); diff --git a/tests/specs/cli/otel_basic/deno_dot_exit.out b/tests/specs/cli/otel_basic/deno_dot_exit.out new file mode 100644 index 000000000..98a41cf60 --- /dev/null +++ b/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": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/deno_dot_exit.ts b/tests/specs/cli/otel_basic/deno_dot_exit.ts new file mode 100644 index 000000000..73540fd9e --- /dev/null +++ b/tests/specs/cli/otel_basic/deno_dot_exit.ts @@ -0,0 +1,2 @@ +console.log("log 1"); +Deno.exit(0); diff --git a/tests/specs/cli/otel_basic/main.ts b/tests/specs/cli/otel_basic/main.ts index 66ef5c79c..6c49462a0 100644 --- a/tests/specs/cli/otel_basic/main.ts +++ b/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); - } - if (body.resourceSpans) { - 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); + const body = await req.json(); + if (body.resourceLogs) { + data.logs.push(...body.resourceLogs[0].scopeLogs[0].logRecords); + } + if (body.resourceSpans) { + data.spans.push(...body.resourceSpans[0].scopeSpans[0].spans); } + return Response.json({ partialSuccess: {} }, { status: 200 }); }, }, ); - -setTimeout(() => { - assert(false, "test did not finish in time"); -}, 10e3); diff --git a/tests/specs/cli/otel_basic/natural_exit.out b/tests/specs/cli/otel_basic/natural_exit.out new file mode 100644 index 000000000..98a41cf60 --- /dev/null +++ b/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": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/natural_exit.ts b/tests/specs/cli/otel_basic/natural_exit.ts new file mode 100644 index 000000000..d40478252 --- /dev/null +++ b/tests/specs/cli/otel_basic/natural_exit.ts @@ -0,0 +1 @@ +console.log("log 1"); diff --git a/tests/specs/cli/otel_basic/uncaught.out b/tests/specs/cli/otel_basic/uncaught.out new file mode 100644 index 000000000..a5a886bfe --- /dev/null +++ b/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": "" + } + ] +} diff --git a/tests/specs/cli/otel_basic/uncaught.ts b/tests/specs/cli/otel_basic/uncaught.ts new file mode 100644 index 000000000..eca7c05cb --- /dev/null +++ b/tests/specs/cli/otel_basic/uncaught.ts @@ -0,0 +1,2 @@ +console.log("log 1"); +throw new Error("uncaught"); diff --git a/tests/util/server/src/macros.rs b/tests/util/server/src/macros.rs index fdbb977e9..e076583f1 100644 --- a/tests/util/server/src/macros.rs +++ b/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); } }); |