New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add named loggers with individually controlled log levels. #1481

Merged
merged 20 commits into from May 12, 2017

Conversation

Projects
5 participants
@LGM-Doyle
Contributor

LGM-Doyle commented Apr 10, 2017

Merge Message

Adds named loggers with individually controlled log levels.

Motivation

There are currently several different ways to control which log messages are generated and printed in the log files

  • a command-line option --log-level that sets the log level for all log messages.
  • a verbose-combat-logging option in OptionsDB that gates logging of detailed combat mechanics and the combat log window.
  • a verbose-logging option in OptionsDB that gates combat and effects processing logging and other miscellaneous locations.
  • a compiled in option TRACE_EXECUTION used to gate logging in the networking and finite state machine (FSM) code.

These can be configured/toggled from the following locations.

Method Command line config.xml, persistent_config.xml OptionsWnd compiler only
log-level X X
verbose-logging X X X
verbose-combat-logging X X X
TRACE_EXECUTION X

Goal

This PR creates a consistent system where it is easy to create/remove named loggers for specific sections of code that can be configured from the command-line, or OptionsDB or the OptionWnd at runtime.

Usage

The default logger works the same as before.

Create a new named logger.

    CreateThreadedLogger(name_of_logger);

Create a log message.

    ErrorLogger(name_of_logger) << "any streamable output, only computed "
                                << "at the error threshold or greater "
                                << "for the 'name_of_logger' logger.";
    WarnLogger(name_of_logger)  << "streamable output";
    InfoLogger(name_of_logger)  << "streamable output";
    DebugLogger(name_of_logger) << "streamable output";
    TraceLogger(name_of_logger) << "streamable output";

The XLogger(name_of_logger) << is a macro that gates computation of everything to the right of the stream operator (<<) based on the runtime threshold of the specific logger. So providing that all of the work assembling the log message is in functions to the right of the stream operator (<<) no work will be done for log messages that would not be printed in the log outputs.

(Optionallly) Set the log threshold in config.xml/persistent_config.xml

  <logging>
    <sources>
      <name_of_logger>warn</name_of_logger>
    </sources>
  </logging>

(Optionally) Set the log threshold from the OptionsWnd with the Other/Logging/Log threshold for individual sources/name_of_logger drop down list.

(Optionally) Override each executables defaut logger to specific log levels in config.xml/persistent_config.xml.

  <logging>
    <execs>
      <ai>warn</ai>
      <client>debug</client>
      <server>trace</server>
    </execs>
  </logging>

(Optionally) Override each executables default logger to specific log levels from the OptionsWnd with the Other/Logging/Log threshold for default logger for process/<ai/client/server> drop down list.

(Optionally) Override all individual loggers of all executables log levels with the command-line/OptionsDB option

--log-level <error/warn/debug/info/debug/trace>

Changes in this PR.

The changes are in three steps: refactor Logger to allow names loggers, add ability to set logger thresholds from OptionsWnd, replace the various detailed loggers with the new named loggers.

Additional Notes

  • Adds a dependency on boost log_setup.
  • Splits logger OptionsDB dependency into LoggerWOptionsDB so that logger is more suitable for a testing environment and doesn't need to pull in the entire OptionsDB framework.
  • Moves year/month/day from each log line to the head of file to make space for more relevant information.
  • OptionsDB now dumps messages about unrecognized options to the console because they are initialized during static initialization before the logger backend is configured. I left those as is, so that this PR didn't change the intent of any log messages. The messages should be changed as the current usage of OptionsDB no longer agrees with the expectation that all options be present and accounted for at static initialization.
@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle Apr 12, 2017

Contributor

It now compiles on OSX and Windows, as well as the original linux.

It needs testing on those OSs, because OSX and particularly Windows required additional coding.

Testing is as follows:

  • quickstart a game
  • check that a log file has generated some log messages
  • go to OptionsWnd/Other/Logging and change some options to generate more/fewer log reports.
  • check in the log file that the log reports you expected to be present/absent are present/absent.

Thanks in advance for your testing time.

Contributor

LGM-Doyle commented Apr 12, 2017

It now compiles on OSX and Windows, as well as the original linux.

