diff --git a/.cargo/config.toml b/.cargo/config.toml new file mode 100644 index 0000000..a539230 --- /dev/null +++ b/.cargo/config.toml @@ -0,0 +1,2 @@ +[build] +rustflags = ["--cfg", "tracing_unstable"] diff --git a/.vscode/settings.json b/.vscode/settings.json new file mode 100644 index 0000000..5d22469 --- /dev/null +++ b/.vscode/settings.json @@ -0,0 +1,5 @@ +{ + "rust-analyzer.cargo.extraEnv": { + "RUSTFLAGS": "--cfg tracing_unstable" + } +} diff --git a/Cargo.lock b/Cargo.lock index 28e4130..b896ba6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1733,6 +1733,7 @@ dependencies = [ "tracing-error", "tracing-subscriber", "url 2.2.2", + "valuable", "wiremock", "zip 0.5.13", ] @@ -3093,6 +3094,8 @@ checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" dependencies = [ "serde", "tracing-core", + "valuable", + "valuable-serde", ] [[package]] @@ -3110,6 +3113,8 @@ dependencies = [ "tracing-core", "tracing-log", "tracing-serde", + "valuable", + "valuable-serde", ] [[package]] @@ -3247,6 +3252,30 @@ name = "valuable" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" +dependencies = [ + "valuable-derive", +] + +[[package]] +name = "valuable-derive" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9d44690c645190cfce32f91a1582281654b2338c6073fa250b0949fd25c55b32" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "valuable-serde" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5285cfff30cdabe26626736a54d989687dd9cab84f51f4048b61d6d0ae8b0907" +dependencies = [ + "serde", + "valuable", +] [[package]] name = "value-bag" diff --git a/Cargo.toml b/Cargo.toml index 73624b4..2d9c3fc 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,10 +27,11 @@ strum = { version = "0.24", features = ["derive"] } tempfile = "3.3" tokio = { version = "1.16", features = ["full"] } tokio-util = { version = "0.7", features = ["full"] } -tracing = "0.1" +tracing = { version = "0.1", features = ["valuable"] } tracing-error = "0.2" -tracing-subscriber = { version = "0.3", features = ["default", "json"] } +tracing-subscriber = { version = "0.3", features = ["default", "json", "valuable"] } url = "2.2" +valuable = { version = "0.1.0", features = ["derive"] } gitlab-runner = "0.0.5" # gitlab-runner = { path = "../gitlab-runner-rs/gitlab-runner" } diff --git a/src/errors.rs b/src/errors.rs new file mode 100644 index 0000000..46dd194 --- /dev/null +++ b/src/errors.rs @@ -0,0 +1,142 @@ +use color_eyre::{ + config::EyreHook, + eyre::{EyreHandler, InstallError}, + Report, +}; +use tracing::error; +use tracing_error::{ExtractSpanTrace, SpanTrace}; +use valuable::Valuable; + +struct Handler { + inner: Box, + location: Option<&'static std::panic::Location<'static>>, +} + +impl Handler { + fn new(inner: Box) -> Self { + assert!(inner.downcast_ref::().is_some()); + + Self { + inner, + location: None, + } + } + + fn span_trace(&self) -> Option<&SpanTrace> { + self.inner + .downcast_ref::() + .unwrap() + .span_trace() + } +} + +impl EyreHandler for Handler { + fn debug( + &self, + error: &(dyn std::error::Error + 'static), + f: &mut core::fmt::Formatter<'_>, + ) -> core::fmt::Result { + self.inner.debug(error, f) + } + + fn display( + &self, + error: &(dyn std::error::Error + 'static), + f: &mut core::fmt::Formatter<'_>, + ) -> core::fmt::Result { + self.inner.display(error, f) + } + + fn track_caller(&mut self, location: &'static std::panic::Location<'static>) { + self.location = Some(location); + self.inner.track_caller(location) + } +} + +#[derive(Valuable)] +struct LocationValue { + // These field names mimic the ones in regular span traces. + filename: &'static str, + line_number: u32, +} + +#[derive(Valuable)] +struct SpanFrameValue { + name: String, + location: Option, + fields: String, +} + +#[derive(Valuable)] +struct ReportValue { + location: Option, + errors: Vec, + spans: Vec, +} + +fn get_span_trace_value(span_trace: &SpanTrace) -> Vec { + let mut trace: Vec = vec![]; + span_trace.with_spans(|span, fields| { + trace.push(SpanFrameValue { + name: span.name().to_owned(), + location: match (span.file(), span.line()) { + (Some(filename), Some(line_number)) => Some(LocationValue { + filename, + line_number, + }), + (_, _) => None, + }, + fields: fields.to_owned(), + }); + true + }); + trace +} + +impl ReportValue { + fn from_report(report: &Report) -> Option { + report + .handler() + .downcast_ref::() + .map(|handler| Self { + location: handler.location.map(|location| LocationValue { + filename: location.file(), + line_number: location.line(), + }), + errors: report + .chain() + .filter_map(|error| { + // The is_none() is something color-eyre does here too, + // but I'm honestly not sure why. + if error.span_trace().is_none() { + Some(format!("{}", error)) + } else { + None + } + }) + .collect(), + spans: handler + .span_trace() + // If the handler has no span trace, get the one closest to + // the root cause. + .or_else(|| report.chain().rev().filter_map(|e| e.span_trace()).next()) + .map(get_span_trace_value) + .unwrap_or_default(), + }) + } +} + +pub fn install_json_report_hook(hook: EyreHook) -> Result<(), InstallError> { + let error_hook = hook.into_eyre_hook(); + color_eyre::eyre::set_hook(Box::new(move |error| { + Box::new(Handler::new(error_hook(error))) + })) +} + +pub fn log_report(report: Report) { + if let Some(report) = ReportValue::from_report(&report) { + error!(report = &report.as_value()); + } else { + error!(?report); + } +} diff --git a/src/handler.rs b/src/handler.rs index 1feea6f..6d65f1a 100644 --- a/src/handler.rs +++ b/src/handler.rs @@ -21,12 +21,13 @@ use open_build_service_api as obs; use serde::{Deserialize, Serialize}; use tokio::{fs::File as AsyncFile, io::AsyncSeekExt}; use tokio_util::{compat::FuturesAsyncWriteCompatExt, io::ReaderStream}; -use tracing::{debug, error, instrument}; +use tracing::{debug, instrument}; use crate::{ artifacts::{save_to_tempfile, ArtifactDirectory}, binaries::download_binaries, build_meta::{BuildHistoryRetrieval, BuildMeta, CommitBuildInfo, RepoArch}, + errors::log_report, monitor::{MonitoredPackage, ObsMonitor, PackageCompletion, PackageMonitoringOptions}, pipeline::{generate_monitor_pipeline, GeneratePipelineOptions, PipelineDownloadBinaries}, prune::prune_branch, @@ -451,7 +452,7 @@ impl ObsJobHandler { outputln!("Build was superceded by a newer revision."); } PackageCompletion::Disabled => { - outputln!("Package is disabled for this architecture."); + outputln!("Build is disabled for this architecture."); } PackageCompletion::Failed(reason) => { log_file @@ -603,15 +604,17 @@ async fn upload_artifact( #[async_trait] impl JobHandler for ObsJobHandler { + #[tracing::instrument(skip(self))] async fn step(&mut self, script: &[String], _phase: Phase) -> JobResult { for command in script { if let Err(err) = self.command(command).await { // Failed builds would already have information on them printed // above, so don't print anything on them again. if !err.is::() { - error!(gitlab.output = true, "Error running command: {:?}", err); + outputln!("Error running command: {:?}", err); } + log_report(err); self.script_failed = true; return Err(()); } @@ -620,12 +623,14 @@ impl JobHandler for ObsJobHandler { Ok(()) } + #[tracing::instrument(skip(self, uploader))] async fn upload_artifacts(&mut self, uploader: &mut Uploader) -> JobResult { let mut success = true; for (name, file) in &mut self.artifacts { if let Err(err) = upload_artifact(name.clone(), file, uploader).await { - error!(gitlab.output = true, "Failed to upload {}: {:?}", name, err); + outputln!("Failed to upload {}: {:?}", name, err); + log_report(err); success = false; } } @@ -1504,7 +1509,7 @@ mod tests { // so don't check for an old build status. let build_actually_occurred = dput_test != DputTest::ReusePreviousBuild; assert_eq!( - job_log.contains("Waiting for build status"), + job_log.contains("waiting for updates"), build_actually_occurred ); diff --git a/src/main.rs b/src/main.rs index 0638df0..b4fc11a 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,26 +1,23 @@ use std::{fmt, str::FromStr}; use clap::Parser; -use color_eyre::eyre::Result; -use gitlab_runner::Runner; +use color_eyre::{config::HookBuilder, eyre::Result}; +use gitlab_runner::{outputln, Runner}; use strum::{Display, EnumString}; -use tracing::{error, info, Subscriber}; -use tracing_subscriber::{ - filter::targets::Targets, - fmt::{format::DefaultFields, FormatEvent}, - prelude::*, - registry::LookupSpan, - util::SubscriberInitExt, - Layer, -}; +use tracing::info; +use tracing_subscriber::{filter::targets::Targets, prelude::*, util::SubscriberInitExt, Layer}; use url::Url; -use crate::handler::{HandlerOptions, ObsJobHandler}; +use crate::{ + errors::{install_json_report_hook, log_report}, + handler::{HandlerOptions, ObsJobHandler}, +}; mod artifacts; mod binaries; mod build_meta; mod dsc; +mod errors; mod handler; mod monitor; mod pipeline; @@ -59,7 +56,7 @@ impl fmt::Display for TargetsArg { } } -#[derive(Display, EnumString)] +#[derive(Display, EnumString, PartialEq, Eq)] #[strum(serialize_all = "lowercase")] enum LogFormat { Pretty, @@ -90,16 +87,6 @@ struct Args { max_jobs: usize, } -fn formatter_layer(format: E, targets: Targets) -> impl Layer -where - S: Subscriber + for<'a> LookupSpan<'a>, - E: FormatEvent + 'static, -{ - tracing_subscriber::fmt::layer() - .event_format(format) - .with_filter(targets) -} - #[tokio::main] async fn main() { let args = Args::parse(); @@ -113,34 +100,46 @@ async fn main() { match args.log_format { LogFormat::Compact => registry - .with(formatter_layer( - tracing_subscriber::fmt::format().compact(), - args.log.targets, - )) + .with( + tracing_subscriber::fmt::layer() + .compact() + .with_filter(args.log.targets), + ) .init(), LogFormat::Json => registry - .with(formatter_layer( - tracing_subscriber::fmt::format().json(), - args.log.targets, - )) + .with( + tracing_subscriber::fmt::layer() + .json() + .with_filter(args.log.targets), + ) .init(), LogFormat::Pretty => registry - .with(formatter_layer( - tracing_subscriber::fmt::format().pretty(), - args.log.targets, - )) + .with( + tracing_subscriber::fmt::layer() + .pretty() + .with_filter(args.log.targets), + ) .init(), } - color_eyre::install().unwrap(); + let (panic_hook, eyre_hook) = HookBuilder::default().into_hooks(); + panic_hook.install(); + + if args.log_format == LogFormat::Json { + install_json_report_hook(eyre_hook).unwrap(); + } else { + eyre_hook.install().unwrap(); + } info!("Starting runner..."); + runner .run( |job| async { ObsJobHandler::from_obs_config_in_job(job, HandlerOptions::default()).map_err( |err| { - error!("Failed to create new client: {:?}", err); + outputln!("Failed to set up job handler: {:?}", err); + log_report(err); }, ) }, diff --git a/src/monitor.rs b/src/monitor.rs index 4aab4ce..d674c68 100644 --- a/src/monitor.rs +++ b/src/monitor.rs @@ -214,11 +214,11 @@ impl ObsMonitor { match state { PackageBuildState::Building(code) => { if previous_code != Some(code) { - if previous_code.is_some() { - outputln!("Build status is now '{}'...", code); - } else { - outputln!("Monitoring build, current status is '{}'...", code); + if previous_code.is_none() { + outputln!("Monitoring build..."); } + + outputln!("Build status is '{}'.", code); previous_code = Some(code); } @@ -226,7 +226,10 @@ impl ObsMonitor { } PackageBuildState::Dirty => { if !was_dirty { - outputln!("Package is dirty, trying again later..."); + outputln!( + "Package build is dirty / being re-scheduled, \ + waiting for updates..." + ); } was_dirty = true; @@ -235,11 +238,14 @@ impl ObsMonitor { PackageBuildState::PendingStatusPosted => { ensure!( old_status_retries < options.max_old_status_retries, - "Old build status has been posted for too long." + "Outdated package build status has been posted for too long." ); if old_status_retries == 0 { - outputln!("Waiting for build status to be available..."); + outputln!( + "Package has the build status of a previous build, \ + waiting for updates..." + ); } old_status_retries += 1; @@ -870,6 +876,10 @@ mod tests { tokio::time::timeout(Duration::from_secs(5), monitor.monitor_package(options)).await ); let err = assert_err!(result); - assert!(err.to_string().contains("Old build status"), "{:?}", err); + assert!( + err.to_string().contains("Outdated package build status"), + "{:?}", + err + ); } }