Make CCF stderr fatal-only and consistent

CHANGELOG.md

@@ -14,6 +14,7 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/) a
 
 ### Changed
 
+- CCF-owned fatal termination paths now all emit flushed diagnostics to stderr, while recoverable logs and fatal-severity-only entries remain on stdout. See [Logging](doc/build_apps/logging.rst) (#8690).
 - CCF consensus protocol tracing now uses `ccf.cft` for the Fluentd tag (#8657).
 - `observability.fluentd` now accepts an array of independent sinks, and configurable delivery behaviour.
   See [Observability Export](doc/operations/configuration.rst#observability-export) for more details (#8666).

doc/build_apps/logging.rst

@@ -1,7 +1,14 @@
 Logging
 =======
 
-.. note:: The experimental :doc:`Rust SDK <rust_api>` does not expose this logging API. Output from Rust's ``print!`` and ``eprint!`` macros is visible to the host, so it must not contain confidential data.
+CCF-generated log records are written to stdout at every severity, including ``fail`` and ``fatal``.
+The ``fatal`` severity label alone does not mean that the node will terminate or that the message will be written to stderr.
+CCF writes a flushed diagnostic to stderr when a fatal path terminates the node or process; recoverable errors and ordinary log records remain on stdout.
+
+This contract covers diagnostics produced by CCF itself.
+Applications and dependencies may write directly to stderr, and runtime-generated diagnostics such as assertion failures, uncaught C++ exceptions, or Rust panic hooks may also appear there.
+Those outputs are outside CCF's guarantee and must not contain confidential data.
+The experimental :doc:`Rust SDK <rust_api>` does not expose the CCF logging API, so output from Rust's ``print!`` and ``eprint!`` macros is visible to the host and must not contain confidential data.
 
 To add your own lines to the node's output you should use the ``CCF_APP_*`` macros defined in ``ccf/ds/logger.h``:
 

src/ds/files.h

@@ -3,6 +3,7 @@
 #pragma once
 
 #include "ccf/ds/nonstd.h"
+#include "ds/internal_logger.h"
 
 #include <cerrno>
 #include <cstddef>
@@ -101,7 +102,8 @@ namespace files
       {
         return {};
       }
-      std::cerr << "Could not open file " << file << std::endl;
+      ccf::logger::write_fatal_diagnostic(
+        fmt::format("Could not open file {}", file));
       exit(-1); // NOLINT(concurrency-mt-unsafe)
     }
 
@@ -113,7 +115,8 @@ namespace files
 
     if (!optional && !f)
     {
-      std::cerr << "Could not read file " << file << std::endl;
+      ccf::logger::write_fatal_diagnostic(
+        fmt::format("Could not read file {}", file));
       exit(-1); // NOLINT(concurrency-mt-unsafe)
     }
     return data;

src/ds/internal_logger.h

@@ -4,12 +4,22 @@
 
 #include "ccf/ds/logger.h"
 
+#include <iostream>
+#include <string_view>
+
 // Defines the LOG_*_FMT macros that should be used for logging by
 // framework-internal components. Alternatively, replace with macros which add a
 // system-specific tag.
 
 namespace ccf::logger
 {
+  inline void write_fatal_diagnostic(std::string_view message)
+  {
+    // A single insertion keeps concurrent diagnostics on separate lines, since
+    // std::cerr is synchronised with stdio and each write takes its lock.
+    std::cerr << fmt::format("Fatal error: {}\n", message) << std::flush;
+  }
+
 #define LOG_TRACE_FMT CCF_LOG_FMT(TRACE, "")
 #define LOG_DEBUG_FMT CCF_LOG_FMT(DEBUG, "")
 #define LOG_INFO_FMT CCF_LOG_FMT(INFO, "")

src/ds/test/logger.cpp

@@ -9,8 +9,10 @@
 #include <cstdint>
 #include <ctime>
 #include <doctest/doctest.h>
+#include <iostream>
 #include <memory>
 #include <optional>
+#include <sstream>
 #include <thread>
 #include <utility>
 #include <vector>
@@ -94,6 +96,54 @@ class ScopedLoggerConfig
   }
 };
 
+class ScopedCerrCapture
+{
+  std::ostringstream captured;
+  std::streambuf* previous = std::cerr.rdbuf(captured.rdbuf());
+
+public:
+  ScopedCerrCapture() = default;
+  ScopedCerrCapture(const ScopedCerrCapture&) = delete;
+  ScopedCerrCapture& operator=(const ScopedCerrCapture&) = delete;
+
+  ~ScopedCerrCapture()
+  {
+    std::cerr.rdbuf(previous);
+  }
+
+  std::string str() const
+  {
+    return captured.str();
+  }
+};
+
+class ScopedCoutCapture
+{
+  std::ostringstream captured;
+  std::streambuf* previous = std::cout.rdbuf(captured.rdbuf());
+
+public:
+  ScopedCoutCapture() = default;
+  ScopedCoutCapture(const ScopedCoutCapture&) = delete;
+  ScopedCoutCapture& operator=(const ScopedCoutCapture&) = delete;
+
+  ~ScopedCoutCapture()
+  {
+    std::cout.rdbuf(previous);
+  }
+
+  void clear()
+  {
+    captured.str("");
+    captured.clear();
+  }
+
+  std::string str() const
+  {
+    return captured.str();
+  }
+};
+
 #ifndef CCF_CFT_TRACING
 TEST_CASE("Logger timestamp retains microsecond precision")
 {
@@ -257,6 +307,38 @@ TEST_CASE("Framework logging macros")
   ccf::logger::config::loggers().clear();
 }
 
+TEST_CASE("Only explicit fatal diagnostics write to stderr")
+{
+  const ScopedLoggerConfig restore_config;
+  ccf::logger::config::level() = ccf::LoggerLevel::TRACE;
+  ScopedCoutCapture captured_out;
+  ScopedCerrCapture captured_err;
+
+  const auto check_console_logger = [&](auto logger) {
+    auto& loggers = ccf::logger::config::loggers();
+    loggers.clear();
+    loggers.emplace_back(std::move(logger));
+    captured_out.clear();
+
+    LOG_INFO_FMT("Recoverable information");
+    LOG_FAIL_FMT("Recoverable failure");
+    LOG_FATAL_FMT("Fatal severity label without termination");
+
+    CHECK(captured_err.str().empty());
+    const auto output = captured_out.str();
+    CHECK(output.contains("Recoverable information"));
+    CHECK(output.contains("Recoverable failure"));
+    CHECK(output.contains("Fatal severity label without termination"));
+  };
+
+  check_console_logger(std::make_unique<ccf::logger::TextConsoleLogger>());
+  check_console_logger(std::make_unique<ccf::logger::JsonConsoleLogger>());
+  captured_out.clear();
+  ccf::logger::write_fatal_diagnostic("Node terminated");
+  CHECK(captured_out.str().empty());
+  CHECK(captured_err.str() == "Fatal error: Node terminated\n");
+}
+
 TEST_CASE("Application logging macros")
 {
   std::vector<std::string> logs;

src/host/run.cpp

@@ -246,6 +246,8 @@ namespace ccf
       catch (const std::exception& e)
       {
         LOG_FAIL_FMT("Exception in ccf::run: {}", e.what());
+        ccf::logger::write_fatal_diagnostic(
+          "Enclave runtime thread failed; see stdout logs for details");
 
         throw;
       }
@@ -416,8 +418,10 @@ namespace ccf
       }
       catch (const std::exception& e)
       {
-        LOG_FATAL_FMT(
+        const auto message = fmt::format(
           "Invalid address for RPC interface {}: {}. Exiting.", name, e.what());
+        LOG_FATAL_FMT("{}", message);
+        ccf::logger::write_fatal_diagnostic(message);
         return static_cast<int>(CLI::ExitCodes::ValidationError);
       }
     }
@@ -434,9 +438,11 @@ namespace ccf
         files::exists(config.ledger.directory) &&
         !fs::is_empty(config.ledger.directory))
       {
-        LOG_FATAL_FMT(
+        const auto message = fmt::format(
           "On start, ledger directory should not exist or be empty ({})",
           config.ledger.directory);
+        LOG_FATAL_FMT("{}", message);
+        ccf::logger::write_fatal_diagnostic(message);
         return static_cast<int>(CLI::ExitCodes::ValidationError);
       }
 
@@ -447,10 +453,12 @@ namespace ccf
           files::exists(readonly_ledger_directory) &&
           !fs::is_empty(readonly_ledger_directory))
         {
-          LOG_FATAL_FMT(
+          const auto message = fmt::format(
             "On start, read-only ledger directories should not exist or be "
             "empty ({})",
             readonly_ledger_directory);
+          LOG_FATAL_FMT("{}", message);
+          ccf::logger::write_fatal_diagnostic(message);
           return static_cast<int>(CLI::ExitCodes::ValidationError);
         }
       }