It needs testing on those OSs, because OSX and particularly Windows required additional coding.

Testing is as follows:

  • quickstart a game
  • check that a log file has generated some log messages
  • go to OptionsWnd/Other/Logging and change some options to generate more/fewer log reports.
  • check in the log file that the log reports you expected to be present/absent are present/absent.

Thanks in advance for your testing time.

@geoffthemedio

This comment has been minimized.

Show comment
Hide comment
@geoffthemedio

geoffthemedio Apr 12, 2017

Member

This seems overly complicated to me... In particular, are 5 log levels really necessary?

I find the lambda function syntax for controlling whether to evaluate stuff to log particularly clunky / awkward. A simple if block seems preferable. Can this be easily integrated with the named loggers, perhaps to poll whether a particular named logger has a particular log level?

The pull request is another huge one, which is difficult to review. Can you break it into smaller chunks?

Member

geoffthemedio commented Apr 12, 2017

This seems overly complicated to me... In particular, are 5 log levels really necessary?

I find the lambda function syntax for controlling whether to evaluate stuff to log particularly clunky / awkward. A simple if block seems preferable. Can this be easily integrated with the named loggers, perhaps to poll whether a particular named logger has a particular log level?

The pull request is another huge one, which is difficult to review. Can you break it into smaller chunks?

@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle Apr 12, 2017

Contributor

I will start start breaking it into smaller chunks.

In particular, are 5 log levels really necessary?

@dbenage-cx provided two external discussions on levels of logging in the forum

I think that at least 4 levels are necessary.

We should have 2 levels of problem log messages, error and warning. Errors are a notice to the devs that something should be fixed in the code. (Ideally) there should be no errors in released code. Warnings are a notice to the user that something is in a downgraded state, like a missing sound system.

We need at least 2 levels of progress/state log messages for developers, debug and trace. This distinction is already apparent in the existing code with verbose-logging, verbose-combat-logging and TRACE_EXECUTION. Collapsing these two levels into one level would mean that when debugging the network code the options are no logs, or many logs messages per exchange between the client and the server.

Can this be easily integrated with the named loggers, perhaps to poll whether a particular named logger has a particular log level?

No it can't be done easily. It would involve replicating parts of the boost::logging API macros to extract that state from the backend. It would be dependent on internals of boost::logging and consequently be brittle.

However, most of the lamda functions are in the trace logging of the effects code. Most are only preventing unnecessary iteration over some set, when there will be no log generated. They can be removed.

Contributor

LGM-Doyle commented Apr 12, 2017

I will start start breaking it into smaller chunks.

In particular, are 5 log levels really necessary?

@dbenage-cx provided two external discussions on levels of logging in the forum

I think that at least 4 levels are necessary.

We should have 2 levels of problem log messages, error and warning. Errors are a notice to the devs that something should be fixed in the code. (Ideally) there should be no errors in released code. Warnings are a notice to the user that something is in a downgraded state, like a missing sound system.

We need at least 2 levels of progress/state log messages for developers, debug and trace. This distinction is already apparent in the existing code with verbose-logging, verbose-combat-logging and TRACE_EXECUTION. Collapsing these two levels into one level would mean that when debugging the network code the options are no logs, or many logs messages per exchange between the client and the server.

Can this be easily integrated with the named loggers, perhaps to poll whether a particular named logger has a particular log level?

No it can't be done easily. It would involve replicating parts of the boost::logging API macros to extract that state from the backend. It would be dependent on internals of boost::logging and consequently be brittle.

However, most of the lamda functions are in the trace logging of the effects code. Most are only preventing unnecessary iteration over some set, when there will be no log generated. They can be removed.

@dbenage-cx

This comment has been minimized.

Show comment
Hide comment
@dbenage-cx

dbenage-cx Apr 12, 2017

Member

Briefly checked this PR earlier, really like some of the changes.

If nothing else changes, please set the default severity of effects to Info (or change many to trace). I only played to ~turn 34 with default severities and freeorion.log was >655MB.

No config option for combat_log is present in config.xml unless set at command line/persistent config.
Would prefer that any options always have a config entry.

Member

dbenage-cx commented Apr 12, 2017

