LoggingSystem

• Requirement analysis
• Proposed solution
• User manual
  • Logging API
  • How to trace / log information
  • Logger settings
  • The "Default" logger

Requirement analysis

As a SD developer, when debugging the code or data, we very often need to follow up with more or less accuracy the progress of SD execution, about the whole game or only some specific component.

As a SD maintainer, getting asked to analyse and fix bugs reported by our end-users, we also need to know more or less precisely what happened before the notified bug in order to try and repeat it (end-users often forget important details when reporting bugs).

From the above, we clearly see that this need often changes, as the issue to examine and analyse changes :

• along the component axis : we often need to concentrate on a limited set of game components, and thus to ignore the other ones, because we already have some idea of where the issue is located,
• along the criticity or level of detail axis : concentrating on 1 or 2 specific components doesn't mean that we don't need to follow up, at least at a high level, what's happening in the others ; in a given component, the "events" to follow-up can be sorted into multiple criticity levels or levels of detail.

And so that we need to be able to filter the events / follow-up information along these 2 axis taken independently.

Proposed solution

A good old answer to this need is to set up a logging API, enabling the developer to log the useful follow-up information / events as textual messages into an output stream (aka the printf design pattern ;-).

In order to ship the above-described multi-axis filtering features, each tracing / logging "functions" must enable the developer to specify :

• the criticity level of the logged information,
• the component to which the logged information is related,
• the target output stream,
• of course, the logged information, as a textual message (we'll use the printf formatting model, for it's ease of use) :-)

Note: A component here can be taken as a real one in the application : a module, a library, ... But we can also extend the concept to any "code geography" object that we'd need to filter information (example : a specific car in the game, as a cross-real-component object).

And as SD is a multi-threaded software, each logged event / information must at least be time-stamped (to get an idea of the order of operations).

At run-time, the developer must be able to specify, in a simple manner, and without recompiling any code (through an XML configuration file),

• separately for each targeted component,
• the criticity level threshold : information with a lower one will not actually be output to the target stream.

Through a simple trick, this criticity level threshold allows the developer to filter the traces along the 2 requested axis : of course the criticity level itself, but also the component axis (a criticity level threshold higher that the maximum ... actually completely inhibits output for the specified component).

The API must also enable the developer to specify by code the filtering settings for each component : as default ones, or simply for changing values when needed while the game is running.

Being able to customise output formatting would be also good.

We'll use the logger concept :

• a logger is an object dedicated to logging information to a specific output stream (or may be multiple ones if needed),
• it features :
  • a name, that can be used to identify the component to follow-up (or any such "code geography" object for filtering),
  • a criticity level threshold,
  • a target output stream (stdout, stderr, or a text file), and may be multiple ones,
  • possibly other data driving the output formatting ... etc.

User manual

Logging API

The logging system is mainly implemented through the GfLogger? class (source:trunk/src/libs/tgf/tgf.h) ; here's a sum-up of it's public API :

class TGF_API GfLogger
{
 public:

    //! Trace level / criticity : enum or integer if > eDebug (ascending level means descending criticity).
    enum { eFatal = 0, eError, eWarning, eInfo, eTrace, eDebug };

    //! Change criticity level threshold.
    void setLevelThreshold(int nLevel);

    //! Change output lines header columns selection.
    enum { eNone=0, eTime=0x01, eLogger=0x02, eLevel=0x04, eAll=eTime|eLogger|eLevel };
    void setHeaderColumns(unsigned bfHdrCols);

    //! Change output stream ("stdout" or "stderr" or a file name).
    void setStream(const std::string& strPathname);

    //! Tracing functions (name gives the trace level / criticity).
    void fatal(const char *pszFmt, ...); // Warning : This one calls exit(1) at the end !
    void error(const char *pszFmt, ...);
    void warning(const char *pszFmt, ...);
    void info(const char *pszFmt, ...);
    void trace(const char *pszFmt, ...);
    void debug(const char *pszFmt, ...);

    //! Generic tracing function (you must specify the level, enum or integer if > eDebug).
    void message(int nLevel, const char *pszFmt, ...);

