format: render stack traces in results

Now when a test fails, we get output like the below, which allows us to see
where things actually went wrong.

This is a bit fugly because it displays the stack trace twice. This is because
we're using thiserror which doesn't really provide us a nice way to override
Display implementations (perhaps we should just hand craft those, but then
what's the point of the macro?).

This also requires us to use nightly, because std::backtrace and related
functionality are not in stable yet. Hopefully they will arrive soon. (I did
not add in all the macro tests for feature, since we don't necessarily care
about building on stable right now...)

Anyway, let's say this:

Fixes project-machine#22

for now. Hopefully someone can come along in 6 months when the situation looks
better and make things prettier, but for now this at least gives us functional
backtraces.

test tests::test_put_blob_correct_hash ... ok
thread 'index::tests::test_can_open_new_index' panicked at 'called `Result::unwrap()` on an `Err` value: invalid image schema: -1
   0: oci::index::Index::open
             at ./src/index.rs:46:68
   1: oci::index::tests::test_can_open_new_index
             at ./src/index.rs:74:9
   2: oci::index::tests::test_can_open_new_index::{{closure}}
             at ./src/index.rs:70:5
   3: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   4: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
      test::__rust_begin_short_backtrace
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:576:5
   5: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:344:9
      std::panicking::try::do_call
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:379:40
      std::panicking::try
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:343:19
      std::panic::catch_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:431:14
      test::run_test_in_process
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:599:18
      test::run_test::run_test_inner::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:491:39
   6: test::run_test::run_test_inner::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:518:37
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/sys_common/backtrace.rs:125:18
   7: std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/thread/mod.rs:474:17
      <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:344:9
      std::panicking::try::do_call
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:379:40
      std::panicking::try
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:343:19
      std::panic::catch_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:431:14
      std::thread::Builder::spawn_unchecked::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/thread/mod.rs:473:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   8: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      std::sys::unix::thread::Thread::new::thread_start
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/sys/unix/thread.rs:71:17
   9: start_thread
  10: clone
', oci/src/index.rs:74:45
stack backtrace:
thread 'tests::test_put_get_index' panicked at 'called `Result::unwrap()` on an `Err` value: invalid image schema: -1
   0: oci::index::Index::open
             at ./src/index.rs:46:68
   1: oci::Image::get_index
             at ./src/lib.rs:130:9
   2: oci::tests::test_put_get_index
             at ./src/lib.rs:186:22
   3: oci::tests::test_put_get_index::{{closure}}
             at ./src/lib.rs:173:5
   4: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   5: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
      test::__rust_begin_short_backtrace
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:576:5
   6: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:344:9
      std::panicking::try::do_call
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:379:40
      std::panicking::try
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:343:19
      std::panic::catch_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:431:14
      test::run_test_in_process
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:599:18
      test::run_test::run_test_inner::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:491:39
   7: test::run_test::run_test_inner::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/test/src/lib.rs:518:37
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/sys_common/backtrace.rs:125:18
   8: std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/thread/mod.rs:474:17
      <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:344:9
      std::panicking::try::do_call
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:379:40
      std::panicking::try
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:343:19
      std::panic::catch_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panic.rs:431:14
      std::thread::Builder::spawn_unchecked::{{closure}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/thread/mod.rs:473:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   9: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/alloc/src/boxed.rs:1546:9
      std::sys::unix::thread::Thread::new::thread_start
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/sys/unix/thread.rs:71:17
  10: start_thread
  11: clone
', oci/src/lib.rs:186:41
   0: rust_begin_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:493:5
   1: core::panicking::panic_fmt
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/panicking.rs:92:14
   2: core::result::unwrap_failed
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/result.rs:1355:5
   3: core::result::Result<T,E>::unwrap
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/result.rs:1037:23
   4: oci::index::tests::test_can_open_new_index
             at ./src/index.rs:74:9
   5: oci::index::tests::test_can_open_new_index::{{closure}}
             at ./src/index.rs:70:5
   6: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   7: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: rust_begin_unwind
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/std/src/panicking.rs:493:5
   1: core::panicking::panic_fmt
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/panicking.rs:92:14
   2: core::result::unwrap_failed
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/result.rs:1355:5
   3: core::result::Result<T,E>::unwrap
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/result.rs:1037:23
   4: oci::tests::test_put_get_index
             at ./src/lib.rs:186:22
   5: oci::tests::test_put_get_index::{{closure}}
             at ./test index::tests::test_can_open_new_index ... src/lib.rs:FAILED173:5

   6: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
   7: core::ops::function::FnOnce::call_once
             at /rustc/132b4e5d167b7e622fcc11fa2b67b931105b4de1/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Signed-off-by: Tycho Andersen <tycho@tycho.pizza>

.github/workflows/ci.yaml

@@ -13,7 +13,8 @@ jobs:
             - uses: actions/checkout@v2
             - uses: actions-rs/toolchain@v1
               with:
-                toolchain: stable
+                toolchain: nightly
+                components: clippy, rustfmt
             - name: install dependencies
               run: |
                 sudo apt-get install libfuse-dev libzstd-dev libxxhash-dev

Makefile

@@ -1,16 +1,16 @@
 SRC=$(shell find . -name \*.rs | grep -v "^./target")
 
 target/debug/puzzlefs: $(SRC)
-	cargo build
+	cargo +nightly build
 
 .PHONY: check
 check:
-	RUST_BACKTRACE=1 cargo test -- --nocapture
+	RUST_BACKTRACE=1 cargo +nightly test -- --nocapture
 
 .PHONY: lint
 lint: $(SRC)
 	rustfmt --check $(SRC)
-	cargo clippy --all-targets --all-features -- -D warnings -A clippy::upper-case-acronyms
+	cargo +nightly clippy --all-targets --all-features -- -D warnings -A clippy::upper-case-acronyms
 
 .PHONY: fmt
 fmt:

format/src/error.rs

@@ -0,0 +1,68 @@
+extern crate serde_cbor;
+extern crate serde_json;
+
+use std::backtrace::Backtrace;
+use std::error::Error;
+use std::fmt;
+use std::io;
+use std::os::raw::c_int;
+
+use nix::errno::Errno;
+use thiserror::Error;
+
+#[derive(Error)]
+pub enum WireFormatError {
+    #[error("cannot turn local ref into a digest")]
+    LocalRefError(Backtrace),
+    #[error("cannot seek to other blob")]
+    SeekOtherError(Backtrace),
+    #[error("no value present")]
+    ValueMissing(Backtrace),
+    #[error("invalid image schema: {0}")]
+    InvalidImageSchema(i32, Backtrace),
+    #[error("invalid image version: {0}")]
+    InvalidImageVersion(String, Backtrace),
+    #[error("fs error: {0}")]
+    IOError(#[from] io::Error, Backtrace),
+    #[error("deserialization error (cbor): {0}")]
+    CBORError(#[from] serde_cbor::Error, Backtrace),
+    #[error("deserialization error (json): {0}")]
+    JSONError(#[from] serde_json::Error, Backtrace),
+}
+
+impl WireFormatError {
+    pub fn to_errno(&self) -> c_int {
+        match self {
+            WireFormatError::LocalRefError(..) => Errno::EINVAL as c_int,
+            WireFormatError::SeekOtherError(..) => Errno::ESPIPE as c_int,
+            WireFormatError::ValueMissing(..) => Errno::ENOENT as c_int,
+            WireFormatError::InvalidImageSchema(..) => Errno::EINVAL as c_int,
+            WireFormatError::InvalidImageVersion(..) => Errno::EINVAL as c_int,
+            WireFormatError::IOError(ioe, ..) => {
+                ioe.raw_os_error().unwrap_or(Errno::EINVAL as i32) as c_int
+            }
+            WireFormatError::CBORError(..) => Errno::EINVAL as c_int,
+            WireFormatError::JSONError(..) => Errno::EINVAL as c_int,
+        }
+    }
+
+    pub fn from_errno(errno: Errno) -> Self {
+        Self::IOError(
+            io::Error::from_raw_os_error(errno as i32),
+            Backtrace::capture(),
+        )
+    }
+}
+
+impl fmt::Debug for WireFormatError {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> std::result::Result<(), fmt::Error> {
+        // This sucks, but otherwise we get astonishingly ugly stack traces. (In both cases, they
+        // get rendered twice when we do .unwrap() of an error in tests, which sucks, but...)
+        write!(f, "{}", &self)?;
+        self.backtrace()
+            .map(|b| write!(f, "\n{}", b))
+            .unwrap_or(Ok(()))
+    }
+}
+
+pub type Result<T> = std::result::Result<T, WireFormatError>;

format/src/lib.rs

@@ -1,2 +1,6 @@
+#![feature(backtrace)]
 mod types;
 pub use types::*;
+
+mod error;
+pub use error::*;

format/src/types.rs

@@ -1,74 +1,30 @@
 extern crate serde_cbor;
-extern crate serde_json;
 extern crate xattr;
 
+use std::backtrace::Backtrace;
 use std::convert::TryInto;
 use std::ffi::OsString;
 use std::fs;
 use std::io;
 use std::io::{Read, Seek};
 use std::mem;
-use std::os::raw::c_int;
 use std::os::unix::fs::{FileTypeExt, MetadataExt};
 use std::path::Path;
 use std::vec::Vec;
 
-use nix::errno::Errno;
 use nix::sys::stat;
 use serde::de::Error as SerdeError;
 use serde::de::Visitor;
 use serde::{Deserialize, Deserializer, Serialize, Serializer};
-use thiserror::Error;
 
 use compression::{Compression, Decompressor};
 
+use crate::error::{Result, WireFormatError};
+
 // To get off the ground here, we just use serde and cbor for most things, except for the fixed
 // size Inode which depends being a fixed size (and cbor won't generate it that way) in the later
 // format.
 
-#[derive(Error, Debug)]
-pub enum WireFormatError {
-    #[error("cannot turn local ref into a digest")]
-    LocalRefError,
-    #[error("cannot seek to other blob")]
-    SeekOtherError,
-    #[error("no value present")]
-    ValueMissing,
-    #[error("invalid image schema")]
-    InvalidImageSchema(i32),
-    #[error("invalid image version")]
-    InvalidImageVersion(String),
-    #[error("fs error")]
-    IOError(#[from] io::Error),
-    #[error("deserialization error (cbor)")]
-    CBORError(#[from] serde_cbor::Error),
-    #[error("deserialization error (json)")]
-    JSONError(#[from] serde_json::Error),
-}
-
-impl WireFormatError {
-    pub fn to_errno(&self) -> c_int {
-        match self {
-            WireFormatError::LocalRefError => Errno::EINVAL as c_int,
-            WireFormatError::SeekOtherError => Errno::ESPIPE as c_int,
-            WireFormatError::ValueMissing => Errno::ENOENT as c_int,
-            WireFormatError::InvalidImageSchema(_) => Errno::EINVAL as c_int,
-            WireFormatError::InvalidImageVersion(_) => Errno::EINVAL as c_int,
-            WireFormatError::IOError(ioe) => {
-                ioe.raw_os_error().unwrap_or(Errno::EINVAL as i32) as c_int
-            }
-            WireFormatError::CBORError(_) => Errno::EINVAL as c_int,
-            WireFormatError::JSONError(_) => Errno::EINVAL as c_int,
-        }
-    }
-
-    pub fn from_errno(errno: Errno) -> Self {
-        Self::IOError(io::Error::from_raw_os_error(errno as i32))
-    }
-}
-
-pub type Result<T> = std::result::Result<T, WireFormatError>;
-
 /*
  *
  * TODO: use these wrappers like the spec says
@@ -92,7 +48,7 @@ fn read_one<'a, T: Deserialize<'a>, R: Read>(r: R) -> Result<T> {
     // read one value.
     let mut iter = serde_cbor::Deserializer::from_reader(r).into_iter::<T>();
     let v = iter.next().transpose()?;
-    v.ok_or(WireFormatError::ValueMissing)
+    v.ok_or_else(|| WireFormatError::ValueMissing(Backtrace::capture()))
 }
 
 #[derive(Serialize, Deserialize, Debug)]
@@ -491,7 +447,7 @@ impl MetadataBlob {
 
     pub fn seek_ref(&mut self, r: &BlobRef) -> Result<u64> {
         match r.kind {
-            BlobRefKind::Other { .. } => Err(WireFormatError::SeekOtherError),
+            BlobRefKind::Other { .. } => Err(WireFormatError::SeekOtherError(Backtrace::capture())),
             BlobRefKind::Local => self
                 .f
                 .seek(io::SeekFrom::Start(r.offset))

oci/src/descriptor.rs

@@ -1,3 +1,4 @@
+use std::backtrace::Backtrace;
 use std::collections::HashMap;
 use std::convert::{TryFrom, TryInto};
 use std::fmt;
@@ -45,7 +46,7 @@ impl TryFrom<BlobRef> for Digest {
     fn try_from(v: BlobRef) -> std::result::Result<Self, Self::Error> {
         match v.kind {
             BlobRefKind::Other { digest } => Ok(Digest(digest)),
-            BlobRefKind::Local => Err(WireFormatError::LocalRefError),
+            BlobRefKind::Local => Err(WireFormatError::LocalRefError(Backtrace::capture())),
         }
     }
 }
@@ -55,7 +56,7 @@ impl TryFrom<&BlobRef> for Digest {
     fn try_from(v: &BlobRef) -> std::result::Result<Self, Self::Error> {
         match v.kind {
             BlobRefKind::Other { digest } => Ok(Digest(digest)),
-            BlobRefKind::Local => Err(WireFormatError::LocalRefError),
+            BlobRefKind::Local => Err(WireFormatError::LocalRefError(Backtrace::capture())),
         }
     }
 }

oci/src/index.rs

@@ -1,3 +1,4 @@
+use std::backtrace::Backtrace;
 use std::collections::HashMap;
 use std::fs;
 use std::path::Path;
@@ -40,7 +41,10 @@ impl Index {
         let index_file = fs::File::open(p)?;
         let index = serde_json::from_reader::<_, Index>(index_file)?;
         if index.version != PUZZLEFS_SCHEMA_VERSION {
-            Err(WireFormatError::InvalidImageSchema(index.version))
+            Err(WireFormatError::InvalidImageSchema(
+                index.version,
+                Backtrace::capture(),
+            ))
         } else {
             Ok(index)
         }

oci/src/lib.rs

@@ -1,5 +1,8 @@
+#![feature(backtrace)]
+
 extern crate hex;
 
+use std::backtrace::Backtrace;
 use std::convert::TryFrom;
 use std::fs;
 use std::io;
@@ -54,7 +57,10 @@ impl<'a> Image<'a> {
         let layout_file = fs::File::open(oci_dir.join(IMAGE_LAYOUT_PATH))?;
         let layout = serde_json::from_reader::<_, OCILayout>(layout_file)?;
         if layout.version != PUZZLEFS_IMAGE_LAYOUT_VERSION {
-            Err(WireFormatError::InvalidImageVersion(layout.version))
+            Err(WireFormatError::InvalidImageVersion(
+                layout.version,
+                Backtrace::capture(),
+            ))
         } else {
             Ok(Image { oci_dir })
         }