@@ -459,7 +467,9 @@ namespace ccf
       config.command.type != StartType::Join &&
       config.command.type != StartType::Recover)
     {
-      LOG_FATAL_FMT("Start command should be start|join|recover. Exiting.");
+      constexpr auto message = "Start command should be start|join|recover.";
+      LOG_FATAL_FMT("{} Exiting.", message);
+      ccf::logger::write_fatal_diagnostic(message);
       return static_cast<int>(CLI::ExitCodes::ValidationError);
     }
 
@@ -471,6 +481,8 @@ namespace ccf
     {
       LOG_FAIL_FMT(
         "2TX reconfiguration is experimental, disabled in release mode");
+      ccf::logger::write_fatal_diagnostic(
+        "2TX reconfiguration is disabled in release mode");
       return CreateNodeStatus::ReconfigurationMethodNotSupported;
     }
 
@@ -525,11 +537,21 @@ namespace ccf
       // Startup diagnostics are safe here: no runtime thread has executed,
       // and locally generated secrets will be discarded.
       LOG_FAIL_FMT("Error starting node: {}", e.what());
+      ccf::logger::write_fatal_diagnostic(
+        "Node startup failed; see stdout logs for details");
       return failure_status;
     }
 
     run_enclave_threads(config, *enclave);
-    runtime_control->throw_if_fatal_error();
+    try
+    {
+      runtime_control->throw_if_fatal_error();
+    }
+    catch (const std::exception& e)
+    {
+      LOG_FAIL_FMT("Exception in ccf::run: {}", e.what());
+      return CreateNodeStatus::InternalError;
+    }
 
     return std::nullopt;
   }
