Deprecate old logging macros from application code (#4039)

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).
 
+## Unreleased
+
+### Deprecated
+
+- The previous logging macros (`LOG_INFO_FMT`, `LOG_DEBUG_FMT` etc) have been deprecated, and should no longer be used by application code. Replace with the `CCF_APP_*` equivalent.
+
 ## [3.0.0-dev1]
 
 ### Added

CMakeLists.txt

@@ -72,6 +72,10 @@ option(BUILD_UNIT_TESTS "Build unit tests" ON)
 option(TLS_TEST "TLS Test using https://github.com/drwetter/testssl.sh" OFF)
 option(BUILD_TPCC "Build TPPC sample app and clients" OFF)
 
+# Allow framework code to use LOG_*_FMT macros. These will be removed from
+# public headers in future
+add_compile_definitions(CCF_LOGGER_NO_DEPRECATE)
+
 # Build common library for CCF enclaves
 add_custom_target(ccf ALL)
 
@@ -231,11 +235,8 @@ add_custom_target(
   signing_key ALL DEPENDS ${CMAKE_CURRENT_BINARY_DIR}/signing_key.pem
 )
 
-# Add Logging app.
-add_subdirectory(${CCF_DIR}/samples/apps/logging)
-
-# Add NoBuiltins app
-add_subdirectory(${CCF_DIR}/samples/apps/nobuiltins)
+# Add sample apps
+add_subdirectory(${CCF_DIR}/samples)
 
 if(BUILD_TESTS)
   enable_testing()

include/ccf/ds/logger.h

@@ -38,7 +38,7 @@ namespace logger
 
   static constexpr long int ns_per_s = 1'000'000'000;
 
