Merge pull request #5793 from str4d/5766-print-test-logs-on-failure

test: Capture gtest log output and only print on error

src/gtest/main.cpp

@@ -9,6 +9,8 @@
 #include <sodium.h>
 #include <tracing.h>
 
+#include <boost/filesystem.hpp>
+
 const std::function<std::string(const char*)> G_TRANSLATION_FUN = nullptr;
 
 struct ECCryptoClosure
@@ -18,16 +20,62 @@ struct ECCryptoClosure
 
 ECCryptoClosure instance_of_eccryptoclosure;
 
+class LogGrabber : public ::testing::EmptyTestEventListener {
+    fs::path logPath;
+
+public:
+    LogGrabber(fs::path logPathIn) : logPath(logPathIn) {}
+
+    virtual void OnTestStart(const ::testing::TestInfo& test_info) {
+        // Test logs are written synchronously, so we can clear the log file to
+        // ensure that at the end of the test, the log lines are all related to
+        // the test itself.
+        std::ofstream logFile;
+        logFile.open(logPath.string(), std::ofstream::out | std::ofstream::trunc);
+        logFile.close();
+    }
+
+    virtual void OnTestEnd(const ::testing::TestInfo& test_info) {
+        // If the test failed, print the test logs.
+        auto result = test_info.result();
+        if (result && result->Failed()) {
+            std::cout << "\n--- Logs:";
+
+            std::ifstream logFile;
+            logFile.open(logPath.string(), std::ios::in | std::ios::ate);
+            ASSERT_TRUE(logFile.is_open());
+            logFile.seekg(0, logFile.beg);
+            std::string line;
+            while (logFile.good()) {
+                std::getline(logFile, line);
+                if (!line.empty()) {
+                    std::cout << "\n  " << line;
+                }
+            }
+
+            std::cout << "\n---" << std::endl;
+        }
+    }
+};
+
 int main(int argc, char **argv) {
   assert(sodium_init() != -1);
   ECC_Start();
 
-  // Log all errors to stdout so we see them in test output.
-  std::string initialFilter = "error";
-  pTracingHandle = tracing_init(
-      nullptr, 0,
-      initialFilter.c_str(),
-      false);
+    // Log all errors to a common test file.
+    fs::path tmpPath = fs::temp_directory_path();
+    fs::path tmpFilename = fs::unique_path("%%%%%%%%");
+    fs::path logPath = tmpPath / tmpFilename;
+    const fs::path::string_type& logPathStr = logPath.native();
+    static_assert(sizeof(fs::path::value_type) == sizeof(codeunit),
+                    "native path has unexpected code unit size");
+    const codeunit* logPathCStr = reinterpret_cast<const codeunit*>(logPathStr.c_str());
+    size_t logPathLen = logPathStr.length();
+
+    std::string initialFilter = "error";
+    pTracingHandle = tracing_init_test(
+        logPathCStr, logPathLen,
+        initialFilter.c_str());
 
   testing::InitGoogleMock(&argc, argv);
 
@@ -35,6 +83,10 @@ int main(int argc, char **argv) {
   // tests on macOS (https://github.com/zcash/zcash/issues/4802).
   testing::FLAGS_gtest_death_test_style = "threadsafe";
 
+    ::testing::TestEventListeners& listeners =
+        ::testing::UnitTest::GetInstance()->listeners();
+    listeners.Append(new LogGrabber(logPath));
+
   auto ret = RUN_ALL_TESTS();
 
   ECC_Stop();

src/rust/include/tracing.h

@@ -30,6 +30,16 @@ TracingHandle* tracing_init(
     const char* initial_filter,
     bool log_timestamps);
 
+/// Initializes the tracing crate for use in tests, returning a handle for the
+/// logging component. The handle must be freed to close the logging component.
+///
+/// `log_path` is the path to a file that logs will be written to, and must not
+/// be NULL. Logs are written synchronously to avoid non-determinism in tests.
+TracingHandle* tracing_init_test(
+    const codeunit* log_path,
+    size_t log_path_len,
+    const char* initial_filter);
+
 /// Frees a tracing handle returned from `tracing_init`;
 void tracing_free(TracingHandle* handle);
 

src/rust/src/tracing_ffi.rs

@@ -1,9 +1,14 @@
 use libc::c_char;
 use std::ffi::CStr;
+use std::fs::File;
 use std::path::Path;
 use std::slice;
 use std::str;
-use std::sync::atomic::{AtomicUsize, Ordering};
+use std::sync::{
+    atomic::{AtomicUsize, Ordering},
+    Mutex,
+};
+
 use tracing::{
     callsite::{Callsite, Identifier},
     field::{FieldSet, Value},
@@ -143,6 +148,46 @@ pub extern "C" fn tracing_init(
     }))
 }
 
+#[no_mangle]
+pub extern "C" fn tracing_init_test(
+    #[cfg(not(target_os = "windows"))] log_path: *const u8,
+    #[cfg(target_os = "windows")] log_path: *const u16,
+    log_path_len: usize,
+    initial_filter: *const c_char,
+) -> *mut TracingHandle {
+    let initial_filter = unsafe { CStr::from_ptr(initial_filter) }
+        .to_str()
+        .expect("initial filter should be a valid string");
+
+    let log_path = unsafe { slice::from_raw_parts(log_path, log_path_len) };
+
+    #[cfg(not(target_os = "windows"))]
+    let log_path = OsStr::from_bytes(log_path);
+
+    #[cfg(target_os = "windows")]
+    let log_path = OsString::from_wide(log_path);
+
+    let log_path = Path::new(&log_path);
+
+    let file = File::create(log_path).expect("can create log file for test");
+
+    let file_logger = tracing_subscriber::fmt::layer()
+        .with_writer(Mutex::new(file))
+        .without_time();
+
+    let (filter, reload_handle) = reload::Layer::new(EnvFilter::from(initial_filter));
+
+    tracing_subscriber::registry()
+        .with(file_logger)
+        .with(filter)
+        .init();
+
+    Box::into_raw(Box::new(TracingHandle {
+        _file_guard: None,
+        reload_handle: Box::new(reload_handle),
+    }))
+}
+
 #[no_mangle]
 pub extern "C" fn tracing_free(handle: *mut TracingHandle) {
     drop(unsafe { Box::from_raw(handle) });