@@ -552,11 +574,13 @@ namespace ccf
 #endif
   }
 
-  int run(int argc, char** argv) // NOLINT(bugprone-exception-escape)
+  // NOLINTNEXTLINE(misc-use-anonymous-namespace)
+  static int run_impl(int argc, char** argv)
   {
     if (signal(SIGPIPE, SIG_IGN) == SIG_ERR)
     {
       LOG_FAIL_FMT("Failed to ignore SIGPIPE");
+      ccf::logger::write_fatal_diagnostic("Failed to ignore SIGPIPE");
       return 1;
     }
 
@@ -703,6 +727,7 @@ namespace ccf
     catch (const std::logic_error& e)
     {
       LOG_FATAL_FMT("{}. Exiting.", e.what());
+      ccf::logger::write_fatal_diagnostic(e.what());
       return static_cast<int>(CLI::ExitCodes::ValidationError);
     }
 
@@ -769,6 +794,7 @@ namespace ccf
     catch (const std::logic_error& e)
     {
       LOG_FATAL_FMT("{}. Exiting.", e.what());
+      ccf::logger::write_fatal_diagnostic(e.what());
       return static_cast<int>(CLI::ExitCodes::ValidationError);
     }
 
@@ -777,6 +803,8 @@ namespace ccf
     {
       LOG_FATAL_FMT(
         "PID file {} already exists. Exiting.", pid_file_path.string());
+      ccf::logger::write_fatal_diagnostic(
+        fmt::format("PID file {} already exists", pid_file_path.string()));
       return static_cast<int>(CLI::ExitCodes::FileError);
     }
 
@@ -797,6 +825,9 @@ namespace ccf
     catch (const std::exception& e)
     {
       LOG_FAIL_FMT("Exception in ccf::run: {}", e.what());
+      ccf::logger::write_fatal_diagnostic(
+        "Unhandled exception while running the node; see stdout logs for "
+        "details");
       inner_ret = CreateNodeStatus::InternalError;
     }
 
@@ -821,6 +852,8 @@ namespace ccf
     {
       LOG_FAIL_FMT(
         "Failed to close uv loop cleanly: {}", uv_err_name(loop_close_rc));
+      ccf::logger::write_fatal_diagnostic(fmt::format(
+        "Failed to close the host event loop: {}", uv_err_name(loop_close_rc)));
       // walk loop to diagnose unclosed handles
       auto cb = [](uv_handle_t* handle, void* arg) {
         (void)arg;
@@ -835,4 +868,25 @@ namespace ccf
 
     return inner_ret.value_or(loop_close_rc);
   }
+
+  int run(int argc, char** argv) // NOLINT(bugprone-exception-escape)
+  {
+    try
+    {
+      return run_impl(argc, argv);
+    }
+    catch (const std::exception& e)
+    {
+      LOG_FAIL_FMT("Unhandled exception in ccf::run: {}", e.what());
+      ccf::logger::write_fatal_diagnostic(
+        fmt::format("Unhandled exception in CCF node: {}", e.what()));
+      return CreateNodeStatus::InternalError;
+    }
+    catch (...)
+    {
+      LOG_FAIL_FMT("Unhandled exception in ccf::run");
+      ccf::logger::write_fatal_diagnostic("Unhandled exception in CCF node");
+      return CreateNodeStatus::InternalError;
+    }
+  }
 }

src/host/runtime_control.h

@@ -7,7 +7,6 @@
 #include "uv/proxy.h"
 
 #include <functional>
-#include <iostream>
 #include <mutex>
 #include <optional>
 #include <stdexcept>
@@ -76,7 +75,7 @@ namespace asynchost
         if (!fatal_error.has_value())
         {
           fatal_error = message;
-          std::cerr << message << std::endl << std::flush;
+          ccf::logger::write_fatal_diagnostic(message);
         }
       }
 

src/host/socket.h

@@ -75,13 +75,17 @@ namespace asynchost
     /// Failure loggers for when things go wrong, fataly
     virtual void on_resolve_failed()
     {
-      LOG_FATAL_FMT("{} {} resolve failed", conn_name, name);
+      const auto message = fmt::format("{} {} resolve failed", conn_name, name);
+      LOG_FATAL_FMT("{}", message);
+      ccf::logger::write_fatal_diagnostic(message);
       abort();
     }
 
     virtual void on_listen_failed()
     {
-      LOG_FATAL_FMT("{} {} listen failed", conn_name, name);
+      const auto message = fmt::format("{} {} listen failed", conn_name, name);
+      LOG_FATAL_FMT("{}", message);
+      ccf::logger::write_fatal_diagnostic(message);
       abort();
     }
   };