Add dynamic logging for full_system & thunderscope (UBC-Thunderbots#3539)

Author: nycrat

src/.bazelrc

@@ -70,6 +70,8 @@ build --per_file_copt=proto/.*,proto/message_translation/.*,proto/primitive/.*,s
 # TODO: #3492
 # build --per_file_copt=software/.*,shared/.*,-external/.*@-Wconversion
 
+build --cxxopt="-DG3_DYNAMIC_LOGGING"
+
 build --per_file_copt=.*\.pb\.(h|cc|cpp)$@-w
 build --per_file_copt=./external/.*,./bazel-out/.*@-w
 

src/software/logger/logger.h

@@ -63,16 +63,17 @@ class LoggerSingleton
      */
     static void initializeLogger(const std::string& runtime_dir,
                                  const std::shared_ptr<ProtoLogger>& proto_logger,
-                                 const bool reduce_repetition = true)
+                                 const bool reduce_repetition   = true,
+                                 const LEVELS minimum_log_level = DEBUG)
     {
-        static std::shared_ptr<LoggerSingleton> s(
-            new LoggerSingleton(runtime_dir, proto_logger, reduce_repetition));
+        static LoggerSingleton s(runtime_dir, proto_logger, reduce_repetition,
+                                 minimum_log_level);
     }
 
    private:
     LoggerSingleton(const std::string& runtime_dir,
                     const std::shared_ptr<ProtoLogger>& proto_logger,
-                    const bool reduce_repetition)
+                    const bool reduce_repetition, const LEVELS minimum_log_level)
     {
         logWorker = g3::LogWorker::createLogWorker();
         // Default locations
@@ -123,6 +124,13 @@ class LoggerSingleton
         auto plotjuggler_handle = logWorker->addSink(std::make_unique<PlotJugglerSink>(),
                                                      &PlotJugglerSink::sendToPlotJuggler);
 
+        g3::log_levels::setHighest(minimum_log_level);
+
+        // Add custom logging levels below setHighest to always enable
+        g3::only_change_at_initialization::addLogLevel(CSV);
+        g3::only_change_at_initialization::addLogLevel(VISUALIZE);
+        g3::only_change_at_initialization::addLogLevel(PLOTJUGGLER);
+
         g3::initializeLogging(logWorker.get());
     }
 

src/software/networking/benchmarking_utils/latency_tester_secondary_node_main.cpp

@@ -6,7 +6,7 @@
 
 constexpr int SLEEP_DURATION_S = 1;
 
-int main(int argc, char **argv)
+int main(int argc, char** argv)
 {
     struct CommandLineArgs
     {

src/software/thunderscope/binary_context_managers/full_system.py

@@ -11,6 +11,7 @@
 from software.python_bindings import *
 from proto.import_all_protos import *
 from software.py_constants import *
+from software.thunderscope.constants import LogLevels
 from software.thunderscope.binary_context_managers.util import is_cmd_running
 
 
@@ -25,6 +26,7 @@ def __init__(
         should_restart_on_crash: bool = True,
         run_sudo: bool = False,
         running_in_realtime: bool = True,
+        log_level: LogLevels = LogLevels.DEBUG,
     ) -> None:
         """Run FullSystem
 
@@ -34,6 +36,7 @@ def __init__(
         :param should_restart_on_crash: whether or not to restart the program after it has been crashed
         :param run_sudo: true if we should run full system under sudo
         :param running_in_realtime: True if we are running fullsystem in realtime, else False
+        :param log_level: Minimum g3log level that will be printed (DEBUG|INFO|WARNING|FATAL)
         """
         self.full_system_runtime_dir = full_system_runtime_dir
         self.debug_full_system = debug_full_system
@@ -42,6 +45,7 @@ def __init__(
         self.should_restart_on_crash = should_restart_on_crash
         self.should_run_under_sudo = run_sudo
         self.running_in_realtime = running_in_realtime
+        self.log_level = log_level
 
         self.thread = threading.Thread(target=self.__restart__, daemon=True)
 
@@ -61,10 +65,13 @@ def __enter__(self) -> FullSystem:
         except:
             pass
 
-        self.full_system = "software/unix_full_system --runtime_dir={} {} {}".format(
-            self.full_system_runtime_dir,
-            "--friendly_colour_yellow" if self.friendly_colour_yellow else "",
-            "--ci" if not self.running_in_realtime else "",
+        self.full_system = (
+            "software/unix_full_system --runtime_dir={} {} {} --log_level={}".format(
+                self.full_system_runtime_dir,
+                "--friendly_colour_yellow" if self.friendly_colour_yellow else "",
+                "--ci" if not self.running_in_realtime else "",
+                self.log_level.value,
+            )
         )
 
         if self.should_run_under_sudo:

src/software/thunderscope/constants.py

@@ -1,7 +1,7 @@
 from pyqtgraph.Qt import QtGui
 from OpenGL.GL import *
 from proto.import_all_protos import *
-from enum import Enum, IntEnum
+from enum import Enum, IntEnum, StrEnum
 from proto.robot_log_msg_pb2 import LogLevel
 
 import textwrap
@@ -377,3 +377,12 @@ class ProtoPlayerFlags(Enum):
 
     NO_ERROR_FLAG = 0
     UNCAUGHT_EXCEPTION_FLAG = 1 << 0
+
+
+class LogLevels(StrEnum):
+    """Log levels for FullSystem to indicate minimum logged level"""
+
+    DEBUG = "DEBUG"
+    INFO = "INFO"
+    WARNING = "WARNING"
+    FATAL = "FATAL"

src/software/thunderscope/thunderscope_main.py

@@ -25,7 +25,7 @@
 from software.thunderscope.estop_helpers import get_estop_config
 from software.thunderscope.proto_unix_io import ProtoUnixIO
 import software.thunderscope.thunderscope_config as config
-from software.thunderscope.constants import CI_DURATION_S
+from software.thunderscope.constants import CI_DURATION_S, LogLevels
 from software.thunderscope.util import *
 
 from software.thunderscope.binary_context_managers.full_system import FullSystem
@@ -98,6 +98,14 @@
         default=False,
         help="Visualize C++ Tests",
     )
+    parser.add_argument(
+        "--log_level",
+        action="store",
+        help="Minimum g3log level for full_system logs",
+        choices=[level for level in LogLevels],
+        default=LogLevels.DEBUG,
+        type=LogLevels,
+    )
     parser.add_argument(
         "--blue_log",
         action="store",
@@ -359,6 +367,7 @@
                     friendly_colour_yellow=friendly_colour_yellow,
                     should_restart_on_crash=True,
                     run_sudo=args.sudo,
+                    log_level=args.log_level,
                 ) as full_system:
                     full_system.setup_proto_unix_io(current_proto_unix_io)
 
@@ -432,13 +441,15 @@ def __ticker(tick_rate_ms: int) -> None:
             should_restart_on_crash=False,
             run_sudo=args.sudo,
             running_in_realtime=(not args.ci_mode),
+            log_level=args.log_level,
         ) as blue_fs, FullSystem(
             full_system_runtime_dir=args.yellow_full_system_runtime_dir,
             debug_full_system=args.debug_yellow_full_system,
             friendly_colour_yellow=True,
             should_restart_on_crash=False,
             run_sudo=args.sudo,
             running_in_realtime=(not args.ci_mode),
+            log_level=args.log_level,
         ) as yellow_fs, Gamecontroller(
             suppress_logs=(not args.verbose),
         ) as gamecontroller, (

src/software/unix_full_system_main.cpp

@@ -4,6 +4,7 @@
 #include <filesystem>
 #include <iostream>
 #include <numeric>
+#include <optional>
 
 #include "proto/message_translation/ssl_wrapper.h"
 #include "proto/parameters.pb.h"
@@ -45,6 +46,33 @@ void cleanup(int signal_num)
     exit(0);
 }
 
+/**
+ * Parses a string into a LEVELS enum value of DEBUG, INFO, WARNING, or FATAL.
+ * If the log level is not recognised, returns std::nullopt
+ *
+ * @param log_level The log level argument as a string
+ */
+std::optional<LEVELS> parseLogLevel(const std::string& log_level)
+{
+    if (log_level == "DEBUG")
+    {
+        return DEBUG;
+    }
+    else if (log_level == "INFO")
+    {
+        return INFO;
+    }
+    else if (log_level == "WARNING")
+    {
+        return WARNING;
+    }
+    else if (log_level == "FATAL")
+    {
+        return FATAL;
+    }
+    return std::nullopt;
+}
+
 int main(int argc, char** argv)
 {
     // Setup dynamic parameters
@@ -54,6 +82,7 @@ int main(int argc, char** argv)
         std::string runtime_dir     = "/tmp/tbots";
         bool friendly_colour_yellow = false;
         bool ci                     = false;
+        std::string log_level       = "DEBUG";
     };
 
     CommandLineArgs args;
@@ -70,6 +99,9 @@ int main(int argc, char** argv)
     desc.add_options()(
         "ci", boost::program_options::bool_switch(&args.ci),
         "If true, then the World timestamp will be used to as the time provider for ProtoLogger");
+    desc.add_options()(
+        "log_level", boost::program_options::value<std::string>(&args.log_level),
+        "The minimum g3log level that will be printed (DEBUG|INFO|WARNING|FATAL)");
 
     boost::program_options::variables_map vm;
     boost::program_options::store(parse_command_line(argc, argv, desc), vm);
@@ -91,6 +123,15 @@ int main(int argc, char** argv)
             TracySetProgramName("Thunderbots: Yellow");
         }
 
+        std::optional<LEVELS> minimum_log_level = parseLogLevel(args.log_level);
+
+        if (!minimum_log_level.has_value())
+        {
+            std::cout << "error: --log_level=" << args.log_level
+                      << " is not a valid option." << std::endl;
+            return 1;
+        }
+
         std::function<double()> time_provider;
         if (!args.ci)
         {
@@ -110,7 +151,8 @@ int main(int argc, char** argv)
         }
         proto_logger = std::make_shared<ProtoLogger>(args.runtime_dir, time_provider,
                                                      args.friendly_colour_yellow);
-        LoggerSingleton::initializeLogger(args.runtime_dir, proto_logger);
+        LoggerSingleton::initializeLogger(args.runtime_dir, proto_logger, true,
+                                          *minimum_log_level);
         TbotsProto::ThunderbotsConfig tbots_proto;
 
         // Override friendly color