Briefly checked this PR earlier, really like some of the changes.

If nothing else changes, please set the default severity of effects to Info (or change many to trace). I only played to ~turn 34 with default severities and freeorion.log was >655MB.

No config option for combat_log is present in config.xml unless set at command line/persistent config.
Would prefer that any options always have a config entry.

@adrianbroher

This comment has been minimized.

Show comment
Hide comment
@adrianbroher

adrianbroher Apr 12, 2017

Contributor

The XLogger(name_of_logger) << is a macro that gates computation of everything to the right of the stream operator (<<) based on the runtime threshold of the specific logger.

Did you check if this is actually true?

http://www.boost.org/doc/libs/1_59_0/libs/log/doc/html/log/rationale/why_not_lazy_streaming.html

Further remarks after the PR was shrinked to a consumable size.

Contributor

adrianbroher commented Apr 12, 2017

The XLogger(name_of_logger) << is a macro that gates computation of everything to the right of the stream operator (<<) based on the runtime threshold of the specific logger.

Did you check if this is actually true?

http://www.boost.org/doc/libs/1_59_0/libs/log/doc/html/log/rationale/why_not_lazy_streaming.html

Further remarks after the PR was shrinked to a consumable size.

@dbenage-cx

This comment has been minimized.

Show comment
Hide comment
@dbenage-cx

dbenage-cx Apr 12, 2017

Member

@adrianbroher I believe the wording there suggests that packet.size() would always be called only if "lazy streaming" was implemented and done so without additional work.

The first doc mention I see confirming this is the note at http://www.boost.org/doc/libs/1_59_0/libs/log/doc/html/log/tutorial/trivial_filtering.html

In practice, this diff(print to console when sound enabled) also appears to exhibit the functionality described by LGM-Doyle.

Member

dbenage-cx commented Apr 12, 2017

@adrianbroher I believe the wording there suggests that packet.size() would always be called only if "lazy streaming" was implemented and done so without additional work.

The first doc mention I see confirming this is the note at http://www.boost.org/doc/libs/1_59_0/libs/log/doc/html/log/tutorial/trivial_filtering.html

In practice, this diff(print to console when sound enabled) also appears to exhibit the functionality described by LGM-Doyle.

@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle Apr 13, 2017

Contributor

Thanks everyone for the comments. I'm working on the fixes and the split.

@dbenage-cx I changed the effects priority to trace. It should have been trace, but I had removed the info level and bumped the effects logs up to debug while considering what the "right" number of levels was.

I'm working on the combat_log logger not appearing in the config.xml file.

@adrianbroher I think @dbenage-cx's example is a perfect answer to your question.

I now plan to do some "playtesting" of the release candidate.

Contributor

LGM-Doyle commented Apr 13, 2017

Thanks everyone for the comments. I'm working on the fixes and the split.

@dbenage-cx I changed the effects priority to trace. It should have been trace, but I had removed the info level and bumped the effects logs up to debug while considering what the "right" number of levels was.

I'm working on the combat_log logger not appearing in the config.xml file.

@adrianbroher I think @dbenage-cx's example is a perfect answer to your question.

I now plan to do some "playtesting" of the release candidate.

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 24, 2017

Add a build type dependent default log threshold.
The default Release build type threshold is info.
The default Debug build type threshold is debug.

Based on discussions in review freeorion#1481.

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 24, 2017

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 24, 2017

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 24, 2017

In Universe and Effect code flatten some lambdas used for logging.
For review freeorion#1481.

This trades code clarity for an unnecessary iteration over a set.

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 24, 2017

@LGM-Doyle LGM-Doyle added this to Pull Requests in Improve Logging Apr 24, 2017

@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle Apr 24, 2017

Contributor

I've now broken this up into multiple parts.

This PR is now the last part.

This PR replaces the various other verbose or trace logging methods with a named TraceLogger(<a_name>)

It follows the core implementation #1529.

Merge Message
Replace other verbose or trace logging methods with a TraceLogger(a_name).

Contributor

LGM-Doyle commented Apr 24, 2017

I've now broken this up into multiple parts.

This PR is now the last part.

This PR replaces the various other verbose or trace logging methods with a named TraceLogger(<a_name>)

