[release/4.x] Cherry pick: Permit Trace+Debug logging in all non-SGX builds (#5375)

CHANGELOG.md

@@ -5,6 +5,12 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
+## [4.0.5]
+
+[4.0.5]: https://github.com/microsoft/CCF/releases/tag/ccf-4.0.5
+
+- Debug logging is now available in non-SGX builds by default, and controlled by a run-time CLI argument (`--enclave-log-level`). On SGX this remains a build-time decision (#5375).
+
 ## [4.0.4]
 
 [4.0.4]: https://github.com/microsoft/CCF/releases/tag/ccf-4.0.4

CMakeLists.txt

@@ -74,11 +74,25 @@ else()
   unset(NODES)
 endif()
 
-option(VERBOSE_LOGGING "Enable verbose, unsafe logging of enclave code" OFF)
-set(TEST_HOST_LOGGING_LEVEL "info")
+option(
+  VERBOSE_LOGGING
+  "Enable verbose, potentially unsafe logging of enclave code. Affects logging level passed at run-time to end-to-end-tests, and compile-time max verbosity on SGX."
+  OFF
+)
+set(TEST_LOGGING_LEVEL "info")
 if(VERBOSE_LOGGING)
-  set(TEST_HOST_LOGGING_LEVEL "trace")
-  add_compile_definitions(VERBOSE_LOGGING)
+  set(TEST_LOGGING_LEVEL "trace")
+endif()
+
+# NB: Toggling VERBOSE_LOGGING on non-SGX platforms causes no build change, so
+# should not cause a rebuild
+if(COMPILE_TARGET STREQUAL "sgx" AND NOT VERBOSE_LOGGING)
+  # Disable verbose, unsafe logging of enclave code. On some platforms it is
+  # safe to build with this logging enabled, and then it can be disabled at
+  # run-time. However this run-time control is not possible on SGX, so to ensure
+  # a given MRENCLAVE cannot leak via debug logging it must be removed at
+  # build-time, with this option.
+  add_compile_definitions(CCF_DISABLE_VERBOSE_LOGGING)
 endif()
 
 option(USE_NULL_ENCRYPTOR "Turn off encryption of ledger updates - debug only"
@@ -275,9 +289,6 @@ target_compile_options(
 )
 target_include_directories(cchost PRIVATE ${CCF_GENERATED_DIR})
 
-# Host is always built with verbose logging enabled, regardless of CMake option
-target_compile_definitions(cchost PRIVATE VERBOSE_LOGGING)
-
 if(COMPILE_TARGET STREQUAL "sgx")
   target_compile_definitions(cchost PUBLIC PLATFORM_SGX)
 elseif(COMPILE_TARGET STREQUAL "snp")
@@ -434,8 +445,9 @@ set(CCF_NETWORK_TEST_DEFAULT_CONSTITUTION
     --constitution
     ${CCF_DIR}/samples/constitutions/default/apply.js
 )
-set(CCF_NETWORK_TEST_ARGS --host-log-level ${TEST_HOST_LOGGING_LEVEL}
-                          --worker-threads ${WORKER_THREADS}
+set(CCF_NETWORK_TEST_ARGS
+    --host-log-level ${TEST_LOGGING_LEVEL} --enclave-log-level
+    ${TEST_LOGGING_LEVEL} --worker-threads ${WORKER_THREADS}
 )
 
 if(COMPILE_TARGET STREQUAL "sgx")
@@ -851,7 +863,6 @@ if(BUILD_TESTS)
       logger_json_test
       ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/logger_json_test.cpp
     )
-    target_compile_definitions(logger_json_test PUBLIC VERBOSE_LOGGING)
 
     add_unit_test(
       kv_test
@@ -1108,7 +1119,6 @@ if(BUILD_TESTS)
     # Picobench benchmarks
     add_picobench(map_bench SRCS src/ds/test/map_bench.cpp)
     add_picobench(logger_bench SRCS src/ds/test/logger_bench.cpp)
-    target_compile_definitions(logger_bench PUBLIC VERBOSE_LOGGING)
     add_picobench(json_bench SRCS src/ds/test/json_bench.cpp)
     add_picobench(ring_buffer_bench SRCS src/ds/test/ring_buffer_bench.cpp)
     add_picobench(

cmake/version.cmake

@@ -5,7 +5,11 @@ unset(CCF_VERSION)
 unset(CCF_RELEASE_VERSION)
 unset(CCF_VERSION_SUFFIX)
 
-option(UNSAFE_VERSION "Produce build with unsafe logging levels" OFF)
+option(
+  UNSAFE_VERSION
+  "Append unsafe suffix to project and targets. Should be used on platforms where log level is determined at build-time, to distinguish builds which are unsafely verbose."
+  OFF
+)
 
 set(CCF_PROJECT "ccf_${COMPILE_TARGET}")
 if(UNSAFE_VERSION)

doc/build_apps/logging.rst

@@ -28,7 +28,7 @@ These logging functions do several things:
 - Prefix formatted metadata. The produced log line will include a timestamp, the name and line number where the line was produced, and an ``[app]`` tag
 - Write without an ECALL. The final write must be handled by the host, so writing directly from the enclave would require an expensive ECALL. Instead these macros will queue writes to a ringbuffer for the host to process, so diagnostic logging should not cause significant performance drops
 
-By default, the ``CCF_APP_TRACE`` and ``CCF_APP_DEBUG`` macros are compiled out, to avoid leaking confidential information during execution. To enable these, define ``VERBOSE_LOGGING`` before including ``logger.h`` in your application code. The unsafe build variants of CCF include verbose logging of the framework itself, but this can be used independently of verbose logging in the application code.
+The most-verbose lines which are emitted may be restricted at build-time, if required for security on that platform. On SGX, the ``CCF_APP_TRACE`` and ``CCF_APP_DEBUG`` macros are disabled at compile-time, to avoid leaking confidential information during execution. To enable these, define ``VERBOSE_LOGGING`` before including ``logger.h`` in your application code. The unsafe build variants of CCF include verbose logging of the framework itself, but this can be used independently of verbose logging in the application code.
 
 .. note:: The app's logging entries will be interleaved (line-by-line) with the framework's logging messages. Filter for entries containing ``[app]`` to extract only application log lines.
 

doc/contribute/build_ccf.rst

@@ -51,7 +51,6 @@ The most common build switches include:
 * **BUILD_TESTS**: Boolean. Build all tests for CCF. Default to ON.
 * **SAN**: Boolean. Build unit tests with Address and Undefined behaviour sanitizers enabled. Default to OFF.
 * **COMPILE_TARGET**: String. Target compilation platform. Defaults to ``sgx``. Supported values are ``sgx``, ``snp``, or ``virtual``.
-* **VERBOSE_LOGGING**: Boolean. Enable all logging levels. Default to OFF.
 
 Run Tests
 ---------

doc/host_config_schema/cchost_config.json

@@ -534,7 +534,7 @@
           "type": "string",
           "enum": ["Trace", "Debug", "Info", "Fail", "Fatal"],
           "default": "Info",
-          "description": "Logging level for the untrusted host. Note: while it is possible to set the host log level at startup, it is deliberately not possible to change the log level of the enclave without rebuilding it and changing its code identity"
+          "description": "Logging level for the untrusted host."
         },
         "format": {
           "type": "string",

edl/ccf.edl

@@ -25,6 +25,7 @@ enclave {
             size_t enclave_version_size,
             [out] size_t* enclave_version_len,
             StartType start_type,
+            LoggerLevel enclave_log_level,
             size_t num_worker_thread,
             [user_check] void* time_location,
         );

include/ccf/ds/logger.h

@@ -3,6 +3,7 @@
 #pragma once
 
 #include "ccf/ds/enum_formatter.h"
+#include "ccf/ds/logger_level.h"
 #include "ccf/ds/thread_ids.h"
 
 #define FMT_HEADER_ONLY
@@ -16,22 +17,18 @@
 
 namespace logger
 {
-  enum Level
-  {
-    TRACE,
-    DEBUG, // events useful for debugging
-    INFO, // important events that should be logged even in release mode
-    FAIL, // survivable failures that should always be logged
-    FATAL, // fatal errors that may be non-recoverable
-    MAX_LOG_LEVEL
-  };
-
-  static constexpr Level MOST_VERBOSE = static_cast<Level>(0);
+  static constexpr LoggerLevel MOST_VERBOSE =
+#ifdef CCF_DISABLE_VERBOSE_LOGGING
+    LoggerLevel::INFO
+#else
+    LoggerLevel::TRACE
+#endif
+    ;
 
   static constexpr const char* LevelNames[] = {
     "trace", "debug", "info", "fail", "fatal"};
 
-  static constexpr const char* to_string(Level l)
+  static constexpr const char* to_string(LoggerLevel l)
   {
     return LevelNames[static_cast<int>(l)];
   }
@@ -48,7 +45,7 @@ namespace logger
   {
   public:
     friend struct Out;
-    Level log_level;
+    LoggerLevel log_level;
     std::string tag;
     std::string file_name;
     size_t line_number;
@@ -58,7 +55,7 @@ namespace logger
     std::string msg;
 
     LogLine(
-      Level level_,
+      LoggerLevel level_,
       std::string_view tag_,
       std::string_view file_name_,
       size_t line_number_,
@@ -295,14 +292,14 @@ namespace logger
     }
 #endif
 
-    static inline Level& level()
+    static inline LoggerLevel& level()
     {
-      static Level the_level = MOST_VERBOSE;
+      static LoggerLevel the_level = MOST_VERBOSE;
 
       return the_level;
     }
 
-    static inline bool ok(Level l)
+    static inline bool ok(LoggerLevel l)
     {
       return l >= level();
     }
@@ -327,7 +324,7 @@ namespace logger
       }
 
 #ifndef INSIDE_ENCLAVE
-      if (line.log_level == Level::FATAL)
+      if (line.log_level == LoggerLevel::FATAL)
       {
         throw std::logic_error("Fatal: " + format_to_text(line));
       }
@@ -358,8 +355,9 @@ namespace logger
 // This allows:
 // CCF_LOG_OUT(DEBUG, "foo") << "this " << "msg";
 #define CCF_LOG_OUT(LVL, TAG) \
-  logger::config::ok(logger::LVL) && \
-    logger::Out() == logger::LogLine(logger::LVL, TAG, __FILE__, __LINE__)
+  logger::config::ok(LoggerLevel::LVL) && \
+    logger::Out() == \
+      logger::LogLine(LoggerLevel::LVL, TAG, __FILE__, __LINE__)
 
 // To avoid repeating the (s, ...) args for every macro, we cheat with a curried
 // macro here by ending the macro with another macro name, which then accepts
@@ -382,7 +380,7 @@ namespace logger
 #  define CCF_LOGGER_DEPRECATE(MACRO)
 #endif
 
-#ifdef VERBOSE_LOGGING
+#ifndef CCF_DISABLE_VERBOSE_LOGGING
 #  define LOG_TRACE_FMT \
     CCF_LOGGER_DEPRECATE(LOG_TRACE_FMT) CCF_LOG_FMT(TRACE, "")
 #  define LOG_DEBUG_FMT \
@@ -391,8 +389,8 @@ namespace logger
 #  define CCF_APP_TRACE CCF_LOG_FMT(TRACE, "app")
 #  define CCF_APP_DEBUG CCF_LOG_FMT(DEBUG, "app")
 #else
-// Without compile-time VERBOSE_LOGGING option, these logging macros are
-// compile-time nops (and cannot be enabled by accident or malice)
+// With verbose logging disabled by compile-time definition, these logging
+// macros are compile-time nops (and cannot be enabled by accident or malice)
 #  define LOG_TRACE_FMT(...) CCF_LOGGER_DEPRECATE(LOG_TRACE_FMT)((void)0)
 #  define LOG_DEBUG_FMT(...) CCF_LOGGER_DEPRECATE(LOG_DEBUG_FMT)((void)0)
 

include/ccf/ds/logger_level.h

@@ -0,0 +1,13 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the Apache 2.0 License.
+#pragma once
+
+enum LoggerLevel
+{
+  TRACE,
+  DEBUG, // events useful for debugging
+  INFO, // important events that should be logged even in release mode
+  FAIL, // survivable failures that should always be logged
+  FATAL, // fatal errors that may be non-recoverable
+  MAX_LOG_LEVEL
+};

scripts/scan-build.sh

@@ -9,8 +9,5 @@ export CCC_CXX="clang++-$CLANG_VERSION"
 
 SCAN="scan-build-$CLANG_VERSION --exclude 3rdparty --exclude test"
 
-# VERBOSE_LOGGING=ON is important, without it scan-build will report values as unused
-# everywhere we compile out the logging statements that would otherwise read them
-$SCAN cmake -GNinja -DCOMPILE_TARGET=virtual -DVERBOSE_LOGGING=ON -DCMAKE_BUILD_TYPE=Debug ..
 # Fails on the current build of clang, because of false positives in doctest, WIP
 $SCAN ninja || true

src/common/configuration.h

@@ -22,16 +22,13 @@
 #include <string>
 #include <vector>
 
-namespace logger
-{
-  DECLARE_JSON_ENUM(
-    Level,
-    {{Level::TRACE, "Trace"},
-     {Level::DEBUG, "Debug"},
-     {Level::INFO, "Info"},
-     {Level::FAIL, "Fail"},
-     {Level::FATAL, "Fatal"}});
-}
+DECLARE_JSON_ENUM(
+  LoggerLevel,
+  {{LoggerLevel::TRACE, "Trace"},
+   {LoggerLevel::DEBUG, "Debug"},
+   {LoggerLevel::INFO, "Info"},
+   {LoggerLevel::FAIL, "Fail"},
+   {LoggerLevel::FATAL, "Fatal"}});
 
 DECLARE_JSON_ENUM(
   StartType,

src/common/enclave_interface_types.h

@@ -2,6 +2,8 @@
 // Licensed under the Apache 2.0 License.
 #pragma once
 
+#include "ccf/ds/logger_level.h"
+
 enum CreateNodeStatus
 {
   /** Call was successful and the node was successfully created */

src/consensus/aft/test/driver.cpp

@@ -44,7 +44,7 @@ int main(int argc, char** argv)
 #else
   logger::config::add_text_console_logger();
 #endif
-  logger::config::level() = logger::DEBUG;
+  logger::config::level() = LoggerLevel::DEBUG;
 
   threading::ThreadMessaging::init(1);
 

src/consensus/aft/test/main.cpp

@@ -769,7 +769,7 @@ DOCTEST_TEST_CASE("Recv append entries logic" * doctest::test_suite("multiple"))
 
 DOCTEST_TEST_CASE("Exceed append entries limit")
 {
-  logger::config::level() = logger::INFO;
+  logger::config::level() = LoggerLevel::INFO;
 
   ccf::NodeId node_id0 = kv::test::PrimaryNodeId;
   ccf::NodeId node_id1 = kv::test::FirstBackupNodeId;

src/ds/test/logger_bench.cpp

@@ -51,7 +51,7 @@ static void log_accepted(picobench::state& s)
 {
   prepare_loggers<LK, Absorb>();
 
-  logger::config::level() = logger::DEBUG;
+  logger::config::level() = LoggerLevel::DEBUG;
   {
     picobench::scope scope(s);
 
@@ -69,7 +69,7 @@ static void log_accepted_fmt(picobench::state& s)
 {
   prepare_loggers<LK, Absorb>();
 
-  logger::config::level() = logger::DEBUG;
+  logger::config::level() = LoggerLevel::DEBUG;
   {
     picobench::scope scope(s);
 
@@ -87,7 +87,7 @@ static void log_rejected(picobench::state& s)
 {
   prepare_loggers<LK, Absorb>();
 
-  logger::config::level() = logger::FAIL;
+  logger::config::level() = LoggerLevel::FAIL;
   {
     picobench::scope scope(s);
 
@@ -105,7 +105,7 @@ static void log_rejected_fmt(picobench::state& s)
 {
   prepare_loggers<LK, Absorb>();
 
-  logger::config::level() = logger::FAIL;
+  logger::config::level() = LoggerLevel::FAIL;
   {
     picobench::scope scope(s);
 

src/ds/test/logger_json_test.cpp

@@ -12,7 +12,7 @@ TEST_CASE("Test custom log format")
   std::string test_log_file = "./test_json_logger.txt";
   remove(test_log_file.c_str());
   logger::config::add_json_console_logger();
-  logger::config::level() = logger::DEBUG;
+  logger::config::level() = LoggerLevel::DEBUG;
   std::string log_msg_dbg = "log_msg_dbg";
   std::string log_msg_fail = "log_msg_fail";
 

src/enclave/interface.h

@@ -38,7 +38,7 @@ DECLARE_RINGBUFFER_MESSAGE_PAYLOAD(
   std::chrono::microseconds::rep,
   std::string,
   size_t,
-  logger::Level,
+  LoggerLevel,
   std::string,
   uint16_t,
   std::string);