Add support for tagged loggers and app-specific logging macros (#4024)

CHANGELOG.md

@@ -20,6 +20,7 @@ and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.
 ### Changed
 
 - Generated OpenAPI now describes whether each endpoint is forwarded (#3935).
+- Application code should now use the `CCF_APP_*` macros rather than `LOG_*_FMT` (eg - `CCF_APP_INFO` replacing `LOG_INFO_FMT`). The new macros will add an `[app]` tag to all lines so they can be easily filtered from framework code (#4024).
 
 ### Fixed
 

CMakeLists.txt

@@ -248,6 +248,10 @@ if(BUILD_TESTS)
       json_schema ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/json_schema.cpp
     )
 
+    add_unit_test(
+      logger_test ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/logger.cpp
+    )
+
     add_unit_test(
       openapi_test ${CMAKE_CURRENT_SOURCE_DIR}/src/ds/test/openapi.cpp
     )

doc/build_apps/example.rst

@@ -56,6 +56,5 @@ The C++ implementation of the Logging application is located in the :ccf_repo:`s
 .. toctree::
    :maxdepth: 2
 
-   logging_cpp
-   logging_rpc_api
-   logging
+   example_cpp
+   example_rpc_api

doc/build_apps/example_cpp.rst

@@ -1,5 +1,5 @@
-Logging (C++)
-=============
+Example app (C++)
+=================
 
 A C++ application exposes itself to CCF by implementing:
 
@@ -9,7 +9,7 @@ A C++ application exposes itself to CCF by implementing:
     :end-before: SNIPPET_END: app_interface
     :dedent:
 
-The Logging application simply has:
+The Logging example application simply has:
 
 .. literalinclude:: ../../samples/apps/logging/logging.cpp
     :language: cpp

doc/build_apps/example_rpc_api.rst

@@ -1,5 +1,5 @@
-Logging RPC API
-===============
+Example app RPC API
+===================
 
 .. openapi:: ../schemas/app_openapi.json
    :examples:

doc/build_apps/index.rst

@@ -3,7 +3,7 @@ Build Apps
 
 This section describes how CCF applications can be developed and deployed to a CCF network.
 
-Applications can be written in JavaScript/TypeScript or C++. An application consists of a collection of endpoints that can be triggered by :term:`Users`. Each endpoint can define an :ref:`build_apps/logging_cpp:API Schema` to validate user requests.
+Applications can be written in JavaScript/TypeScript or C++. An application consists of a collection of endpoints that can be triggered by :term:`Users`. Each endpoint can define an :ref:`build_apps/example_cpp:API Schema` to validate user requests.
 
 These endpoints can read or mutate the state of a unique :ref:`build_apps/kv/index:Key-Value Store` that represents the internal state of the application. Applications define a set of ``Maps`` (see :doc:`kv/kv_how_to`), mapping from a key to a value. When an application endpoint is triggered, the effects on the Store are committed atomically.
 
@@ -95,6 +95,7 @@ These endpoints can read or mutate the state of a unique :ref:`build_apps/kv/ind
     example
     js_app_ts
     js_app_bundle
+    logging
     build_app
     run_app
     auth/index

doc/build_apps/logging.rst

@@ -1,22 +1,33 @@
 Logging
 =======
 
-.. note:: When using CFT consensus, only the primary node will display log messages written by the application.
-
-To add your own lines to the node's output you should use the macros defined in ``ds/logger.h``:
+To add your own lines to the node's output you should use the ``CCF_APP_*`` macros defined in ``ccf/ds/logger.h``:
 
 .. code-block:: cpp
 
     #include "ccf/ds/logger.h"
 
     int x = 5;
-    LOG_INFO_FMT("x is currently {}", x);
+    CCF_APP_INFO("x is currently {}", x);
 
-These macros do several things:
+Applications written in JavaScript and TypeScript can produce similar log lines using standard functions ``console.log``, ``console.info``, ``console.warn``, and ``console.error``:
 
-- Variable substitution. The example above will produce a message of "x is currently 5". See `libfmt <https://fmt.dev/latest/>`_ for more details of the formatting syntax.
-- Declare the severity of the entry. CCF defines 5 levels (``trace``, ``debug``, ``info``, ``fail``, and ``fatal``), and production nodes will generally ignore entries below a specified severity
-- Prefix formatted metadata. The produced log line will include a timestamp and the name and line number where the line was produced
+.. code-block:: js
+
+    x = 5
+    console.info(`x is ${x}`)
+
+Either approach will produce a line in the node's stdout like::
+
+    2022-07-12T12:34:56.626262Z        0   [info ][app] ../src/my_app/my_app.cpp:42    | x is 5
+
+These logging functions do several things:
+
+- Variable substitution. See `libfmt <https://fmt.dev/latest/>`_ for more details of the formatting syntax used in C++
+- Declare the severity of the entry. CCF defines 5 levels (``trace``, ``debug``, ``info``, ``fail``, and ``fatal``), and production nodes will generally ignore entries below ``info``
+- 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
 
-Note that your app's logging entries will be interleaved (line-by-line) with the framework's logging messages, so you may want to prefix your app's entries so they can be more easily distinguished.
+.. 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.
+
+.. note:: Since these logs are produced during execution, they will generally only appear on a single node and not every replica. They may also log information about uncommitted or re-executed transactions, as they are emitted independently of transaction commit.

doc/build_apps/release_policy.rst

@@ -12,7 +12,7 @@ User-facing API
 As defined under :ref:`use_apps/rpc_api:Built-ins`.
 
 These endpoints are expected to be quite stable across releases, but it is difficult for CCF itself to version them because its own versioning scheme may not be in-sync with a given application: release dates and numbers will differ.
-It is instead recommended that applications programmatically disable these endpoints as exposed by CCF now, and replace them with their own as illustrated in :ref:`build_apps/logging_cpp:Default Endpoints`. This is currently only supported for C++ applications.
+It is instead recommended that applications programmatically disable these endpoints as exposed by CCF now, and replace them with their own as illustrated in :ref:`build_apps/example_cpp:Default Endpoints`. This is currently only supported for C++ applications.
 
 CCF exposes its implementation of the user built-in endpoints as a public, versioned C++ API and application code can dispatch to the chosen implementation for each of its own versions.
 

doc/contribute/onboarding.rst

@@ -23,7 +23,7 @@ First complete :doc:`/contribute/build_setup`, and see :doc:`/contribute/build_c
 Walk through a sample application
 ---------------------------------
 
-:doc:`/build_apps/logging_cpp` documents the sample native app under ``/samples/apps/logging`` in the repo.
+:doc:`/build_apps/example_cpp` documents the sample C++ app under ``/samples/apps/logging`` in the repo.
 
 The logging application is simple, but exercises most features of the framework, and is extensively used in the end to end tests.
 

doc/operations/troubleshooting.rst

@@ -86,4 +86,6 @@ There is an option to generate machine-readable logs for monitoring. To enable t
 - ``file`` is the file the log originated from
 - ``number`` is the line number in the file the log originated from
 - ``level`` is the level of the log message [info, debug, trace, fail, fatal]
-- ``msg`` is the log message
+- ``msg`` is the log message
+
+See :ref:`this page <build_apps/logging:Logging>` for steps to add application-specific logging, which will have an additional ``tag`` field set to ``app``.

doc/use_apps/rpc_api.rst

@@ -2,7 +2,7 @@ RPC API
 =======
 
 Application RPCs are exposed under ``/app`` and require authentication with a valid user identity.
-This is a sample of what an application endpoint may look like, as generated by the :ref:`example C++ logging app <build_apps/logging_cpp:Logging (C++)>`.
+This is a sample of what an application endpoint may look like, as generated by the :ref:`example C++ logging app <build_apps/example_cpp>`.
 
 .. openapi:: ../schemas/app_openapi.json
    :examples:

doc/use_apps/verify_tx.rst

@@ -115,7 +115,7 @@ Note that since a receipt is a committment by a service to a transaction, a veri
 Application Claims
 ------------------
 
-CCF allows application code to attach arbitrary claims to a transaction, via the :cpp:func:`enclave::RpcContext::set_claims_digest` API, as illustrated in :ref:`build_apps/logging_cpp:User-Defined Claims in Receipts`.
+CCF allows application code to attach arbitrary claims to a transaction, via the :cpp:func:`enclave::RpcContext::set_claims_digest` API, as illustrated in :ref:`build_apps/example_cpp:User-Defined Claims in Receipts`.
 
 This is useful to allow the reveal and verification of application-related claims offline, ie. without access to the CCF network.
 For example, a logging application may choose to set the digest of the payload being logged as ``claims_digest``.
@@ -129,7 +129,7 @@ Revealing ``hash(claim_a)`` and ``claim_b`` allows verification without revealin
 
 Although CCF takes the approach of concatenating leaf components to keep its implementation simple and format-agnostic, an application may choose to encode its claims in a structured way for convenience, for example as JSON, CBOR etc.
 
-Applications may wish to expose dedicated endpoints, besides CCF's built-in :http:GET:`/node/receipt`, in which they can selectively expand claims, as illustrated in :ref:`build_apps/logging_cpp:User-Defined Claims in Receipts`.
+Applications may wish to expose dedicated endpoints, besides CCF's built-in :http:GET:`/node/receipt`, in which they can selectively expand claims, as illustrated in :ref:`build_apps/example_cpp:User-Defined Claims in Receipts`.
 If some claims must stay confidential, applications should encrypt them rather than merely digest them. They key can be kept in a private table for example, which like the claim will be available through the historical query API. The application logic can then decide whether to decrypt the claim for the caller depending on its authorisation policy.
 
 Commit Evidence

include/ccf/ccf_assert.h

@@ -16,7 +16,8 @@
     { \
       if ((expr) == 0) \
       { \
-        LOG_FAIL_FMT("Assertion failed: {} {}", #expr, (msg)); \
+        CCF_LOG_FMT(FAIL, "assert") \
+        ("Assertion failed: {} {}", #expr, (msg)); \
         throw std::logic_error(msg); \
       } \
     } while (0)

include/ccf/ds/logger.h

@@ -21,8 +21,8 @@ namespace logger
     TRACE,
     DEBUG, // events useful for debugging
     INFO, // important events that should be logged even in release mode
-    FAIL, // important failures that should always be logged
-    FATAL, // fatal errors that lead to a termination of the program/enclave
+    FAIL, // survivable failures that should always be logged
+    FATAL, // fatal errors that may be non-recoverable
     MAX_LOG_LEVEL
   };
 
@@ -31,18 +31,21 @@ namespace logger
   static constexpr const char* LevelNames[] = {
     "trace", "debug", "info", "fail", "fatal"};
 
-  static const char* to_string(Level l)
+  static constexpr const char* to_string(Level l)
   {
     return LevelNames[static_cast<int>(l)];
   }
 
   static constexpr long int ns_per_s = 1'000'000'000;
 
+  static constexpr auto preamble_length = 44u;
+
   struct LogLine
   {
   public:
     friend struct Out;
     Level log_level;
+    std::string tag;
     std::string file_name;
     size_t line_number;
     uint16_t thread_id;
@@ -51,13 +54,15 @@ namespace logger
     std::string msg;
 
     LogLine(
-      Level level,
-      const char* file_name,
-      size_t line_number,
+      Level level_,
+      std::string_view tag_,
+      std::string_view file_name_,
+      size_t line_number_,
       std::optional<uint16_t> thread_id_ = std::nullopt) :
-      log_level(level),
-      file_name(file_name),
-      line_number(line_number)
+      log_level(level_),
+      tag(tag_),
+      file_name(file_name_),
+      line_number(line_number_)
     {
       if (thread_id_.has_value())
       {
@@ -104,9 +109,9 @@ namespace logger
     AbstractLogger() = default;
     virtual ~AbstractLogger() = default;
 
-    virtual void emit(const std::string& s, std::ostream& os = std::cout)
+    virtual void emit(const std::string& s)
     {
-      os << s << std::flush;
+      std::cout << s << std::flush;
     }
 
     virtual void write(
@@ -149,13 +154,12 @@ namespace logger
 
         s = fmt::format(
           "{{\"h_ts\":\"{}\",\"e_ts\":\"{}\",\"thread_id\":\"{}\",\"level\":\"{"
-          "}\",\"file\":\"{}\","
-          "\"number\":\"{}\","
-          "\"msg\":{}}}\n",
+          "}\",\"tag\":\"{}\",\"file\":\"{}\",\"number\":\"{}\",\"msg\":{}}}\n",
           get_timestamp(host_tm, host_ts),
           get_timestamp(enclave_tm, enc_ts),
           ll.thread_id,
           to_string(ll.log_level),
+          ll.tag,
           ll.file_name,
           ll.line_number,
           escaped_msg);
@@ -163,13 +167,12 @@ namespace logger
       else
       {
         s = fmt::format(
-          "{{\"h_ts\":\"{}\",\"thread_id\":\"{}\",\"level\":\"{}\",\"file\":\"{"
-          "}"
-          "\",\"number\":\"{}\","
-          "\"msg\":{}}}\n",
+          "{{\"h_ts\":\"{}\",\"thread_id\":\"{}\",\"level\":\"{}\",\"tag\":\"{}"
+          "\",\"file\":\"{}\",\"number\":\"{}\",\"msg\":{}}}\n",
           get_timestamp(host_tm, host_ts),
           ll.thread_id,
           to_string(ll.log_level),
+          ll.tag,
           ll.file_name,
           ll.line_number,
           escaped_msg);
@@ -189,15 +192,25 @@ namespace logger
     std::tm host_tm;
     ::gmtime_r(&host_ts.tv_sec, &host_tm);
 
-    auto file_line = fmt::format("{}:{}", ll.file_name, ll.line_number);
+    auto file_line = fmt::format("{}:{} ", ll.file_name, ll.line_number);
     auto file_line_data = file_line.data();
 
-    // Truncate to final characters - if too long, advance char*
-    constexpr auto max_len = 36u;
+    // The preamble is the level, then tag, then file line. If the file line is
+    // too long, the final characters are retained.
+    auto preamble = fmt::format(
+                      "[{:<5}]{} ",
+                      to_string(ll.log_level),
+                      (ll.tag.empty() ? "" : fmt::format("[{}]", ll.tag)))
+                      .substr(0, preamble_length);
+    const auto max_file_line_len = preamble_length - preamble.size();
 
     const auto len = file_line.size();
-    if (len > max_len)
-      file_line_data += len - max_len;
+    if (len > max_file_line_len)
+    {
+      file_line_data += len - max_file_line_len;
+    }
+
+    preamble += file_line_data;
 
     if (enclave_offset.has_value())
     {
@@ -205,12 +218,11 @@ namespace logger
       // that the time inside the enclave was 130 milliseconds earlier than
       // the host timestamp printed on the line
       return fmt::format(
-        "{} {:+01.3f} {:<3} [{:<5}] {:<36} | {}\n",
+        "{} {:+01.3f} {:<3} {:<45}| {}\n",
         get_timestamp(host_tm, host_ts),
         enclave_offset.value(),
         ll.thread_id,
-        to_string(ll.log_level),
-        file_line_data,
+        preamble,
         ll.msg);
     }
     else
@@ -218,11 +230,10 @@ namespace logger
       // Padding on the right to align the rest of the message
       // with lines that contain enclave time offsets
       return fmt::format(
-        "{}        {:<3} [{:<5}] {:<36} | {}\n",
+        "{}        {:<3} {:<45}| {}\n",
         get_timestamp(host_tm, host_ts),
         ll.thread_id,
-        to_string(ll.log_level),
-        file_line_data,
+        preamble,
         ll.msg);
     }
   }
@@ -306,14 +317,6 @@ namespace logger
     }
   };
 
-  // The == operator is being used to:
-  // 1. Be a lower precedence than <<, such that using << on the LogLine will
-  // happen before the LogLine is "equalitied" with the Out.
-  // 2. Be a higher precedence than &&, such that the log statement is bound
-  // more tightly than the short-circuiting.
-  // This allows:
-  // LOG_DEBUG << "this " << "msg";
-
 #pragma clang diagnostic push
 #pragma clang diagnostic ignored "-Wgnu-zero-variadic-macro-arguments"
 
@@ -327,54 +330,46 @@ namespace logger
 #  define CCF_FMT_STRING(s) FMT_STRING(s)
 #endif
 
-#ifdef VERBOSE_LOGGING
-#  define LOG_TRACE \
-    logger::config::ok(logger::TRACE) && \
-      logger::Out() == logger::LogLine(logger::TRACE, __FILE__, __LINE__)
-#  define LOG_TRACE_FMT(s, ...) \
-    LOG_TRACE << fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
+// The == operator is being used to:
+// 1. Be a lower precedence than <<, such that using << on the LogLine will
+// happen before the LogLine is "equalitied" with the Out.
+// 2. Be a higher precedence than &&, such that the log statement is bound
+// more tightly than the short-circuiting.
+// 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__)
 
-#  define LOG_DEBUG \
-    logger::config::ok(logger::DEBUG) && \
-      logger::Out() == logger::LogLine(logger::DEBUG, __FILE__, __LINE__)
-#  define LOG_DEBUG_FMT(s, ...) \
-    LOG_DEBUG << fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
+// 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
+// the trailing arguments
+#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
+
+#ifdef VERBOSE_LOGGING
+#  define LOG_TRACE_FMT CCF_LOG_FMT(TRACE, "")
+#  define 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
-#  define LOG_TRACE_FMT(...)
+#  define LOG_TRACE_FMT(...) ((void)0)
+#  define LOG_DEBUG_FMT(...) ((void)0)
 
-#  define LOG_DEBUG
-#  define LOG_DEBUG_FMT(...)
+#  define CCF_APP_TRACE(...) ((void)0)
+#  define CCF_APP_DEBUG(...) ((void)0)
 #endif
 
-#define LOG_INFO \
-  logger::config::ok(logger::INFO) && \
-    logger::Out() == logger::LogLine(logger::INFO, __FILE__, __LINE__)
-#define LOG_INFO_FMT(s, ...) \
-  LOG_INFO << fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
+#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_FAIL \
-  logger::config::ok(logger::FAIL) && \
-    logger::Out() == logger::LogLine(logger::FAIL, __FILE__, __LINE__)
-#define LOG_FAIL_FMT(s, ...) \
-  LOG_FAIL << fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
-
-#define LOG_FATAL \
-  logger::config::ok(logger::FATAL) && \
-    logger::Out() == logger::LogLine(logger::FATAL, __FILE__, __LINE__)
-#define LOG_FATAL_FMT(s, ...) \
-  LOG_FATAL << fmt::format(CCF_FMT_STRING(s), ##__VA_ARGS__)
-
-// Convenient wrapper to report exception errors. Exception message is only
-// displayed in debug mode
-#define LOG_FAIL_EXC(msg) \
-  do \
-  { \
-    LOG_FAIL_FMT("Exception in {}", __PRETTY_FUNCTION__); \
-    LOG_DEBUG_FMT("Error: {}", msg); \
-  } while (0)
+#define CCF_APP_INFO CCF_LOG_FMT(INFO, "app")
+#define CCF_APP_FAIL CCF_LOG_FMT(FAIL, "app")
+#define CCF_APP_FATAL CCF_LOG_FMT(FATAL, "app")
 
 #pragma clang diagnostic pop
 }

include/ccf/endpoint.h

@@ -340,20 +340,7 @@ namespace ccf::endpoints
      */
     Endpoint& set_forwarding_required(ForwardingRequired fr);
 
-    void install()
-    {
-      if (installer == nullptr)
-      {
-        LOG_FATAL_FMT(
-          "Can't install this endpoint ({}) - it is not associated with an "
-          "installer",
-          full_uri_path);
-      }
-      else
-      {
-        installer->install(*this);
-      }
-    }
+    void install();
   };
 
   using EndpointPtr = std::shared_ptr<const Endpoint>;

include/ccf/endpoint_registry.h

@@ -28,6 +28,8 @@ namespace ccf::endpoints
   {
     std::regex template_regex;
     std::vector<std::string> template_component_names;
+
+    static std::optional<PathTemplateSpec> parse(const std::string_view& uri);
   };
 
   struct PathTemplatedEndpoint : public Endpoint
@@ -37,44 +39,6 @@ namespace ccf::endpoints
     PathTemplateSpec spec;
   };
 
-  inline std::optional<PathTemplateSpec> parse_path_template(
-    const std::string& uri)
-  {
-    auto template_start = uri.find_first_of('{');
-    if (template_start == std::string::npos)
-    {
-      return std::nullopt;
-    }
-
-    PathTemplateSpec spec;
-
-    std::string regex_s = uri;
-    template_start = regex_s.find_first_of('{');
-    while (template_start != std::string::npos)
-    {
-      const auto template_end = regex_s.find_first_of('}', template_start);
-      if (template_end == std::string::npos)
-      {
-        throw std::logic_error(fmt::format(
-          "Invalid templated path - missing closing curly bracket: {}", uri));
-      }
-
-      spec.template_component_names.push_back(
-        regex_s.substr(template_start + 1, template_end - template_start - 1));
-      regex_s.replace(
-        template_start, template_end - template_start + 1, "([^/]+)");
-      template_start = regex_s.find_first_of('{', template_start + 1);
-    }
-
-    LOG_TRACE_FMT("Parsed a templated endpoint: {} became {}", uri, regex_s);
-    LOG_TRACE_FMT(
-      "Component names are: {}",
-      fmt::join(spec.template_component_names, ", "));
-    spec.template_regex = std::regex(regex_s);
-
-    return spec;
-  }
-
   /** The EndpointRegistry records the user-defined endpoints for a given
    * CCF application.
    *

samples/apps/logging/logging.cpp

@@ -377,7 +377,8 @@ namespace loggingapp
         // SNIPPET: public_table_access
         auto records_handle =
           ctx.tx.template rw<RecordsMap>(public_records(ctx));
-        records_handle->put(params["id"], in.msg);
+        const auto id = params["id"].get<size_t>();
+        records_handle->put(id, in.msg);
         update_first_write(ctx.tx, in.id, false, get_scope(ctx));
         // SNIPPET_START: set_claims_digest
         if (in.record_claim)
@@ -385,6 +386,7 @@ namespace loggingapp
           ctx.rpc_ctx->set_claims_digest(ccf::ClaimsDigest::Digest(in.msg));
         }
         // SNIPPET_END: set_claims_digest
+        CCF_APP_INFO("Storing {} = {}", id, in.msg);
         return ccf::make_success(true);
       };
       // SNIPPET_END: record_public
@@ -417,8 +419,12 @@ namespace loggingapp
         auto record = public_records_handle->get(id);
 
         if (record.has_value())
+        {
+          CCF_APP_INFO("Fetching {} = {}", id, record.value());
           return ccf::make_success(LoggingGet::Out{record.value()});
+        }
 
+        CCF_APP_INFO("Fetching - no entry for {}", id);
         return ccf::make_error(
           HTTP_STATUS_BAD_REQUEST,
           ccf::errors::ResourceNotFound,

src/apps/js_generic/js_generic_base.cpp

@@ -278,9 +278,9 @@ namespace ccfapp
       JS_SetModuleLoaderFunc(
         rt, nullptr, js::js_app_module_loader, &endpoint_ctx.tx);
 
-      js::Context ctx(rt);
-      js::TxContext txctx{&endpoint_ctx.tx, js::TxAccess::APP};
-      js::ReadOnlyTxContext historical_txctx{historical_tx, js::TxAccess::APP};
+      js::Context ctx(rt, js::TxAccess::APP);
+      js::TxContext txctx{&endpoint_ctx.tx};
+      js::ReadOnlyTxContext historical_txctx{historical_tx};
 
       js::register_request_body_class(ctx);
       js::populate_global(
@@ -524,7 +524,7 @@ namespace ccfapp
             if (key.verb == other_key.verb)
             {
               const auto opt_spec =
-                ccf::endpoints::parse_path_template(other_key.uri_path);
+                ccf::endpoints::PathTemplateSpec::parse(other_key.uri_path);
               if (opt_spec.has_value())
               {
                 const auto& template_spec = opt_spec.value();
@@ -594,7 +594,8 @@ namespace ccfapp
         tx.ro<ccf::endpoints::EndpointsMap>(ccf::endpoints::Tables::ENDPOINTS);
 
       endpoints->foreach_key([this, &verbs, &method](const auto& key) {
-        const auto opt_spec = ccf::endpoints::parse_path_template(key.uri_path);
+        const auto opt_spec =
+          ccf::endpoints::PathTemplateSpec::parse(key.uri_path);
         if (opt_spec.has_value())
         {
           const auto& template_spec = opt_spec.value();

src/apps/js_v8/js_v8_base.cpp

@@ -353,7 +353,7 @@ namespace ccfapp
             if (key.verb == other_key.verb)
             {
               const auto opt_spec =
-                ccf::endpoints::parse_path_template(other_key.uri_path);
+                ccf::endpoints::PathTemplateSpec::parse(other_key.uri_path);
               if (opt_spec.has_value())
               {
                 const auto& template_spec = opt_spec.value();
@@ -423,7 +423,8 @@ namespace ccfapp
         tx.ro<ccf::endpoints::EndpointsMap>(ccf::endpoints::Tables::ENDPOINTS);
 
       endpoints->foreach_key([this, &verbs, &method](const auto& key) {
-        const auto opt_spec = ccf::endpoints::parse_path_template(key.uri_path);
+        const auto opt_spec =
+          ccf::endpoints::PathTemplateSpec::parse(key.uri_path);
         if (opt_spec.has_value())
         {
           const auto& template_spec = opt_spec.value();

src/apps/js_v8/tmpl/console_global.cpp

@@ -9,30 +9,60 @@
 
 namespace ccf::v8_tmpl
 {
-  static void log(const v8::FunctionCallbackInfo<v8::Value>& info)
+  static std::optional<std::stringstream> stringify_args(
+    const v8::FunctionCallbackInfo<v8::Value>& fci)
   {
-    v8::Isolate* isolate = info.GetIsolate();
+    v8::Isolate* isolate = fci.GetIsolate();
     v8::Local<v8::Context> context = isolate->GetCurrentContext();
 
     std::stringstream ss;
-    for (int i = 0; i < info.Length(); i++)
+    for (int i = 0; i < fci.Length(); i++)
     {
       if (i != 0)
-        ss << ' ';
-      v8::Local<v8::String> str;
-      if (!info[i]->IsNativeError() && info[i]->IsObject())
       {
-        if (!v8::JSON::Stringify(context, info[i]).ToLocal(&str))
-          return;
+        ss << ' ';
+      }
+      v8::Local<v8::String> str;
+      if (!fci[i]->IsNativeError() && fci[i]->IsObject())
+      {
+        if (!v8::JSON::Stringify(context, fci[i]).ToLocal(&str))
+          return std::nullopt;
       }
       else
       {
-        if (!info[i]->ToString(context).ToLocal(&str))
-          return;
+        if (!fci[i]->ToString(context).ToLocal(&str))
+          return std::nullopt;
       }
       ss << v8_util::to_str(isolate, str);
     }
-    LOG_INFO << ss.str() << std::endl;
+    return ss;
+  }
+
+  static void info(const v8::FunctionCallbackInfo<v8::Value>& fci)
+  {
+    const auto ss = stringify_args(fci);
+    if (ss.has_value())
+    {
+      CCF_APP_INFO("{}", ss->str());
+    }
+  }
+
+  static void fail(const v8::FunctionCallbackInfo<v8::Value>& fci)
+  {
+    const auto ss = stringify_args(fci);
+    if (ss.has_value())
+    {
+      CCF_APP_FAIL("{}", ss->str());
+    }
+  }
+
+  static void fatal(const v8::FunctionCallbackInfo<v8::Value>& fci)
+  {
+    const auto ss = stringify_args(fci);
+    if (ss.has_value())
+    {
+      CCF_APP_FATAL("{}", ss->str());
+    }
   }
 
   v8::Local<v8::ObjectTemplate> ConsoleGlobal::create_template(
@@ -44,7 +74,16 @@ namespace ccf::v8_tmpl
 
     tmpl->Set(
       v8_util::to_v8_istr(isolate, "log"),
-      v8::FunctionTemplate::New(isolate, log));
+      v8::FunctionTemplate::New(isolate, info));
+    tmpl->Set(
+      v8_util::to_v8_istr(isolate, "info"),
+      v8::FunctionTemplate::New(isolate, info));
+    tmpl->Set(
+      v8_util::to_v8_istr(isolate, "warn"),
+      v8::FunctionTemplate::New(isolate, fail));
+    tmpl->Set(
+      v8_util::to_v8_istr(isolate, "error"),
+      v8::FunctionTemplate::New(isolate, fatal));
 
     return handle_scope.Escape(tmpl);
   }

src/consensus/aft/raft.h

@@ -6,6 +6,7 @@
 #include "ccf/ds/mutex.h"
 #include "ccf/tx_id.h"
 #include "ccf/tx_status.h"
+#include "ds/ccf_exception.h"
 #include "ds/serialized.h"
 #include "enclave/reconfiguration_type.h"
 #include "impl/state.h"

src/ds/ccf_exception.h

@@ -56,3 +56,12 @@ namespace ccf
     {}
   };
 };
+
+// Convenient wrapper to report exception errors. Exception message is only
+// displayed in debug mode
+#define LOG_FAIL_EXC(msg) \
+  do \
+  { \
+    LOG_FAIL_FMT("Exception in {}", __PRETTY_FUNCTION__); \
+    LOG_DEBUG_FMT("Error: {}", msg); \
+  } while (0)

src/ds/test/logger.cpp

@@ -0,0 +1,129 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the Apache 2.0 License.
+
+#include "ccf/ds/logger.h"
+
+#define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN
+#include <doctest/doctest.h>
+
+template <typename Base>
+class TestLogger : public Base
+{
+public:
+  std::vector<std::string>& logs;
+
+  TestLogger(std::vector<std::string>& l) : logs(l) {}
+
+  void emit(const std::string& s) override
+  {
+    logs.push_back(s);
+  }
+};
+
+using TestTextLogger = TestLogger<logger::TextConsoleLogger>;
+using TestJsonLogger = TestLogger<logger::JsonConsoleLogger>;
+
+TEST_CASE("Standard logging macros")
+{
+  std::vector<std::string> logs;
+
+  logger::config::loggers().emplace_back(
+    std::make_unique<TestTextLogger>(logs));
+
+  {
+    REQUIRE(logs.empty());
+    LOG_INFO_FMT("Hello A");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("info") != std::string::npos);
+    REQUIRE(log.find("logger.cpp") != std::string::npos);
+    REQUIRE(log.find("Hello A") != std::string::npos);
+
+    logs.clear();
+  }
+
+  {
+    REQUIRE(logs.empty());
+    LOG_FAIL_FMT("Hello B");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("fail") != 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(LOG_FATAL_FMT("Hello C"));
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("fatal") != 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)
+
+constexpr auto custom_long_tag =
+  "A very long tag that may need to be truncated";
+#define CUSTOM_LOG_LONG CCF_LOG_FMT(INFO, custom_long_tag)
+
+TEST_CASE("Custom logging macros")
+{
+  std::vector<std::string> logs;
+
+  logger::config::loggers().emplace_back(
+    std::make_unique<TestTextLogger>(logs));
+
+  {
+    REQUIRE(logs.empty());
+    CUSTOM_LOG("Some message");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("info") != std::string::npos);
+    REQUIRE(log.find(custom_tag) != std::string::npos);
+    REQUIRE(log.find("logger.cpp") != std::string::npos);
+    REQUIRE(log.find("Some message") != std::string::npos);
+
+    logs.clear();
+  }
+
+  {
+    REQUIRE(logs.empty());
+    CUSTOM_LOG_LONG("Some other message");
+    REQUIRE(logs.size() == 1);
+
+    const auto& log = logs[0];
+    REQUIRE(log.find("info") != std::string::npos);
+    // Search for smaller prefixes of the long tag, expect that one is
+    // eventually present
+    std::string truncated_tag = custom_long_tag;
+    while (truncated_tag.size() > 0)
+    {
+      const auto search = log.find(truncated_tag);
+      if (search != std::string::npos)
+      {
+        break;
+      }
+      truncated_tag.resize(truncated_tag.size() - 1);
+    }
+    REQUIRE(truncated_tag.size() > 0);
+    REQUIRE(log.find("Some other message") != std::string::npos);
+
+    logs.clear();
+  }
+
+  logger::config::loggers().clear();
+}

src/ds/test/logger_bench.cpp

@@ -57,7 +57,7 @@ static void log_accepted(picobench::state& s)
 
     for (size_t i = 0; i < s.iterations(); ++i)
     {
-      LOG_DEBUG << "test" << std::endl;
+      CCF_LOG_OUT(DEBUG, "") << "test " << i << std::endl;
     }
   }
 
@@ -75,7 +75,7 @@ static void log_accepted_fmt(picobench::state& s)
 
     for (size_t i = 0; i < s.iterations(); ++i)
     {
-      LOG_DEBUG_FMT("test");
+      LOG_DEBUG_FMT("test {}", i);
     }
   }
 
@@ -93,7 +93,7 @@ static void log_rejected(picobench::state& s)
 
     for (size_t i = 0; i < s.iterations(); ++i)
     {
-      LOG_DEBUG << "test" << std::endl;
+      CCF_LOG_OUT(DEBUG, "") << "test " << i << std::endl;
     }
   }
 
@@ -111,7 +111,7 @@ static void log_rejected_fmt(picobench::state& s)
 
     for (size_t i = 0; i < s.iterations(); ++i)
     {
-      LOG_DEBUG_FMT("test");
+      LOG_DEBUG_FMT("test {}", i);
     }
   }
 

src/ds/test/openapi.cpp

@@ -2,6 +2,7 @@
 // Licensed under the Apache 2.0 License.
 #include "ccf/ds/openapi.h"
 
+#include "ccf/ds/logger.h"
 #include "ccf/http_consts.h"
 
 #define DOCTEST_CONFIG_IMPLEMENT_WITH_MAIN

src/enclave/interface.h

@@ -36,6 +36,7 @@ DECLARE_RINGBUFFER_MESSAGE_PAYLOAD(
   std::string,
   size_t,
   logger::Level,
+  std::string,
   uint16_t,
   std::string);
 DECLARE_RINGBUFFER_MESSAGE_PAYLOAD(AdminMessage::fatal_error_msg, std::string);

src/enclave/ringbuffer_logger.h

@@ -28,6 +28,7 @@ namespace ccf
         line.file_name,
         line.line_number,
         line.log_level,
+        line.tag,
         line.thread_id,
         line.msg);
     }

src/endpoints/endpoint.cpp

@@ -68,4 +68,19 @@ namespace ccf::endpoints
     properties.forwarding_required = fr;
     return *this;
   }
+
+  void Endpoint::install()
+  {
+    if (installer == nullptr)
+    {
+      LOG_FATAL_FMT(
+        "Can't install this endpoint ({}) - it is not associated with an "
+        "installer",
+        full_uri_path);
+    }
+    else
+    {
+      installer->install(*this);
+    }
+  }
 }

src/endpoints/endpoint_registry.cpp

@@ -77,6 +77,44 @@ namespace ccf::endpoints
     }
   }
 
+  std::optional<PathTemplateSpec> PathTemplateSpec::parse(
+    const std::string_view& uri)
+  {
+    auto template_start = uri.find_first_of('{');
+    if (template_start == std::string::npos)
+    {
+      return std::nullopt;
+    }
+
+    PathTemplateSpec spec;
+
+    std::string regex_s(uri);
+    template_start = regex_s.find_first_of('{');
+    while (template_start != std::string::npos)
+    {
+      const auto template_end = regex_s.find_first_of('}', template_start);
+      if (template_end == std::string::npos)
+      {
+        throw std::logic_error(fmt::format(
+          "Invalid templated path - missing closing curly bracket: {}", uri));
+      }
+
+      spec.template_component_names.push_back(
+        regex_s.substr(template_start + 1, template_end - template_start - 1));
+      regex_s.replace(
+        template_start, template_end - template_start + 1, "([^/]+)");
+      template_start = regex_s.find_first_of('{', template_start + 1);
+    }
+
+    LOG_TRACE_FMT("Parsed a templated endpoint: {} became {}", uri, regex_s);
+    LOG_TRACE_FMT(
+      "Component names are: {}",
+      fmt::join(spec.template_component_names, ", "));
+    spec.template_regex = std::regex(regex_s);
+
+    return spec;
+  }
+
   EndpointRegistry::Metrics& EndpointRegistry::get_metrics_for_endpoint(
     const EndpointDefinitionPtr& e)
   {
@@ -151,7 +189,8 @@ namespace ccf::endpoints
       endpoint.authn_policies.pop_back();
     }
 
-    const auto template_spec = parse_path_template(endpoint.dispatch.uri_path);
+    const auto template_spec =
+      PathTemplateSpec::parse(endpoint.dispatch.uri_path);
     if (template_spec.has_value())
     {
       auto templated_endpoint =

src/host/handle_ring_buffer.h

@@ -45,11 +45,12 @@ namespace asynchost
              file_name,
              line_number,
              log_level,
+             tag,
              thread_id,
              msg] = ringbuffer::read_message<AdminMessage::log_msg>(data, size);
 
           logger::LogLine ll(
-            log_level, file_name.c_str(), line_number, thread_id);
+            log_level, tag, file_name.c_str(), line_number, thread_id);
           ll.msg = msg;
 
           // Represent offset as a real (counting seconds) to handle both small

src/js/historical.cpp

@@ -164,9 +164,7 @@ namespace ccf::js
       // Note: The state_ctx object is deleted by js_historical_state_finalizer
       // which is registered as the finalizer for historical_state_class_id.
       auto state_ctx = new HistoricalStateContext{
-        state,
-        state->store->create_read_only_tx(),
-        ReadOnlyTxContext{nullptr, TxAccess::APP}};
+        state, state->store->create_read_only_tx(), ReadOnlyTxContext{nullptr}};
       state_ctx->tx_ctx.tx = &state_ctx->tx;
       JS_SetOpaque(js_state, state_ctx);
 

src/js/wrap.cpp

@@ -459,8 +459,7 @@ namespace ccf::js
     auto tx_ctx_ptr =
       static_cast<TxContext*>(JS_GetOpaque(this_val, kv_class_id));
 
-    const auto read_only =
-      _check_kv_map_access(tx_ctx_ptr->access, property_name);
+    const auto read_only = _check_kv_map_access(jsctx.access, property_name);
 
     auto handle = tx_ctx_ptr->tx->rw<KVMap>(property_name);
 
@@ -482,7 +481,7 @@ namespace ccf::js
     auto tx_ctx_ptr = static_cast<ReadOnlyTxContext*>(
       JS_GetOpaque(this_val, kv_read_only_class_id));
 
-    _check_kv_map_access(tx_ctx_ptr->access, property_name);
+    _check_kv_map_access(jsctx.access, property_name);
     const auto read_only = true;
 
     auto handle = tx_ctx_ptr->tx->ro<KVMap>(property_name);
@@ -1304,7 +1303,7 @@ namespace ccf::js
 
     js::Runtime rt;
     JS_SetModuleLoaderFunc(rt, nullptr, js::js_app_module_loader, &tx);
-    js::Context ctx2(rt);
+    js::Context ctx2(rt, js::TxAccess::APP);
 
     auto modules = tx.ro<ccf::Modules>(ccf::Tables::MODULES);
     auto quickjs_version =
@@ -1396,7 +1395,8 @@ namespace ccf::js
     historical_state_class_def.finalizer = js_historical_state_finalizer;
   }
 
-  JSValue js_print(JSContext* ctx, JSValueConst, int argc, JSValueConst* argv)
+  std::optional<std::stringstream> stringify_args(
+    JSContext* ctx, int argc, JSValueConst* argv)
   {
     js::Context& jsctx = *(js::Context*)JS_GetContextOpaque(ctx);
 
@@ -1407,19 +1407,84 @@ namespace ccf::js
     for (i = 0; i < argc; i++)
     {
       if (i != 0)
+      {
         ss << ' ';
+      }
       if (!JS_IsError(ctx, argv[i]) && JS_IsObject(argv[i]))
       {
         auto rval = jsctx.json_stringify(JSWrappedValue(ctx, argv[i]));
         str = jsctx.to_str(rval);
       }
       else
+      {
         str = jsctx.to_str(argv[i]);
+      }
       if (!str)
-        return JS_EXCEPTION;
+      {
+        return std::nullopt;
+      }
       ss << *str;
     }
-    LOG_INFO << ss.str() << std::endl;
+    return ss;
+  }
+
+  JSValue js_info(JSContext* ctx, JSValueConst, int argc, JSValueConst* argv)
+  {
+    const auto ss = stringify_args(ctx, argc, argv);
+    if (!ss.has_value())
+    {
+      return JS_EXCEPTION;
+    }
+
+    js::Context& jsctx = *(js::Context*)JS_GetContextOpaque(ctx);
+    if (jsctx.access == js::TxAccess::APP)
+    {
+      CCF_APP_INFO("{}", ss->str());
+    }
+    else
+    {
+      LOG_INFO_FMT("{}", ss->str());
+    }
+    return JS_UNDEFINED;
+  }
+
+  JSValue js_fail(JSContext* ctx, JSValueConst, int argc, JSValueConst* argv)
+  {
+    const auto ss = stringify_args(ctx, argc, argv);
+    if (!ss.has_value())
+    {
+      return JS_EXCEPTION;
+    }
+
+    js::Context& jsctx = *(js::Context*)JS_GetContextOpaque(ctx);
+    if (jsctx.access == js::TxAccess::APP)
+    {
+      CCF_APP_INFO("{}", ss->str());
+    }
+    else
+    {
+      LOG_FAIL_FMT("{}", ss->str());
+    }
+    return JS_UNDEFINED;
+  }
+
+  JSValue js_fatal(JSContext* ctx, JSValueConst, int argc, JSValueConst* argv)
+  {
+    const auto ss = stringify_args(ctx, argc, argv);
+    if (!ss.has_value())
+    {
+      return JS_EXCEPTION;
+    }
+
+    js::Context& jsctx = *(js::Context*)JS_GetContextOpaque(ctx);
+    if (jsctx.access == js::TxAccess::APP)
+    {
+      CCF_APP_FATAL("{}", ss->str());
+    }
+    else
+    {
+      LOG_FATAL_FMT("{}", ss->str());
+    }
     return JS_UNDEFINED;
   }
 
@@ -1431,7 +1496,7 @@ namespace ccf::js
     bool is_error = JS_IsError(ctx, exception_val);
     if (!is_error)
       LOG_INFO_FMT("Throw: ");
-    js_print(ctx, JS_NULL, 1, (JSValueConst*)&exception_val);
+    js_fail(ctx, JS_NULL, 1, (JSValueConst*)&exception_val);
     if (is_error)
     {
       auto val = exception_val["stack"];
@@ -1553,7 +1618,13 @@ namespace ccf::js
     auto console = jsctx.new_obj();
 
     JS_SetPropertyStr(
-      ctx, console, "log", JS_NewCFunction(ctx, js_print, "log", 1));
+      ctx, console, "log", JS_NewCFunction(ctx, js_info, "log", 1));
+    JS_SetPropertyStr(
+      ctx, console, "info", JS_NewCFunction(ctx, js_info, "info", 1));
+    JS_SetPropertyStr(
+      ctx, console, "warn", JS_NewCFunction(ctx, js_fail, "warn", 1));
+    JS_SetPropertyStr(
+      ctx, console, "error", JS_NewCFunction(ctx, js_fatal, "error", 1));
 
     return console;
   }

src/js/wrap.h

@@ -49,13 +49,11 @@ namespace ccf::js
   struct TxContext
   {
     kv::Tx* tx = nullptr;
-    TxAccess access = js::TxAccess::APP;
   };
 
   struct ReadOnlyTxContext
   {
     kv::ReadOnlyTx* tx = nullptr;
-    TxAccess access = js::TxAccess::APP;
   };
 
   struct HistoricalStateContext
@@ -251,10 +249,11 @@ namespace ccf::js
   class Context
   {
     JSContext* ctx;
-    bool ok_to_free = true;
 
   public:
-    Context(JSRuntime* rt)
+    const TxAccess access;
+
+    Context(JSRuntime* rt, TxAccess acc) : access(acc)
     {
       ctx = JS_NewContext(rt);
       if (ctx == nullptr)
@@ -264,18 +263,9 @@ namespace ccf::js
       JS_SetContextOpaque(ctx, this);
     }
 
-    Context(JSContext* other)
-    {
-      ctx = other;
-      ok_to_free = false;
-    }
-
     ~Context()
     {
-      if (ok_to_free)
-      {
-        JS_FreeContext(ctx);
-      }
+      JS_FreeContext(ctx);
     }
 
     operator JSContext*() const

src/node/channels.h

@@ -11,6 +11,7 @@
 #include "ccf/ds/logger.h"
 #include "ccf/entity_id.h"
 #include "crypto/key_exchange.h"
+#include "ds/ccf_exception.h"
 #include "ds/serialized.h"
 #include "ds/state_machine.h"
 #include "ds/thread_messaging.h"

src/node/merklecpp_trace.h

@@ -10,4 +10,4 @@
   { \
     X; \
   };
-#define MERKLECPP_TOUT LOG_TRACE
+#define MERKLECPP_TOUT CCF_LOG_OUT(TRACE, "merkl")

src/node/rpc/forwarder.h

@@ -2,6 +2,7 @@
 // Licensed under the Apache 2.0 License.
 #pragma once
 
+#include "ds/ccf_exception.h"
 #include "enclave/forwarder_types.h"
 #include "enclave/rpc_map.h"
 #include "http/http_rpc_context.h"

src/node/rpc/member_frontend.h

@@ -224,9 +224,9 @@ namespace ccf
       for (const auto& [mid, mb] : pi_->ballots)
       {
         js::Runtime rt;
-        js::Context context(rt);
+        js::Context context(rt, js::TxAccess::GOV_RO);
         rt.add_ccf_classdefs();
-        js::TxContext txctx{&tx, js::TxAccess::GOV_RO};
+        js::TxContext txctx{&tx};
         js::populate_global(
           &txctx,
           nullptr,
@@ -268,9 +268,9 @@ namespace ccf
 
       {
         js::Runtime rt;
-        js::Context js_context(rt);
+        js::Context js_context(rt, js::TxAccess::GOV_RO);
         rt.add_ccf_classdefs();
-        js::TxContext txctx{&tx, js::TxAccess::GOV_RO};
+        js::TxContext txctx{&tx};
         js::populate_global(
           &txctx,
           nullptr,
@@ -373,9 +373,9 @@ namespace ccf
           if (pi_.value().state == ProposalState::ACCEPTED)
           {
             js::Runtime rt;
-            js::Context js_context(rt);
+            js::Context js_context(rt, js::TxAccess::GOV_RW);
             rt.add_ccf_classdefs();
-            js::TxContext txctx{&tx, js::TxAccess::GOV_RW};
+            js::TxContext txctx{&tx};
 
             auto gov_effects =
               context.get_subsystem<AbstractGovernanceEffects>();
@@ -901,7 +901,7 @@ namespace ccf
         auto validate_script = constitution.value();
 
         js::Runtime rt;
-        js::Context context(rt);
+        js::Context context(rt, js::TxAccess::GOV_RO);
         rt.add_ccf_classdefs();
         js::populate_global(
           nullptr,
@@ -1305,7 +1305,7 @@ namespace ccf
 
         {
           js::Runtime rt;
-          js::Context context(rt);
+          js::Context context(rt, js::TxAccess::GOV_RO);
           auto ballot_func =
             context.function(params["ballot"], "vote", "body[\"ballot\"]");
         }