From 40904556dd0365c6b7d49dd03fd9eda151c9047a Mon Sep 17 00:00:00 2001 From: Ryan Gonzalez Date: Wed, 2 Nov 2022 13:29:50 -0500 Subject: [PATCH 1/4] Set up JSON logging properly for fields When using the JSON logging backend, tracing expects the fields to have been formatted as a JSON string. However, the layer wasn't set up properly for that, resulting in a variety of "field_error"s in the logs (and panics on debug builds). As it turns out, we were setting it up in an overcomplicated way regardless, so use the simpler helper functions in tracing that set all of this up for us. Signed-off-by: Ryan Gonzalez --- src/main.rs | 48 +++++++++++++++++------------------------------- 1 file changed, 17 insertions(+), 31 deletions(-) diff --git a/src/main.rs b/src/main.rs index 0638df0..c754c67 100644 --- a/src/main.rs +++ b/src/main.rs @@ -4,15 +4,8 @@ use clap::Parser; use color_eyre::eyre::Result; use gitlab_runner::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::{error, info}; +use tracing_subscriber::{filter::targets::Targets, prelude::*, util::SubscriberInitExt, Layer}; use url::Url; use crate::handler::{HandlerOptions, ObsJobHandler}; @@ -90,16 +83,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,22 +96,25 @@ 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(), } From 6a0fa58f2c5e515077109fe2cb477280ea99ae18 Mon Sep 17 00:00:00 2001 From: Ryan Gonzalez Date: Wed, 2 Nov 2022 12:24:44 -0500 Subject: [PATCH 2/4] Log errors as JSON, independently from GitLab While thinking on #6 and the accidental / intentional use of gitlab.output, it occurred to me that the way we show errors for GitLab is not actually how we'd want them logged with JSON logging (which currently dumps the entire error string, *including ANSI codes*, inside the JSON objects). With this in mind, I realized we can get the color-eyre handler's span traces and just convert it to JSON manually. This would be all, if we could actually log JSON from tracing. Unfortunately, any extra fields logged are converted to strings via Debug and stored as such in the JSON fields. That means we end up with our beautiful JSON errors stuck as strings and filled with dozens of escape sequences, which also makes them entirely unreadable without taking the JSON apart. But! tracing has "unstable" (can change in a bugfix release, but isn't that what Cargo.lock is for anyway?) functionality that integrates with the valuable crate, such that any field value that's a Valuable will be serialized as JSON. So, the eyre Report is converted to an intermediate Valuable that gets sent to tracing, which dutifully serializes it as an actual JSON object. This does, however, still have an unfortunate missing piece, which is serializing the fields in the span trace. tracing-error serializes fields into a string to be retrieved when the span trace is collected, which isn't the JSON format we would want. Now, this *can* be changed to format JSON, but that's not very useful because: - It means that span trace fields will be shown as JSON in the GitLab logs too, which isn't great. - There is no straightforward way to go from a JSON string to a Valuable: valuable only includes ways to go serialize a Valuable via Serde, without any way of *deserializing*. This would only be possible by manually converting everything, which is increasing the already-high complexity. In practice, the individual field values don't really have complex JSON values, so leaving the default non-JSON formatting there is fine. Signed-off-by: Ryan Gonzalez --- .cargo/config.toml | 2 + .vscode/settings.json | 5 ++ Cargo.lock | 29 +++++++++ Cargo.toml | 5 +- src/errors.rs | 142 ++++++++++++++++++++++++++++++++++++++++++ src/handler.rs | 11 +++- src/main.rs | 19 ++++-- 7 files changed, 204 insertions(+), 9 deletions(-) create mode 100644 .cargo/config.toml create mode 100644 .vscode/settings.json create mode 100644 src/errors.rs 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..017f527 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, @@ -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; } } diff --git a/src/main.rs b/src/main.rs index c754c67..d367091 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,19 +1,23 @@ use std::{fmt, str::FromStr}; use clap::Parser; -use color_eyre::eyre::Result; +use color_eyre::{config::HookBuilder, eyre::Result}; use gitlab_runner::Runner; use strum::{Display, EnumString}; use tracing::{error, 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, + handler::{HandlerOptions, ObsJobHandler}, +}; mod artifacts; mod binaries; mod build_meta; mod dsc; +mod errors; mod handler; mod monitor; mod pipeline; @@ -52,7 +56,7 @@ impl fmt::Display for TargetsArg { } } -#[derive(Display, EnumString)] +#[derive(Display, EnumString, PartialEq, Eq)] #[strum(serialize_all = "lowercase")] enum LogFormat { Pretty, @@ -118,7 +122,14 @@ async fn main() { .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 From d4c84fc09493375c0b2b8c1de1636db786e480ed Mon Sep 17 00:00:00 2001 From: Ryan Gonzalez Date: Wed, 2 Nov 2022 13:43:26 -0500 Subject: [PATCH 3/4] Clarify some more logging messages Terminology like "build status" and "dirty" isn't super helpful, so try to make it clearer what's going on. Signed-off-by: Ryan Gonzalez --- src/handler.rs | 4 ++-- src/monitor.rs | 26 ++++++++++++++++++-------- 2 files changed, 20 insertions(+), 10 deletions(-) diff --git a/src/handler.rs b/src/handler.rs index 017f527..6d65f1a 100644 --- a/src/handler.rs +++ b/src/handler.rs @@ -452,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 @@ -1509,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/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 + ); } } From ac2f475580689f0758cb3285f667a67bb247ff64 Mon Sep 17 00:00:00 2001 From: Ryan Gonzalez Date: Wed, 2 Nov 2022 13:43:55 -0500 Subject: [PATCH 4/4] Log to GitLab when the job handler cannot be created This can happen due to e.g. configuration issues on the repo, so it makes sense to log it somewhere other than just the service logs. Signed-off-by: Ryan Gonzalez --- src/main.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/main.rs b/src/main.rs index d367091..b4fc11a 100644 --- a/src/main.rs +++ b/src/main.rs @@ -2,14 +2,14 @@ use std::{fmt, str::FromStr}; use clap::Parser; use color_eyre::{config::HookBuilder, eyre::Result}; -use gitlab_runner::Runner; +use gitlab_runner::{outputln, Runner}; use strum::{Display, EnumString}; -use tracing::{error, info}; +use tracing::info; use tracing_subscriber::{filter::targets::Targets, prelude::*, util::SubscriberInitExt, Layer}; use url::Url; use crate::{ - errors::install_json_report_hook, + errors::{install_json_report_hook, log_report}, handler::{HandlerOptions, ObsJobHandler}, }; @@ -132,12 +132,14 @@ async fn main() { } 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); }, ) },