Log Severity Levels

Programmers discuss here anything related to FreeOrion programming. Primarily for the developers to discuss.

Moderator: Committer

Post Reply
Message
Author
dbenage-cx
Programmer
Posts: 389
Joined: Sun Feb 14, 2016 12:08 am

Log Severity Levels

#1 Post by dbenage-cx »

With the two log related PRs (#669, #1481), wanted to address the severity levels in one place.

Some outside discussion on different log severities:
http://stackoverflow.com/questions/2031 ... log-levels
http://stackoverflow.com/questions/7839 ... log-levels

In particular, I like the thought of passing some threshold for each level, so I will list suggestion from least severity.
For final release, I currently would expect the default log level to be Info (for all channels/scopes).
  • Trace From a developer view, this would be the default severity.
    Detailed or high volume info.
  • Debug Limited to a single line and once per operation/function (some leeway could be given here).
    Concisely summarized messages for general debugging.
  • Info Should always be displayed in a final release. Concise and not high volume .
    Informational message.
  • Warn Unexpected result (from another operation) or other issue.
    Recoverable error. Potentially a bug.
  • Error Issue within the current operation/function.
    Unrecoverable error. Definite bug.
Unrecoverable being that unexpected things may happen, not that the client exits.

e.g. We might Warn that a string is being truncated, or where we use the result of functionA and that result was an unexpected value. functionA should issue an Error before returning such a value.

Fatal was excluded, as in #1481 it can likely be rolled into Error for the needs here.

Mostly in line with the comments within #1481. Difference being Info and lower:
LGM-Doyle@#1481 wrote:The intended uses of the levels are:
error - used for "major" unrecoverable errors which will affect game play. Error level issues
need to be fixed. Error level will probably not be turned off unless they are flooding
the logs.
Examples are: the game is about to crash, a string is missing from the stringtable, etc.

warn - used for "minor", recoverable errors that will not affect game play but do indicate a
problem.
For example a missing id that can be ignored, an extra item in a container.

info - used to report normal game state and progress. This should be the default level of
logging. The number of log should be low enought to not floow the logs.
For example reporting that the network connected/disconnected.

debug - used for low-level implementation or calculation details. For a named logger this
level will probably only be turned on by devs working on that
section of code. This will be detailed and perhaps voluminous.
For example reporting that the network disconnected via a client initiated shutdown
with a linger time of 30 ms before closing.

trace - used for the highest detail of logging.
Unsure if python needs some different rule or exception, if Trace can not be worked in. Possibly set the logger for std::out to trace?
Morlic-fo@669 wrote:As far as log-levels are concerned, I think the following makes sense (for the AI at least):

Fatal / Error: Should exclusively used along with freeorion_tools.print_error to show the error in the chat window as well. Not sure which function should call which one.
Warning: Should be used for "minor" errors such as not getting a ship object from a (supposedly valid) ship_id.
Log(?): Any server update / message as well as orders issued by the AI client
Info: Anything that logs the current AI gamestate such as the table about colonization possibilities or threat assessment.
Debug: Strictly for debugging or logging implementation details. Explicitly not for printing high-level game-related info.
Any content posted should be considered licensed GNU GPL 2.0 and/or CC-BY-SA 3.0 as appropriate.

LGM-Doyle
Programmer
Posts: 219
Joined: Mon Feb 29, 2016 8:37 pm

Re: Log Severity Levels

#2 Post by LGM-Doyle »

I can restore fatal to the C++ logger or remove it from the python logger, whatever we decide.

I removed the fatal level from the C++ because it was only used twice. Once was to indicate a non-fatal scripting error. Designating some errors fatal and others not makes sense in an application that restarts itself, or maintains a continuous log. Otherwise the last error or set of errors in the log is the fatal error.

Similarly on the python side a trace log level can be added so that the python logger is consistent with the C++ logger.

The current logger usage outside of the Logger itself is as follow:
TraceLogger 6 uses
DebugLogger 1067 uses
InfoLogger 3 uses
WarnLogger 5 uses
ErrorLogger 1162 uses
FatalLogger 2 uses

I've been using this PR for the last couple of weeks.

When I playtested I dialed all of the levels down to warn. The log files were short and highlighted problems. When I found a problem or was working on an area I turned on debug level for that section of code. For example the networking code. I only turned trace on if very detailed logging might have helped. Trace level is voluminous enough to change the observed behavior of timing related bugs. It as not my typical level of logging.

dbenage-cx
Programmer
Posts: 389
Joined: Sun Feb 14, 2016 12:08 am

Re: Log Severity Levels

#3 Post by dbenage-cx »

LGM-Doyle @ https://github.com/freeorion/freeorion/pull/1481#issuecomment-298178029 wrote:Perhaps the log levels, info, debug and trace should not have universal meaning, but meaning within the scope of code that the named logger is covering. Otherwise, some of the named loggers will only be able to produce logs in a compressed range.

For example, currently the effects logger only logs at the trace level. This makes sense from a high level perspective, but it means that the effects logger is not as useful as it could be to a dev working on the effects code if they had access to the full range of non-error levels.

We could add a player_info named logger for player directed log message. The messages could possibly be translated. This channel should be player directed, with no code references. For the production release we could ship with warning and errors on for all loggers and the info level on for the player_info logger.
Do you mean differing use case/definitions of severity levels overall? Determining what a given severity level means at any on point sound confusing if so.
In many cases, would adding a scope attribute not be more appropriate? (attrs::named_scope)

Expanding info a little, so it can be used a little more liberally in other channels, sounds reasonable.
I'm not sure how this helps in the cases of effects though.

LGM-Doyle
Programmer
Posts: 219
Joined: Mon Feb 29, 2016 8:37 pm

Re: Log Severity Levels

#4 Post by LGM-Doyle »

I introduced two ideas in the same post. I'll try and clarify both.

First, I was thinking that some of the info log level messages were player directed and some were not, so I suggested separating the player directed messages into their own channel/named logger. Now I think that so few, almost none, of the log messages are player directed that we should consider the log a developer/scripter directed artifact. I don't think that a player_info channel is needed.

Second, the log levels along with named logger channels are designed to separate log messages along three axes: error/not error, verbosity/detail and area of code responsibility. This allows the developer to generate logs for just the sections of code and at the levels of detail that they want.

I've been using this PR for a while now. I debug with the thresholds of all of the named loggers set to warn. When I want to see a particular section of code's logs then I turn them on.

I picked the effects logger as an arbitrary example of a logger which currently has uses a very compressed range of log levels. The same observations are true for the network, FSM (finite state machine) or combat loggers. I am going to switch to using the network logger as an example because it is easier to describe the its operation.

The network logger, receives messages in two parts a header and a body, adds the body of the message to a queue, waits, and then pops the message when requested. It does this thousands of times per turn.

If we only had one logger, all of the log messages from the network logger have to be at the trace level, because even the most basic messages from the networking code will flood the log.

However, now that we have a separate network logger it makes sense to decompress the trace messages associated with receiving a message into:
- info - "Received message of type = <type> from <player_id>"
- debug - "Received header for type = <type>, Waiting for body ..."
- debug - "Received body of type = <type> and length = <length>. Added to queue of length = <x>"
- trace - "Raw message of type = <type> is \n <raw>"
- debug - "Message of type <type> is popped, new queue length is <x>"

A dev can adjust the threshold of the network logger to info at run-time just before they expect it to arrive without receiving a dump of the whole message.

The meaning of info, debug and trace make sense within the context of the network logger. For each sequence of events to receive a message: it generates 1 short info message, 3 more detailed debug messages and 1 possibly very long trace message. The info message is useful to consumers of networking services. The debug and trace levels are useful when working on the network code.

Defining info, debug and trace in the context of the named logger, means that the log information can be of maximum usefulness while debugging both the network code and code that uses the network code. It also means that it should be typically turned off.

dbenage-cx
Programmer
Posts: 389
Joined: Sun Feb 14, 2016 12:08 am

Re: Log Severity Levels

#5 Post by dbenage-cx »

The meaning of info, debug and trace make sense within the context of the network logger. For each sequence of events to receive a message: it generates 1 short info message, 3 more detailed debug messages and 1 possibly very long trace message.
This sounds fine, I had some wild deviations in mind after reading the initial post ;) .