    //! Instance getter (you can't readily instanciate loggers).
    static GfLogger* instance(const std::string& name);
};

Note that it is only a sum-up : there are other methods useful for run-time logging configuration (and of course other "technical" ones you can ignore as a "simple" user).

How to trace / log information

To log an information in the code of a specific component, you simply have to use one of the "tracing" functions above (fatal, error, warning, info, ... etc), and of course the logger instance that is dedicated to the component to follow-up.

First example, not recommended (the one-line way ; easy but : verbose syntax, not very efficient at run-time) :

// Needs a '#include <tgf.h>' line above !
GfLogger::instance("MyLogger")->info("Something interesting happened (x=%d, y=%d, name=%s)\n", x, y, name);

Second example = the recommended way (shorter syntax, the most efficient at run-time ; but : a bit more code) :

1. Declare the logger instance in some .h file of the component to follow-up (let's say "MyComponentTools.h") :

   // Needs a '#include <tgf.h>' line above !
   extern GfLogger* PMyLog;
   #define MyLog (*PMyLog)
   

2. Define the logger instance in some .cpp source file of the component (whatever) :

   // Needs a '#include "MyComponentTools.h"' line above !
   GfLogger* PMyLog = GfLogger::instance("MyLogger");
   

3. Log events / information where needed in the code

   // Needs a '#include "MyComponentTools.h"' line above !
   MyLog.info("Something interesting happened (x=%d, y=%d, name=%s)\n", x, y, name);
   

That way (nothing more needed), you should already see your trace line in the game console while running it (provided that your trace line added in the code is on the way :-).

Logger settings

Now, as you probably noticed, you never called the new operator for your "MyLogger?" logger, and you never specify it's criticity level threshold ; it's because :

• the GfLogger? class instantiate itself the loggers, at start-up or when it's "instance" static method is called,
• at game startup, the GfLogger? class reads the <user settings>/config/logging.xml file in order to instantiate and configure the thus-declared loggers (name, start-up criticity level threshold, start-up output stream, start-up trace lines header columns).

If your logger is not declared in <user settings>/config/logging.xml, no problem : it'll get default settings when automatically instantiated (criticity level threshold = debug, output stream = stderr, all header columns).

If you don't like these default settings, simply add a section for your logger in <user settings>/config/logging.xml.

Note: When specifying a file as the target stream, only specify its name (no path supported) ; it'll then be re-created at each game start-up in the <user settings> folder.

And at any time in the code, when relevant, you can even override these settings through the setLevelThreshold, setStream and setHeaderColumns methods.

The "Default" logger

Mainly for backward compatibility reasons, the logging system automatically creates a default logger, named "Default" ; it serves as :

• the logger hidden behind the legacy logging functions : GfLogFatal, GfLogError, GfLogWarning, GfLogInfo, GfLogTrace, GfLogDebug and GfLogMessage (they are used everywhere in the code, and might / should be less in the future, as we move the code to the new API, using this "Default" logger instance),
• the logger for logging things that happens before the logger settings are loaded from <user settings>/config/logging.xml,
• the legitimate logger for the base gaming framework, that is the tgf library.

It is exported by the tgf library, as the GfLogDefault logger instance, so you can use it this way, as an example :

// Needs a '#include <tgf.h>' line above !
GfLogDefault.debug("Something interesting happened (x=%d, y=%d, name=%s)\n", x, y, name);

which does exactly the same as the now deprecated :

// Deprecated : use GfLogDefault.debug !
// Needs a '#include <tgf.h>' line above !
GfLogDebug("Something interesting happened (x=%d, y=%d, name=%s)\n", x, y, name);

Unlike other loggers, the default logger is initialised through 2 separated steps :

• at application start-up (GfApplication::initialise), as soon as possible, it is instantiated and configured with default settings (the trace level threshold is defined through the CMake options OPTION_TRACE_LEVEL, defaulting to debug=5 ; the target stream is stderr by default),
• later, when the command line options have been parsed (GfApplication::parseOptions), it is configured with the settings read from <user settings>/config/logging.xml.

And these "XML settings" can also be overridden through the command line, when using the -e/--tracelevel and -t/-tracestream switches (use the -h switch to get help about these).