It follows the core implementation #1529.

Merge Message
Replace other verbose or trace logging methods with a TraceLogger(a_name).

@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle Apr 24, 2017

Contributor

I can see that the clang build is failing. I will work on that.

Contributor

LGM-Doyle commented Apr 24, 2017

I can see that the clang build is failing. I will work on that.

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 26, 2017

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 26, 2017

LGM-Doyle added a commit to LGM-Doyle/freeorion that referenced this pull request Apr 26, 2017

In Universe and Effect code flatten some lambdas used for logging.
For review freeorion#1481.

This trades code clarity for an unnecessary iteration over a set.

LGM-Doyle added some commits Mar 24, 2017

Replace human and server TRACE_EXECUTION with logger named "FSM".
Also converted the debug and error messages to the "FSM" channel.
In Universe and Effect code flatten some lambdas used for logging.
For review #1481.

This trades code clarity for an unnecessary iteration over a set.
In HumanClientApp make long term loggers always appear in config.xml.
Loggers are lazy and they are only added to config.xml on first use.
This commit manually adds the "standard" loggers, so that they will
always appear in config.xml.
Rename CreateThreadedLogger to DeclareThreadSafeLogger.
This clarifies that a) the logger is thread safe and b) that the macro
is a declaration.
Change Options Log tab to label per process loggers as general.
This commit removes the separate sections for per process loggers and
detailed channel loggers and replaces the distinction with by
designating the per process loggers as general.

It updates the string table accordingly.

It is based on feedback from review #1481.
@LGM-Doyle

This comment has been minimized.

Show comment
Hide comment
@LGM-Doyle

LGM-Doyle May 12, 2017

Contributor

I've converted it as requested. I left the labels in the log themselves as ai, server and client.

Contributor

LGM-Doyle commented May 12, 2017

I've converted it as requested. I left the labels in the log themselves as ai, server and client.

@geoffthemedio geoffthemedio merged commit 346d7e6 into freeorion:master May 12, 2017

2 checks passed

continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details

@LGM-Doyle LGM-Doyle deleted the LGM-Doyle:add_detailed_logging branch May 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

Add a build type dependent default log threshold.
The default Release build type threshold is info.
The default Debug build type threshold is debug.

Based on discussions in review freeorion#1481.

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

Workaround static de-initialization crashes in boost::log.
There are two problems with static de-initialization in boost::log.

The first is that boost::log uses boost::filesystem to log to files.
boost::filesystem uses a static std::locale object.  There is no way to
influence the order of static de-initialization. Intermittently during
static de-initialization boost::log crashes while flushing the file.

This bug is described in:
http://www.boost.org/doc/libs/1_64_0/libs/log/doc/html/log/rationale/why_crash_on_term.html
https://svn.boost.org/trac/boost/ticket/8642
https://svn.boost.org/trac/boost/ticket/9119

The second bug was reported in PR freeorion#1481.

During static de-initialization boost::log exhausts the thread local
storage (TLS) and crashes.

The solution in this commit, is to close the log file before the start
of static de-initialization at the end of main().  Any remaining logs
will be logged to the console.

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

In Universe and Effect code flatten some lambdas used for logging.
For review freeorion#1481.

This trades code clarity for an unnecessary iteration over a set.

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

MatGB added a commit to MatGB/freeorion that referenced this pull request Aug 15, 2017

Change Options Log tab to label per process loggers as general.
This commit removes the separate sections for per process loggers and
detailed channel loggers and replaces the distinction with by
designating the per process loggers as general.

It updates the string table accordingly.

It is based on feedback from review freeorion#1481.
if (!accounting_map && !log_verbose) {

This comment has been minimized.

@geoffthemedio

geoffthemedio Mar 3, 2018

Member

Changing if (!accounting_map && !log_verbose) to just if (!accounting_map) means that the following else if (!accounting_map) case will never execute. Something doesn't make sense here...

@geoffthemedio

geoffthemedio Mar 3, 2018

Member

Changing if (!accounting_map && !log_verbose) to just if (!accounting_map) means that the following else if (!accounting_map) case will never execute. Something doesn't make sense here...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment