Revamping the entire logging system and message output

[bcoconni]

Yeah, the following is an extremely long description, but this pull request, once approved, will impact nearly every aspect of the code related to logging and message output. Therefore, I've opted for a detailed explanation to ensure the rationale is transparent and the outcomes of this change are unanimously accepted.

The description below was crafted with the assistance of Copilot AI, which has hopefully written my thoughts more clearly than I could have. The structure and delivery of the discussion are entirely of my own design. Copilot AI has merely assisted with each paragraph individually. Any errors in English are a combination of both Copilot's and my own.

So, grab a coffee, make yourself comfortable, and let's get started.

The problem

Following issue #578 and PR #1092, it is evident that the JSBSim method of output logging is not very flexible. JSBSim currently channels all its outputs — such as results, information, debugging, errors, etc. — directly to the console, providing limited filtering options. There are several drawbacks to the current state of affairs:

• Not all users prefer JSBSim output logged to the console. Issue Support SimGear logging #578 exemplifies this, and a similar concern may exist for our Unreal Engine plugin for which it might be more appropriate to log JSBSim output directly within the Unreal Engine's graphical interface. While there are methods to redirect console output, they tend to be cumbersome and result in a large block of text that is hard to decipher.

• Currently, the sole method to control JSBSim verbosity is by setting a cryptic value to the global variable debug_lvl. However, this approach presents several issues:

  • Global variables impact all JSBSim instances and can produce unexpected results in a multithreaded environment (refer to issue Support for run JSBSim instance in multi-thread environment #666).

  • Since debug_lvl is the only mechanism to filter output messages, it is prone to overuse (as observed in the recent PR Reduce console output when debug level is zero #1092, which aims to suppress some warning messages). A single variable does not offer the granularity of filtering that may be required.

• Another minor issue is the inconsistency in message formatting, such as the use of red, bold, underlining, etc., as well as the varying number of line breaks before and after a message.

Proposed solution

Changes for JSBSim users

The present PR introduces a new class, FGLogger, which is registered with FGFDMExec. The concept is to route each message from JSBSim to the FGLogger class instead of directly to the console. By default, for backward compatibility, JSBSim will use a subclass FGLogConsole, derived from FGLogger, to write messages to the console.

But should a user wish to manage messages differently, they could write a subclass of FGLogger and register it with FGFDMExec. For example, in response to issue #578, the FlightGear team might implement a class that outputs messages via the SG_LOG interface.

Design of FGLogger

Firstly, I'm not quite satisfied with the name FGLogger, so please feel free to suggest an alternative. What about FGLogReporter ?

The FGLogger API is intended to be fairly self explanatory. I will delve into the details below as this class will be essential for some JSBSim users, and I would appreciate feedback to ensure its design is making sense.

• The SetLevel method is invoked whenever JSBSim issues a new message, indicating the message severity level (info, debug, warning, error, etc.). This method serves as the signal for the "beginning of transmission".

• The Message method is invoked when the message itself is transmitted. This method might be called several times for a given message due to the way JSBSim builds some messages (by using a for loop for instance).

• The Format method is invoked when JSBSim formats the output message, which may include styles like bold, underline, or colored text. The parameter passed to this method signifies the formatting intention (for example, LogFormat::RED indicates red text). It's the responsibility of the class developer to decide how to implement this formatting for their specific scenario. In most cases, this method might simply be overlooked. Its actual purpose is to maintain backward compatibility, enabling the FGLogConsole class to exhibit formatted text in the same manner as JSBSim currently does.

• The Flush method is called to indicate the "end of transmission." At this point, the class developer can format or parse the message, append a timestamp, etc., then output the finalized message via their application interface. It is in this method that the class developer may trigger the opening of a window to show an error message and request user feedback, such as "Ok" or "Cancel."

• The FileLocation method is used to link a message with a file, typically an XML file. It is invoked immediately following the SetLevel method, and prior to the invocation of the Message or Format methods. FileLocation receives the file name and the line number where the event occurred. This method gives the class developer the option to present the raw information, such as the file name and line number, or to provide a more detailed message that includes the context of the event, such as displaying the lines surrounding the line in question.

• At present, the SetMinLevel method serves as a placeholder. Its function is to offer a straightforward approach to filter messages by severity level, for instance, ignoring all messages below LogLevel::ERROR. The inclusion of this method in the top-level class FGLogger, which all others will inherit, is a matter of debate. My inclination is that the filtering logic should be handled at lower levels in the hierarchy, suggesting that FGLogger should refrain from imposing any particular filtering standards, thereby implying that SetMinLevel ought to be removed.

Message severity

The message severity levels included in this PR essentially replicate those of FlightGear:

enum class LogLevel {
  BULK,  // For frequent messages
  DEBUG, // Less frequent debug type messages
  INFO,  // Informatory messages
  WARN,  // Possible impending problem
  ERROR, // Problem that can be recovered
  FATAL  // Fatal problem => an exception will be thrown
};

Granularity can be adjusted in the future, but currently, this list provides a solid foundation.

Changes for developers of JSBSim

To redirect messages to the FGLogger class, all instances of cout and cerr should be substituted with a log variable, which will be detailed further below. The goal is for log to be used in a manner that's very similar, if not identical, to cout and cerr. This means a line of code like

cout << "This is an error message with code " << error_code << endl;

would be changed to

log << "This is an error message with code " << error_code << endl;

Design of FGLogging

In this pull request, the log variable is an instance of the new FGLogging class. To invoke FGLogger::SetLevel and FGLogger::Flush as described above, the approach is to employ RAII:

• The constructor of FGLogging accepts an FGLogger instance and a severity level to execute FGLogger::SetSeverity and indicate the start of transmission.
• The destructor of FGLogging executes FGLogger::Flush to indicate the end of transmission.

It's important to note that this strategy necessitates declaring the log variable prior to each message output. This declaration should be confined to the narrowest scope possible, ensuring the destruction (and subsequent call to FGLogger::Flush()) occurs immediately after the message is finalized:

{
  FGLogging log(Log, LogLevel::ERROR);
  log << "Something has gone wrong." << endl;
}

The use of brackets is crucial in RAII as they initiate the FGLogger::Flush() call. In addition, this requires an additional line of code relative to cout and cerr. To me, this appears to be a reasonable compromise, especially since it offers a method to specify the message severity, though views on this may vary.

The drawback of this approach is the vigilance it demands from the developer concerning the scope, that is, the placement of brackets, to ensure messages are flushed upon completion. Fortunately, in most instances, the output messages are already enclosed within narrowly scoped brackets, in statements like if (value == bad) { display error message }.

Design of FGXMLLogging

The FGXMLLogging class is nearly identical to its parent FGLogging, with the key distinction being an added Element* parameter utilized to invoke FGLogger::FileLocation.This class replaces FGLogging to create the log variable when the message linked to an XML file:

if (!el->HasAttribute("awesome_parameter"))
{
  FGXMLLogging log(Log, el, LogLevel::ERROR);
  log << "<awesome_parameter> is missing." << endl;
}

The FGXMLLogging class is responsible for extracting the file name and line number from el and passing them to FGLogger::FileLocation.

Scope of this pull request

The present PR introduces the aforementioned classes and integrates them solely within the FGFDMExec class. Given that this approach utilizes the backward-compatible FGLogConsole class, there's no pressing need to apply the modifications throughout the entire codebase. Initially, we can deliberate and refine the design on a smaller scale prior to extending the changes throughout JSBSim.

Open topics

The removal or replacement of the global static variable debug_lvl is not covered in this PR; however, it is my intention to eventually move this variable into the FGLogConsole class. I believe that only FGLogConsole should be aware of this variable, as the rest of the code should not concern itself with message filtering. This is the essence of OOP: to separate concerns. Once debug_lvl is relocated to FGLogConsole, the decision of whether or not it remains a global variable shall be further discussed.

Similarly, the global variables fgred, highint, and similar ones in FGJSBBase should be transferred to FGLogConsole. They should be changed in the process from global static variables to class members variables. Consequently, the FGJSBBase::disableHighLighting method should also be relocated to FGLogConsole.

Additionally, an argument could be added to JSBSim.exe enabling users to choose the level of log messages they wish to see in the console. Similarly, a feature could be implemented in XML scripts to allow for this selection.

[codecov]

Codecov Report

Attention: Patch coverage is 17.64706% with 182 lines in your changes missing coverage. Please review.

Project coverage is 24.94%. Comparing base (e26d03b) to head (b789100).
Report is 2 commits behind head on master.

Files	Patch %	Lines
src/FGFDMExec.cpp	4.72%	141 Missing ⚠️
src/input_output/FGLog.cpp	34.69%	32 Missing ⚠️
src/input_output/FGLog.h	62.50%	9 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #1094      +/-   ##
==========================================
+ Coverage   24.91%   24.94%   +0.02%     
==========================================
  Files         168      170       +2     
  Lines       18108    18235     +127     
==========================================
+ Hits         4511     4548      +37     
- Misses      13597    13687      +90     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[jonsberndt]

This looks like a very well thought out improvement. I like it. Now I'm going to go grab some coffee. :-) Jon

[cbirkhold]

Definite improvement over using debug_lvl 👍

One suggestion: Have a predicate 'is filtered' to be able to avoiding the work of producing log messages that will be ignored/filtered anyways. Currently the code generally checks debug_lvl before incurring the cost of producing log output with the proposed improved system it would be nice to have a similar mechanism.

[seanmcleod]

@bcoconni I had also been thinking very roughly, definitely not at this level of detail, about the logging after @cbirkhold's recent pull request and also because coincidentally I'd been setting debug_lvl recently while looking into the discussion with regards to using JSBSim for checking AHRS algorithms and noticed how verbose it can get.

I'd echo @cbirkhold's comment about avoiding the creation of every log message to then be filtered in terms of the potential performance impact of creating log messages etc. Guess I should really perform a proper test to see what the impact might be, at the moment it's more of a hunch that it might not be insignificant even with all log messages effectively going to /dev/null. Thinking particularly for the use case of using JSBSim not in real-time mode, but while being used for example by reinforcement learning setups etc.

Was trying to think of an elegant way that minimizes the number of extra lines of code that someone wanting to add log messages would need to write, but still uses the RAAI pattern.

Been tinkering with the following, although it does require us to bump up from C++14 to C++17.

int global_level = 2;

class Logger
{
public:
    Logger(int level)
        : _level(level)
    {
    }

    ~Logger()
    {
        std::cout << "~Logger()" << std::endl;
    }

    explicit operator bool() const 
    {
        return _level > global_level;
    }

    void Log(const std::string& message)
    {
        std::cout << message << std::endl;
    }

    static Logger GetLogger(int level)
    {
        return Logger(level);
    }

private:
    int _level;
};


int main()
{
    if (Logger log = Logger::GetLogger(3); log)
    {
        log.Log("Howdy");
    }

    std::cout << "Bye" << std::endl;
}

[agodemar]

Thank you @bcoconni for this detailed explanation. I am definitely OK with this PR

[seanmcleod]

the potential performance impact of creating log messages etc. Guess I should really perform a proper test to see what the impact might be, at the moment it's more of a hunch that it might not be insignificant even with all log messages effectively going to /dev/null.

Okay, so putting my money where my mouth is 😉

So I ran the following 10 times to get an average for different debug levels. In this case there is no output, i.e. output going to the equivalent of /dev/null.

$env:JSBSIM_DEBUG=0
measure-command { .\Release\JSBSim.exe --script=scripts\737_cruise.xml }

Debug Level	Execution Time (s)
0	0.222
1	0.238
2	0.270
9	9.206

And then the following which displays the output to the console.

$env:JSBSIM_DEBUG=0
measure-command { .\Release\JSBSim.exe --script=scripts\737_cruise.xml | out-default }

Debug Level	Execution Time (s)
0	0.258
1	0.397
2	3.116
9	219.744

[bcoconni]

Thanks for the feedback.

Even though the removal of debug_lvl is not the point of this PR, I understand that this scenario should be accounted for in this PR in order to avoid later refactoring.

So I ran the following 10 times to get an average for different debug levels. In this case there is no output, i.e. output going to the equivalent of /dev/null. [...]

OK. This is making the point showing that the cost of building strings even when they are not displayed in the console is not negligible and we cannot rely on FGLogger doing some late filtering. Instead filtering should be processed at the lower possible level in the code to avoid building strings for nothing.

Two scenarios should be considered:

1. The case where an error/warning message is logged to the console. In this situation, logging is enclosed in an if statement and do not involve debug_lvl. In that case, we do not need to add a condition on log.
2. The case where some debug messages are logged to the console. In that case, we want to keep the logging enclosed in a if statement that prevents building strings when the debug logging must be skipped at the user request.

The second case requires the condition to be held by the FGLogging instance and this requires some kind of a factory method as you suggested @seanmcleod.

I'd make some little changes to the code you suggested as I don't think we need a static method nor a global global_level variable for that. The idea is to add a (factory?) method FGLogger::GetLogging() that returns an FGLogging instance that can be later tested as you suggest:

class FGLogger {
  // Keep the implementation as I suggested above

  // New factory method (or sort of)
  FGLogging GetLogging(LogLevel level) {
    if (level > global_level) // Could be a much more complex logic
      return FGLogging(*this, level);
    else
      // return a class that will fail the "if (log)" test
  }
protected:
  LogLevel global_level;
}

Note that global_level is now a member of FGLogger instead of being a global variable.

In the first case described above, we do not need to check the instance returned by FGLogger::GetLogging() as the logging is already enclosed in an if statement that checks the error/warning condition:

  if (value == bad) {
    FGLogging log = Log->GetLogging(LogLevel::ERROR);
    log << "Something bad happened !" << endl;
  }

The only change with respect to my first proposal is that we are replacing a direct call to the FGLogging constructor by a call to the factory method FGLogger::GetLogging.

  if (value == bad) {
-    FGLogging log(Log, LogeLevel::ERROR);
+    FGLogging log = Log->GetLogging(LogLevel::ERROR);
    log << "Something bad happened !" << endl;
  }

In the second case described above, we can use the "if with initializer" feature from C++17 as you mentioned:

  if (FGLogging log = Log->GetLogging(LogLevel::DEBUG); log) {
    log << "Debug message" << endl;
  }

The test on log will fail depending on the class that is returned by FGLogger::GetLogging.

although it does require us to bump up from C++14 to C++17.

I don't think that using C++17 for JSBSim should be a problem: according to this reference, the "if with initializer" feature is supported for some time by all the compilers that we use (i.e. MSVC, gcc and Apple-clang). Also FlightGear has migrated to C++17 for a while.

Let me know what you think about these small adjustments to your proposal.

[seanmcleod]

I'd make some little changes to the code you suggested as I don't think we need a static method nor a global....

@bcoconni feel free to make substantial changes 😉. I probably wasn't clear enough, my example wasn't supposed to be anywhere near a full fledged proposal. It was simply to demonstrate one way of doing filtering, and keeping the number of lines of code that a developer adding a log message would need to write making use of new C++ 17 features to a minimum etc. and I wanted something minimal I could use to test and confirm the syntax, confirm whether temporary objects would be created etc.

Overall I'm happy with your approach.

In terms of C++ 17 I actually tried a test build soon after and came across a compiler error to do with the new C++ 17 std::byte and the use of a byte type in some of the Windows header files.

https://devblogs.microsoft.com/cppblog/c17-features-and-stl-fixes-in-vs-2017-15-3/

[byte] std::byte is enabled by /std:c++17 (and /std:c++latest), but has a fine-grained opt-out macro (_HAS_STD_BYTE can be defined to be 0). This is because given certain patterns of using-directives, it can conflict with the Windows SDK’s headers. This has been reported to the SDK team and will be fixed, but in the meantime the escape hatch is available.

Although mentioned in 2017 it seems the Windows SDK team haven't fixed the issue yet. So I needed to define _HAS_STD_BYTE=0 and then everything compiled fine.

You mentioned FlightGear using C++17 and they also need to include Windows headers, so I took a quick look at their source tree and I see they also define _HAS_STD_BYTE=0.

[bcoconni]

Some further thoughts: I think we can actually merge the PR as it currently is and be able to address the case of debug_lvl later on without having to refactor the current design.

For that we could add some new methods FGLogging::SetVerboseLevel and FGLogger::SetVerboseLevel:

class FGLogging {
public:
  bool SetVerbosityLevel(unsigned int level) { return logger->SetVerbosityLevel(level); }

  // Lots of other things
};

class FGLogger {
public:
  virtual bool SetVerbosityLevel(unsigned int level) = 0;
};

so that debug logging could be using the following C++17 statement:

  if (FGLogging log(Log, LogLevel::DEBUG); log->SetVerbosityLevel(2)) {
    log << "Debug message" << endl;
  }

Note that unlike the design I have suggested above, we wouldn't rely on the copy constructor. Instead when FGLogger::SetVerbosityLevel is called (indirectly) it should return true if the debug info should be logged, false otherwise.

So I think we can push the merge button in the current state of the PR, can't we ? 😃

In terms of C++ 17 I actually tried a test build soon after and came across a compiler error to do with the new C++ 17 std::byte and the use of a byte type in some of the Windows header files.

https://devblogs.microsoft.com/cppblog/c17-features-and-stl-fixes-in-vs-2017-15-3/

[byte] std::byte is enabled by /std:c++17 (and /std:c++latest), but has a fine-grained opt-out macro (_HAS_STD_BYTE can be defined to be 0). This is because given certain patterns of using-directives, it can conflict with the Windows SDK’s headers. This has been reported to the SDK team and will be fixed, but in the meantime the escape hatch is available.

Although mentioned in 2017 it seems the Windows SDK team haven't fixed the issue yet. So I needed to define _HAS_STD_BYTE=0 and then everything compiled fine.

You mentioned FlightGear using C++17 and they also need to include Windows headers, so I took a quick look at their source tree and I see they also define _HAS_STD_BYTE=0.

Indeed, this topic was raised the last time we envisaged upgrading JSBSim to C++17 (see #795 (comment)). It's unfortunate that it has not been fixed in the meantime but we should be able to manage as there are no plans to use std::byte (yet ? 😉).

[seanmcleod]

Some further thoughts: I think we can actually merge the PR as it currently is and be able to address the case of debug_lvl later on without having to refactor the current design.

For that we could add some new methods FGLogging::SetVerboseLevel and FGLogger::SetVerboseLevel:

Yep, looks good from my perspective.