For non-devs, maybe have a some group config setting for logs: Very High/Normal/Minimal?
These would set various loggers to some predefined severity, possibly some other name for "Very High" depending on intended use(Bug Report?).
Fewer options likely preferred here, if a specific issue needs to be tracked the dev will likely have to ask for certain log settings anyway.
Normal could then have different settings depending on release or build type if needed.

LGM-Doyle
Programmer
Posts: 219
Joined: Mon Feb 29, 2016 8:37 pm

Re: Log Severity Levels

#6 Post by LGM-Doyle »

That sound like a good idea.

I suggest changing "Minimal" to "Errors and Warnings Only", with the obvious settings.
For "Normal" set the executable channels to "info" and the named loggers to "warning".
I suggest changing "Very High" to "Custom", and un gray out/enable the individual logger options.

User avatar
mem359
Dyson Forest
Posts: 214
Joined: Sun Jun 08, 2014 1:18 am

Re: Log Severity Levels

#7 Post by mem359 »

I have just posted issue 1575

The logger is not working as it should, for my system (Mac OSX).

LGM-Doyle
Programmer
Posts: 219
Joined: Mon Feb 29, 2016 8:37 pm

Re: Log Severity Levels

#8 Post by LGM-Doyle »

As discussed in issue #1575, I have not provided clear instructions on how to preserve logging setup between builds.
Use "persistent_config.xml." to keep the same log setup with differing builds.

Find and copy the logging settings from "config.xml" into "persistent_config.xml". It is only necessary to copy settings that should not reset with new builds.

Code: Select all

  <logging>
    <execs>
      <ai>debug</ai>
      <client>warn</client>
      <server>trace</server>
    </execs>
    <sources>
      <FSM>info</FSM>
      <combat>warn</combat>
      <combat_log>trace</combat_log>
      <effects>warn</effects>
      <log>trace</log>
      <network>warn</network>
    </sources>
  </logging>

Post Reply