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 <[email protected]>

Author: refi64

.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.lock

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

Cargo.toml

@@ -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/errors.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::<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;
             }
         }

src/handler.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