-  static constexpr auto preamble_length = 44u;
+  static constexpr auto preamble_length = 45u;
 
   struct LogLine
   {
@@ -347,25 +347,42 @@ namespace logger
 #define CCF_LOG_FMT_2(s, ...) fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
 #define CCF_LOG_FMT(LVL, TAG) CCF_LOG_OUT(LVL, TAG) << CCF_LOG_FMT_2
 
+  enum class macro
+  {
+    LOG_TRACE_FMT [[deprecated("Use CCF_APP_TRACE instead")]],
+    LOG_DEBUG_FMT [[deprecated("Use CCF_APP_DEBUG instead")]],
+    LOG_INFO_FMT [[deprecated("Use CCF_APP_INFO instead")]],
+    LOG_FAIL_FMT [[deprecated("Use CCF_APP_FAIL instead")]],
+    LOG_FATAL_FMT [[deprecated("Use CCF_APP_FATAL instead")]],
+  };
+
+#ifndef CCF_LOGGER_NO_DEPRECATE
+#  define CCF_LOGGER_DEPRECATE(MACRO) logger::macro::MACRO;
+#else
+#  define CCF_LOGGER_DEPRECATE(MACRO)
+#endif
+
 #ifdef VERBOSE_LOGGING
-#  define LOG_TRACE_FMT CCF_LOG_FMT(TRACE, "")
-#  define LOG_DEBUG_FMT CCF_LOG_FMT(DEBUG, "")
+#  define LOG_TRACE_FMT \
+    CCF_LOGGER_DEPRECATE(LOG_TRACE_FMT) CCF_LOG_FMT(TRACE, "")
+#  define LOG_DEBUG_FMT \
+    CCF_LOGGER_DEPRECATE(LOG_DEBUG_FMT) CCF_LOG_FMT(DEBUG, "")
 
 #  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)
-#  define LOG_TRACE_FMT(...) ((void)0)
-#  define LOG_DEBUG_FMT(...) ((void)0)
+#  define LOG_TRACE_FMT(...) CCF_LOGGER_DEPRECATE(LOG_TRACE_FMT)((void)0)
+#  define LOG_DEBUG_FMT(...) CCF_LOGGER_DEPRECATE(LOG_DEBUG_FMT)((void)0)
 
 #  define CCF_APP_TRACE(...) ((void)0)
 #  define CCF_APP_DEBUG(...) ((void)0)
 #endif
 
-#define LOG_INFO_FMT CCF_LOG_FMT(INFO, "")
-#define LOG_FAIL_FMT CCF_LOG_FMT(FAIL, "")
-#define LOG_FATAL_FMT CCF_LOG_FMT(FATAL, "")
+#define LOG_INFO_FMT CCF_LOGGER_DEPRECATE(LOG_INFO_FMT) CCF_LOG_FMT(INFO, "")
+#define LOG_FAIL_FMT CCF_LOGGER_DEPRECATE(LOG_FAIL_FMT) CCF_LOG_FMT(FAIL, "")
+#define LOG_FATAL_FMT CCF_LOGGER_DEPRECATE(LOG_FATAL_FMT) CCF_LOG_FMT(FATAL, "")
 
 #define CCF_APP_INFO CCF_LOG_FMT(INFO, "app")
 #define CCF_APP_FAIL CCF_LOG_FMT(FAIL, "app")

include/ccf/endpoint_registry.h

@@ -156,7 +156,7 @@ namespace ccf::endpoints
      * ccf::EndpointDefinition::authn_policies
      * @return The new Endpoint for further modification
      */
-    Endpoint make_endpoint(
+    virtual Endpoint make_endpoint(
       const std::string& method,
       RESTVerb verb,
       const EndpointFunction& f,
@@ -164,7 +164,7 @@ namespace ccf::endpoints
 
     /** Create a read-only endpoint.
      */
-    Endpoint make_read_only_endpoint(
+    virtual Endpoint make_read_only_endpoint(
       const std::string& method,
       RESTVerb verb,
       const ReadOnlyEndpointFunction& f,
@@ -175,7 +175,7 @@ namespace ccf::endpoints
      * Commands are endpoints which do not read or write from the KV. See
      * make_endpoint().
      */
-    Endpoint make_command_endpoint(
+    virtual Endpoint make_command_endpoint(
       const std::string& method,
       RESTVerb verb,
       const CommandEndpointFunction& f,

samples/CMakeLists.txt

@@ -0,0 +1,8 @@
+# Ensure sample apps are built as external apps, with old logging macros unavailable
+remove_definitions(-DCCF_LOGGER_NO_DEPRECATE)
+
+# Add Logging app
+add_subdirectory(${CMAKE_CURRENT_LIST_DIR}/apps/logging)
+
+# Add NoBuiltins app
+add_subdirectory(${CMAKE_CURRENT_LIST_DIR}/apps/nobuiltins)

samples/apps/logging/logging.cpp

@@ -211,6 +211,24 @@ namespace loggingapp
                                  PUBLIC_RECORDS;
     }
 
+    // Wrap all endpoints with trace logging of their invocation
+    ccf::endpoints::Endpoint make_endpoint(
+      const std::string& method,
+      ccf::RESTVerb verb,
+      const ccf::endpoints::EndpointFunction& f,
+      const ccf::AuthnPolicies& ap) override
+    {
+      return ccf::UserEndpointRegistry::make_endpoint(
+        method,
+        verb,
+        [method, verb, f](ccf::endpoints::EndpointContext& args) {
+          CCF_APP_TRACE("BEGIN {} {}", verb.c_str(), method);
+          f(args);
+          CCF_APP_TRACE("END   {} {}", verb.c_str(), method);
+        },
+        ap);
+    }
+
   public:
     LoggerHandlers(ccfapp::AbstractNodeContext& context) :
       ccf::UserEndpointRegistry(context),

samples/apps/nobuiltins/nobuiltins.cpp

@@ -6,8 +6,6 @@
 #include "ccf/ds/json.h"
 #include "ccf/json_handler.h"
 #include "ccf/node_context.h"
-#include "node/rpc/call_types.h"
-#include "node/rpc/serialization.h"
 
 #include <charconv>
 
@@ -59,6 +57,13 @@ namespace nobuiltins
   DECLARE_JSON_TYPE(TimeResponse)
   DECLARE_JSON_REQUIRED_FIELDS(TimeResponse, timestamp)
 
+  struct GetCommit
+  {
+    ccf::TxID transaction_id;
+  };
+  DECLARE_JSON_TYPE(GetCommit)
+  DECLARE_JSON_REQUIRED_FIELDS(GetCommit, transaction_id)
+
   // SNIPPET: registry_inheritance
   class NoBuiltinsRegistry : public ccf::BaseEndpointRegistry
   {
@@ -184,7 +189,7 @@ namespace nobuiltins
       };
       make_endpoint(
         "/api", HTTP_GET, ccf::json_adapter(openapi), ccf::no_auth_required)
-        .set_auto_schema<void, ccf::GetAPI::Out>()
+        .set_auto_schema<void, nlohmann::json>()
         .install();
 
       auto get_commit = [this](auto&, nlohmann::json&&) {
@@ -194,7 +199,7 @@ namespace nobuiltins
 
         if (result == ccf::ApiResult::OK)
         {
-          ccf::GetCommit::Out out;
+          GetCommit out;
           out.transaction_id.view = view;
           out.transaction_id.seqno = seqno;
           return ccf::make_success(out);
@@ -214,7 +219,7 @@ namespace nobuiltins
         HTTP_GET,
         ccf::json_command_adapter(get_commit),
         ccf::no_auth_required)
-        .set_auto_schema<void, ccf::GetCommit::Out>()
+        .set_auto_schema<void, GetCommit>()
         .install();
 
       auto get_txid = [this](auto& ctx, nlohmann::json&&) {

src/ds/test/logger.cpp

@@ -23,7 +23,7 @@ public:
 using TestTextLogger = TestLogger<logger::TextConsoleLogger>;
 using TestJsonLogger = TestLogger<logger::JsonConsoleLogger>;
 
-TEST_CASE("Standard logging macros")
+TEST_CASE("Framework logging macros")
 {
   std::vector<std::string> logs;
 
@@ -72,6 +72,58 @@ TEST_CASE("Standard logging macros")
   logger::config::loggers().clear();
 }
 
+TEST_CASE("Application logging macros")
+{
+  std::vector<std::string> logs;
+
+  logger::config::loggers().emplace_back(
+    std::make_unique<TestTextLogger>(logs));
+
+  {
+    REQUIRE(logs.empty());
+    CCF_APP_INFO("Hello A");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("info") != std::string::npos);
+    REQUIRE(log.find("[app]") != std::string::npos);
+    REQUIRE(log.find("logger.cpp") != std::string::npos);
+    REQUIRE(log.find("Hello A") != std::string::npos);
+
+    logs.clear();
+  }
+
+  {
+    REQUIRE(logs.empty());
+    CCF_APP_FAIL("Hello B");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("fail") != std::string::npos);
+    REQUIRE(log.find("[app]") != std::string::npos);
+    REQUIRE(log.find("logger.cpp") != std::string::npos);
+    REQUIRE(log.find("Hello B") != std::string::npos);
+
+    logs.clear();
+  }
+
+  {
+    REQUIRE(logs.empty());
+    REQUIRE_THROWS(CCF_APP_FATAL("Hello C"));
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("fatal") != std::string::npos);
+    REQUIRE(log.find("[app]") != std::string::npos);
+    REQUIRE(log.find("logger.cpp") != std::string::npos);
+    REQUIRE(log.find("Hello C") != std::string::npos);
+
+    logs.clear();
+  }
+
+  logger::config::loggers().clear();
+}
+
 constexpr auto custom_tag = "my tag";
 #define CUSTOM_LOG CCF_LOG_FMT(INFO, custom_tag)