Logging

Logging#

Polaris uses the log4cpp package (based on the popular log4j package) to manage logging.

Log4cpp defines various levels at which logging messages may be produced. The level of a message defines it’s importance and messages can be directed into various outputs based on their level/importance. For example debug messages can be logged to a debug.log file while higher level messages could be displayed to the user in real time via the console logging (standard output).

The levels available in log4cpp are as follows

  1. EMERG

  2. FATAL

  3. ALERT

  4. CRIT

  5. ERROR

  6. WARN

  7. NOTICE

  8. INFO

  9. DEBUG

  10. NOTSET

However, within Polaris only levels {DEBUG, INFO, NOTICE, WARNING, ERROR} are regularly used and the default routing of messages is that:

  1. NOTICE WARNING AND ERROR messages are routed to standard output (console)

  2. DEBUG, INFO, NOTICE, WARNING and ERROR are routed into log/polaris_progress.log

Users can define their own routing by creating a log4cpp.property file in the log folder of their project - an example which replicates the standard setup described above is available at https://github.com/anl-polaris/polaris-linux/blob/master/log4cpp.property.

As a general rule of thumb, each of the regularly used logging levels should be used as follows:

  1. ERROR - Used when an unrecoverable error has occurred.

  2. WARN - Use when a recoverable error has occurred or when making assumptions that may contradict user expectations.

  3. NOTICE - Use for messages that would make sense in standard output - these should be messages that ALL users will want to see.

  4. INFO - As NOTICE level, but allowed to be slightly more verbose.

  5. DEBUG - Use for information that should only be written to file,

Usage in POLARIS#

Rather than using cout or other other standard C++ printing options, log4cpp should be used in every case so that output is saved to a file as well as printed to the screen.

Messages can be sent at different levels as shown below: MT::Logger::Notice("Standard output"); MT::Logger::Info("Verbose output showing some data: " << data);

There are also macros in core that handle debug messages. You can manually instantiate these levels, of course, but generally you should use the macros so that warnings and errors are obvious in the code: DEBUG_WARNING("Something went wrong here"); DEBUG_ERROR("Something went majorly wrong with data " << data << ", continuing operation") THROW_EXCEPTION("Something is broken, aborting POLARIS")

Remember that THROW_EXCEPTION kills the simulation, only use it where you want the process ended!

Correlated Output#

Where logging messages are emitted from deep within an iterative loop, there is the potential for significant volumes of such messages to be generated, flooding the terminal or output files with highly correlated messages. Examples of this would be when …

Instead of logging each event separately, use the RepeatedEventLogger class to collect together the events and emit a single concise message capturing the entire outcome. For example, the following block:

