diff --git a/Cargo.toml b/Cargo.toml index de8b07cd00c36e..1e8583f3e5d789 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 eb77971748a335..aa013200479c6a 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; @@ -968,6 +969,22 @@ impl Flags { args } + pub fn otel_config(&self) -> Option { + 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), + ..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 3aaf2bd438f363..858774e6e83b9e 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 { - 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/main.rs b/cli/main.rs index 04daff6700ac7f..20d2cb6bff5943 100644 --- a/cli/main.rs +++ b/cli/main.rs @@ -350,18 +350,17 @@ fn setup_panic_hook() { eprintln!("Args: {:?}", env::args().collect::>()); 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 f5b798f81766d6..2951aa711a46d0 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(result: Result) -> 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 960aad15784a1a..4422cf973a4eed 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/util/file_watcher.rs b/cli/util/file_watcher.rs index 8d734af88e97dc..21ea95e067cd25 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(watch_future: F) -> bool where F: Future>, @@ -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 d93753dfd30391..f76663df2ce606 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 fb16e67b77c203..6e690e6f30d9a3 100644 --- a/cli/util/v8.rs +++ b/cli/util/v8.rs @@ -46,15 +46,14 @@ pub fn init_v8_flags( .skip(1) .collect::>(); - #[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 186ae42c48cfc4..2ca5c8d0b4fac6 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 6f728a92b33705..ea6b5396659a59 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/lib.rs b/runtime/lib.rs index 21b61e1c058595..3b16034753d9b4 100644 --- a/runtime/lib.rs +++ b/runtime/lib.rs @@ -140,6 +140,11 @@ pub static UNSTABLE_GRANULAR_FLAGS: &[UnstableGranularFlag] = &[ }, ]; +pub fn exit(code: i32) -> ! { + crate::ops::otel::flush(); + 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 790962f38d11bf..b10a2939e67cdd 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::().get(); - std::process::exit(code) + crate::exit(code) } #[op2] diff --git a/runtime/ops/otel.rs b/runtime/ops/otel.rs index 6a4750acc2bd24..338f7b02657a51 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; 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, // `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)] @@ -295,10 +298,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 +321,7 @@ fn otel_create_globals( return Err(anyhow!( "Failed to read env var OTEL_EXPORTER_OTLP_PROTOCOL: {}", err - )) + )); } }; @@ -372,7 +375,6 @@ fn otel_create_globals( let mut span_processor = BatchSpanProcessor::builder(span_exporter, OtelSharedRuntime).build(); span_processor.set_resource(&resource); - op_state.put::(span_processor); let log_exporter = HttpExporterBuilder::default() .with_http_client(client) @@ -381,35 +383,92 @@ fn otel_create_globals( let log_processor = BatchLogProcessor::builder(log_exporter, OtelSharedRuntime).build(); log_processor.set_resource(&resource); - op_state.put::(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::() { - 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::() { - 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::() else { + let Some((_, log_processor)) = OTEL_PROCESSORS.get() else { log::error!("op_otel_log: OpenTelemetry Logger not available"); return; }; @@ -425,23 +484,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 +520,7 @@ fn op_otel_span_start<'s>( end_time: f64, ) -> Result<(), anyhow::Error> { if let Some(temporary_span) = state.try_take::() { - let Some(span_processor) = state.try_borrow::() else { + let Some((span_processor, _)) = OTEL_PROCESSORS.get() else { return Ok(()); }; span_processor.on_end(temporary_span.0); @@ -678,7 +735,7 @@ fn op_otel_span_flush(state: &mut OpState) { return; }; - let Some(span_processor) = state.try_borrow::() else { + let Some((span_processor, _)) = OTEL_PROCESSORS.get() else { return; }; diff --git a/runtime/snapshot.rs b/runtime/snapshot.rs index bb9bf9166f32ec..7f6e6b8ab6ca2c 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 d81c82c5013be7..d9af90dd22e04d 100644 --- a/runtime/web_worker.rs +++ b/runtime/web_worker.rs @@ -505,9 +505,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, @@ -824,13 +822,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(())) } } @@ -898,7 +895,6 @@ impl WebWorker { } } -#[allow(clippy::print_stderr)] fn print_worker_error( error: &AnyError, name: &str, @@ -911,7 +907,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 82df755faf8913..c7bfb1c5f36a93 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,