Various improvements around logging & JSON

.cargo/config.toml

@@ -0,0 +1,2 @@
+[build]
+rustflags = ["--cfg", "tracing_unstable"]

.vscode/settings.json

@@ -0,0 +1,5 @@
+{
+  "rust-analyzer.cargo.extraEnv": {
+    "RUSTFLAGS": "--cfg tracing_unstable"
+  }
+}

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" }

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<dyn EyreHandler>,
+    location: Option<&'static std::panic::Location<'static>>,
+}
+
+impl Handler {
+    fn new(inner: Box<dyn EyreHandler>) -> Self {
+        assert!(inner.downcast_ref::<color_eyre::Handler>().is_some());
+
+        Self {
+            inner,
+            location: None,
+        }
+    }
+
+    fn span_trace(&self) -> Option<&SpanTrace> {
+        self.inner
+            .downcast_ref::<color_eyre::Handler>()
+            .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<LocationValue>,
+    fields: String,
+}
+
+#[derive(Valuable)]
+struct ReportValue {
+    location: Option<LocationValue>,
+    errors: Vec<String>,
+    spans: Vec<SpanFrameValue>,
+}
+
+fn get_span_trace_value(span_trace: &SpanTrace) -> Vec<SpanFrameValue> {
+    let mut trace: Vec<SpanFrameValue> = 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<Self> {
+        report
+            .handler()
+            .downcast_ref::<Handler>()
+            .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);
+    }
+}

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::<FailedBuild>() {
-                    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
             );