RepeatedEventLogger missingSpeedLinks("Links", "id", "missing speed attribute");
# ...
for (auto& link : links) {
    if link.speed <= 0:
        missingSpeedLinks.addEvent(link.id);
# ...

missingSpeedLinks.log(WARNING);

Will yield a warning level messages as follows:

There were 5 Links missing speed attribute. The affected "id" are: [72, 79, 122, 131, 190]

File Output#

Output can be configured to log to different files as well as to the command line as before. Polaris reads the /log/log4cpp.property file in the model folder to configure the output settings. If this file is not found, output is logged to 2 separate files for debug messages and general logging. Any of these files can be read and edited in a standard text editor.

When Polaris is running, log files should be output into the /log/ folder in the model folder. The contents of the folder are copied into the Polaris output folder when Polaris finishes or hits an exception - the logs are not copied in the event of an unhandled stop.

Log4CPP uses 3 major components:

  1. Categories: The “logger” itself. Has a single priority and any number of appenders (Although more than 2 should be unneccesary).

  2. Appenders: Describes where the log is printed to. Typically either Cout (to the command window) or RollingFileAppender (creates a new log file when the file is too large).

  3. Layout: The print layout for each logging format. Log4CPP comes with defaults as well as a PatternLayout to create our own (described in detail below)

An example of a log4cpp.property file with documentation is below:

# log4cpp.property

# The following is an example file showing the default setup of POLARIS 
# It can be copied into the log folder of a model to override the logging
# behaviour on runs of that model
#   i.e. <project_dir>/log/log4cpp.property
# Note that by default the progress log includes INFO level messages, but 
# the below includes examples of how to create a separate debug log file if 
# your situation warrants such.

log4j.rootCategory=INFO, coutAppender, logFileAppender


log4j.appender.logFileAppender=RollingFileAppender
log4j.appender.logFileAppender.additive=false
# log4j.appender.logFileAppender.threshold=NOTICE # <- This doesn't work and will always output whatever
#                                                 #    the level of the root category is
log4j.appender.logFileAppender.append=false
log4j.appender.logFileAppender.fileName=polaris_progress.log
log4j.appender.logFileAppender.MaxFileSize=10MB
log4j.appender.logFileAppender.maxBackupIndex=50
log4j.appender.logFileAppender.layout=PatternLayout
log4j.appender.logFileAppender.layout.ConversionPattern=%d{ISO8601} Thread: %t | [%6p] %m%n

log4j.appender.coutAppender=ConsoleAppender
log4j.appender.coutAppender.threshold=NOTICE     # <- This does work - not sure why ConsoleAppender does but FileAppenders dont
log4j.appender.coutAppender.target=stdout
log4j.appender.coutAppender.layout=PatternLayout
log4j.appender.coutAppender.layout.ConversionPattern=%d{ISO8601} Thread: %t | [%6p] %m%n

### DOCUMENTATION ###

# CATEGORY
# rootCategory must be set, other categories must derive from root or from one of root's derived categories, (ex. log4cpp.category.sub1=DEBUG, coutAppender)
# First setting is priority (lower settings include all higher settings):  
#   EMERG
#   FATAL
#   ALERT
#   CRIT
#   ERROR
#   WARN
#   NOTICE
#   INFO
#   DEBUG
#   NOTSET

# You can also change the additivity for each category. TRUE means it inherits all prior appenders, FALSE means that it only uses the last one.
# category.debug=DEBUG, debugAppender
# additivity.debug=false

# Second setting is the list of appenders (created in this file), separated by commas, (ex. log4cpp.rootCategory=DEBUG, logFileAppender, coutAppender)

# APPENDER
# Appenders are defined with a name and type
# ex. name "logFileAppender" type "FileAppender"

# The following types are available:

# ConsoleAppender: Outputs to console window. 
	# Set variable "target" to either stdout or stderr
	
# FileAppender: Outputs to a file.
	# Set variable "fileName" to target file (ex. ./LOG_FILE_HERE.log).
	# Set variable "append" to either true or false (append existing file (true) or overwrite (false))
	
# RollingFileAppender:
	# Set variable "fileName" to target file (ex. ./LOG_FILE_HERE.log).
	# Set variable "append" to either true or false (append existing file (true) or overwrite (false))
	# Set the variable "maxFileSize" to change the maximum size of a log file before it rolls over (in bytes!)
	# Set the variable "maxBackupIndex" to change the maximum number of log files to keep when rolling over
	
#%GW : I don't really know what the appenders below do
# DailyRollingFileAppender:
	# Set variable "fileName" to target file (ex. ./LOG_FILE_HERE.log).
	# Set variable "append" to either true or false (append existing file (true) or overwrite (false))
	
# SyslogAppender: DISABLED
# LocalSyslogAppender: DISABLED
# AbortAppender:
# IdsaAppender: DISABLED
# Win32DebugAppender:
# NTEventLogAppender:

# All Appenders have a "layout" variable that changes the output of the file.
# SimpleLayout prints "priority - message" (%p - %m)
# BasicLayout prints "timeStamp priority category ndc: message"

# PatternLayout allows you to create your own format.
	# PatternLayout supports following set of format characters:
		# %% - a single percent sign
		# %c - the category
		# %d - the date\n Date format: The date format character may be followed by a date format specifier enclosed between braces. For example, %d{%H:%M:%S,%l} or %d{%d %m %Y %H:%M:%S,%l}. 
			# If no date format specifier is given then the following format is used: "Wed Jan 02 02:03:55 1980". The date format specifier admits the same syntax as the ANSI C function strftime, 
			# with 1 addition. The addition is the specifier %l for milliseconds, padded with zeros to make 3 digits.
		# %m - the message
		# %n - the platform specific line separator
		# %p - the priority
		# %r - milliseconds since this layout was created.
		# %R - seconds since Jan 1, 1970
		# %u - clock ticks since process start
		# %x - the NDC
		# %t - thread name
	# By default, ConversionPattern for PatternLayout is set to "%m%n".