Refactor logging and allow setting a minimum log level that should no…

…t be emitted (#161)

This pulls the logging code out into its own class as it was getting
more complex.

It also allows limiting sending of logs from a reactor. Sending out
every trace message was causing a lot of overhead.

Now there are two variables in each reactor, one to describe the
displayed log level `log_level` and one to describe the minimum emitted
log level `min_log_level`

src/PowerPlant.cpp

@@ -49,7 +49,7 @@ PowerPlant* PowerPlant::powerplant = nullptr;
 // This is taking argc and argv as given by main so this should not take an array
 // NOLINTNEXTLINE(cppcoreguidelines-avoid-c-arrays,modernize-avoid-c-arrays)
 PowerPlant::PowerPlant(Configuration config, int argc, const char* argv[])
-    : scheduler(config.default_pool_concurrency) {
+    : scheduler(config.default_pool_concurrency), logger(*this) {
 
     // Stop people from making more then one powerplant
     if (powerplant != nullptr) {
@@ -103,21 +103,6 @@ void PowerPlant::submit(std::unique_ptr<threading::ReactionTask>&& task) noexcep
     scheduler.submit(std::move(task));
 }
 
-void PowerPlant::log(const LogLevel& level, std::string message) {
-    // Get the current task
-    const auto* current_task = threading::ReactionTask::get_current_task();
-
-    // Inline emit the log message to default handlers to pause the current task until the log message is processed
-    emit<dsl::word::emit::Inline>(std::make_unique<message::LogMessage>(
-        level,
-        current_task != nullptr ? current_task->parent->reactor.log_level : LogLevel::UNKNOWN,
-        std::move(message),
-        current_task != nullptr ? current_task->statistics : nullptr));
-}
-void PowerPlant::log(const LogLevel& level, std::stringstream& message) {
-    log(level, message.str());
-}
-
 void PowerPlant::shutdown(bool force) {
 
     // Emit our shutdown event

src/PowerPlant.hpp

@@ -38,6 +38,7 @@
 #include "threading/ReactionTask.hpp"
 #include "threading/scheduler/Scheduler.hpp"
 #include "util/FunctionFusion.hpp"
+#include "util/Logger.hpp"
 #include "util/demangle.hpp"
 
 namespace NUClear {
@@ -188,32 +189,41 @@ class PowerPlant {
      * Logs a message through the system so the various log handlers can access it.
      * The arguments being logged should be able to be added into a stringstream.
      *
-     * @tparam level     The level to log at (defaults to DEBUG)
+     * @tparam level     The level to log at
      * @tparam Arguments The types of the arguments we are logging
      *
      * @param args The arguments we are logging
      */
     template <enum LogLevel level, typename... Arguments>
     void log(Arguments&&... args) {
-        log(level, std::forward<Arguments>(args)...);
+        logger.log(nullptr, level, std::forward<Arguments>(args)...);
     }
     template <typename... Arguments>
     void log(const LogLevel& level, Arguments&&... args) {
-        std::stringstream ss;
-        log(level, ss, std::forward<Arguments>(args)...);
+        logger.log(nullptr, level, std::forward<Arguments>(args)...);
     }
-    template <typename First, typename... Arguments>
-    void log(const LogLevel& level, std::stringstream& ss, First&& first, Arguments&&... args) {
-        ss << std::forward<First>(first) << " ";
-        log(level, ss, std::forward<Arguments>(args)...);
+
+    /**
+     * Log a message through NUClear's system.
+     *
+     * This version of log takes a pointer to a reactor as an argument.
+     * When logging from a reactor's log function, even if it's not logging within a reactor needs the context to add
+     * the extra information about the reactors name.
+     *
+     * @tparam level     The level to log at (defaults to DEBUG)
+     * @tparam Arguments The types of the arguments we are logging
+     *
+     * @param reactor The reactor that is logging
+     * @param args    The arguments we are logging
+     */
+    template <enum LogLevel level, typename... Arguments>
+    void log(const Reactor* reactor, Arguments&&... args) {
+        logger.log(reactor, level, std::forward<Arguments>(args)...);
     }
-    template <typename Last>
-    void log(const LogLevel& level, std::stringstream& ss, Last&& last) {
-        ss << std::forward<Last>(last);
-        log(level, ss);
+    template <typename... Arguments>
+    void log(const Reactor* reactor, const LogLevel& level, Arguments&&... args) {
+        logger.log(reactor, level, std::forward<Arguments>(args)...);
     }
-    void log(const LogLevel& level, std::stringstream& message);
-    void log(const LogLevel& level, std::string message);
 
     /**
      * Emits data to the system and routes it to the other systems that use it.
@@ -235,17 +245,15 @@ class PowerPlant {
         emit<dsl::word::emit::Local>(std::move(data));
     }
     template <template <typename> class First,
-              template <typename>
-              class... Remainder,
+              template <typename> class... Remainder,
               typename T,
               typename... Arguments>
     void emit(std::unique_ptr<T>& data, Arguments&&... args) {
         emit<First, Remainder...>(std::move(data), std::forward<Arguments>(args)...);
     }
 
     template <template <typename> class First,
-              template <typename>
-              class... Remainder,
+              template <typename> class... Remainder,
               typename T,
               typename... Arguments>
     void emit(std::unique_ptr<T>&& data, Arguments&&... args) {
@@ -283,8 +291,7 @@ class PowerPlant {
      * @param data The data we are emitting
      */
     template <template <typename> class First,
-              template <typename>
-              class... Remainder,
+              template <typename> class... Remainder,
               typename T,
               typename... Arguments>
     void emit_shared(std::shared_ptr<T> data, Arguments&&... args) {
@@ -326,6 +333,8 @@ class PowerPlant {
     threading::scheduler::Scheduler scheduler;
     /// Our vector of Reactors, will get destructed when this vector is
     std::vector<std::unique_ptr<NUClear::Reactor>> reactors;
+    /// Our logger that handles logging messages
+    util::Logger logger;
 };
 
 /**

src/Reactor.hpp

@@ -177,10 +177,12 @@ class Reactor {
     /// The demangled string name of this reactor
     const std::string reactor_name;
 
-protected:
-    /// The level that this reactor logs at
+    /// The display level above which logs from this reactor will be displayed
     LogLevel log_level{LogLevel::INFO};
+    /// The minimum log level that will be always emitted (if log_level is below this those will be emitted too)
+    LogLevel min_log_level{LogLevel::DEBUG};
 
+protected:
     /***************************************************************************************************************
      * The types here are imported from other contexts so that when extending from the Reactor type in normal      *
      * usage there does not need to be any namespace declarations on the used types.                               *
@@ -436,9 +438,10 @@ class Reactor {
      */
     template <enum LogLevel level = DEBUG, typename... Arguments>
     void log(Arguments&&... args) const {
-
-        // If the log is above or equal to our log level
-        powerplant.log<level>(std::forward<Arguments>(args)...);
+        // Short circuit here before going to the more expensive log function
+        if (level >= min_log_level || level >= log_level) {
+            powerplant.log<level>(this, std::forward<Arguments>(args)...);
+        }
     }
 
     /**
@@ -453,9 +456,10 @@ class Reactor {
      */
     template <typename... Arguments>
     void log(const LogLevel& level, Arguments&&... args) const {
-
-        // If the log is above or equal to our log level
-        powerplant.log(level, std::forward<Arguments>(args)...);
+        // Short circuit here before going to the more expensive log function
+        if (level >= min_log_level || level >= log_level) {
+            powerplant.log(this, level, std::forward<Arguments>(args)...);
+        }
     }
 };
 

src/message/LogMessage.hpp

@@ -42,15 +42,19 @@ namespace message {
          * @param level         The logging level of the log
          * @param display_level The logging level of the reactor that made this log
          * @param message       The string contents of the message
+         * @param reactor_name  The name of the reactor that made this if it was from a reactor's log function or a
+         *                      reaction belonging to that reactor
          * @param statistics    The statistics of the currently executing task or nullptr if not in a task
          */
         LogMessage(const LogLevel& level,
                    const LogLevel& display_level,
                    std::string message,
+                   std::string reactor_name,
                    std::shared_ptr<const ReactionStatistics> statistics)
             : level(level)
             , display_level(display_level)
             , message(std::move(message))
+            , reactor_name(std::move(reactor_name))
             , statistics(std::move(statistics)) {}
 
         /// The logging level of the log
@@ -62,6 +66,9 @@ namespace message {
         /// The string contents of the message
         std::string message;
 
+        /// The name of the reactor that made this log message if it was from a reactor's log function
+        std::string reactor_name;
+
         /// The statistics of the currently executing task that made this message
         const std::shared_ptr<const ReactionStatistics> statistics{nullptr};
     };

src/util/Logger.cpp

@@ -0,0 +1,49 @@
+#include "Logger.hpp"
+
+#include "../Reactor.hpp"
+#include "../dsl/word/emit/Inline.hpp"
+#include "../message/LogMessage.hpp"
+#include "../threading/ReactionTask.hpp"
+
+namespace NUClear {
+namespace util {
+
+    /**
+     * Get the current reactor that is running based on the passed in reactor, or the current task if not in a reactor.
+     *
+     * @param calling_reactor The reactor that is calling this function or nullptr if not called from a reactor
+     *
+     * @return The current reactor or nullptr if not in a reactor
+     */
+    const Reactor* get_current_reactor(const Reactor* calling_reactor) {
+        if (calling_reactor != nullptr) {
+            return calling_reactor;
+        }
+        // Get the current task
+        const auto* const current_task = threading::ReactionTask::get_current_task();
+        return current_task != nullptr && current_task->parent != nullptr ? &current_task->parent->reactor : nullptr;
+    }
+
+    Logger::LogLevels Logger::get_current_log_levels(const Reactor* calling_reactor) {
+        // Get the current reactor either from the passed in reactor or the current task
+        const auto* reactor = get_current_reactor(calling_reactor);
+        return reactor != nullptr ? LogLevels(reactor->log_level, reactor->min_log_level)
+                                  : LogLevels(LogLevel::UNKNOWN, LogLevel::UNKNOWN);
+    }
+
+    void Logger::do_log(const Reactor* calling_reactor, const LogLevel& level, const std::string& message) {
+        // Get the current context
+        const auto* reactor      = get_current_reactor(calling_reactor);
+        const auto* current_task = threading::ReactionTask::get_current_task();
+        auto log_levels          = get_current_log_levels(reactor);
+
+        // Inline emit the log message to default handlers to pause the current task until the log message is processed
+        powerplant.emit<dsl::word::emit::Inline>(
+            std::make_unique<message::LogMessage>(level,
+                                                  log_levels.display_log_level,
+                                                  message,
+                                                  reactor != nullptr ? reactor->reactor_name : "",
+                                                  current_task != nullptr ? current_task->statistics : nullptr));
+    }
+}  // namespace util
+}  // namespace NUClear

src/util/Logger.hpp

@@ -0,0 +1,96 @@
+/*
+ * MIT License
+ *
+ * Copyright (c) 2013 NUClear Contributors
+ *
+ * This file is part of the NUClear codebase.
+ * See https://github.com/Fastcode/NUClear for further info.
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated
+ * documentation files (the "Software"), to deal in the Software without restriction, including without limitation the
+ * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the Software, and to
+ * permit persons to whom the Software is furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in all copies or substantial portions of the
+ * Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE
+ * WARRANTIES OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR
+ * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR
+ * OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
+ */
+
+#ifndef NUCLEAR_UTIL_LOGGER_HPP
+#define NUCLEAR_UTIL_LOGGER_HPP
+
+#include <sstream>
+#include <utility>
+
+#include "../LogLevel.hpp"
+#include "string_join.hpp"
+
+namespace NUClear {
+
+// Forward declarations
+class PowerPlant;
+class Reactor;
+
+namespace util {
+
+    /**
+     * The Logger class is used to handle converting the variardic log calls into an appropriate log message.
+     *
+     * It's also responsible for working out which messages should be emitted and which should be ignored.
+     */
+    class Logger {
+    public:
+        Logger(PowerPlant& powerplant) : powerplant(powerplant) {}
+
+        /**
+         * Log a message to the system.
+         *
+         * This function will check if a log message should be emitted based on the current log levels and then emit the
+         * log message.
+         */
+        template <typename... Arguments>
+        void log(const Reactor* reactor, const LogLevel& level, const Arguments&... args) {
+            // Check if the log level is above the minimum log levels
+            auto log_levels = get_current_log_levels(reactor);
+            if (level >= log_levels.display_log_level || level >= log_levels.min_log_level) {
+                // Collapse the arguments into a string and perform the log action
+                do_log(reactor, level, string_join(" ", std::forward<const Arguments&>(args)...));
+            }
+        }
+
+    private:
+        /**
+         * Describes the log levels for a particular reactor.
+         */
+        struct LogLevels {
+            LogLevels(LogLevel display_log_level, LogLevel min_log_level)
+                : display_log_level(display_log_level), min_log_level(min_log_level) {}
+
+            /// The log level that should be displayed
+            LogLevel display_log_level;
+            /// The minimum log level that should be emitted
+            LogLevel min_log_level;
+        };
+
+        /**
+         * Get the log levels for the current reactor or UNKNOWN if not in a reactor.
+         */
+        static LogLevels get_current_log_levels(const Reactor* reactor);
+
+        /**
+         * Perform the log action and emit the log message.
+         */
+        void do_log(const Reactor* reactor, const LogLevel& level, const std::string& message);
+
+        /// The powerplant that this logger is logging for, used for emitting log messages
+        PowerPlant& powerplant;
+    };
+
+}  // namespace util
+}  // namespace NUClear
+
+#endif  // NUCLEAR_UTIL_LOGGER_HPP