Logging Reference

A guide to logging in SCOP Framework.

Overview

Logging is an essential part of SCOP Framework. It helps to track the progress of the experiments, identify potential problems, and debug issues. Logging information can also be used to measure performance and analyze the results of the experiments.

Additionally, it can be used to compare the results of different experiments and to identify the most effective approaches. Logging also helps to protect the integrity of the experiments, as it can be used to detect any malicious or fraudulent activities.

Finally, logging is essential for testing and validating the experiments, allowing developers to ensure that the experiments are running as expected.

For effective logging, SCOP Framework uses one of the most widely used logging frameworks in the Java Community called Logback. Logback offers a fast implementation, provides several options for configuration, and flexibility in archiving old log files.

Logback in SCOP Framework

The Logback structure consists of three components: Logger, Appender, and Layout.

Logger is the context for the log messages and is what applications interact with in order to generate the log messages.
Appender is responsible for placing log messages in their final locations. It is not uncommon for a Logger to have multiple Appenders attached to it. Logback provides the capability to attach Appenders to more than just text files.
Layout facilitates the production of messages for outputting. Logback provides the means to craft user-defined classes for formatting messages, in addition to comprehensive configuration possibilities for the current ones.

Maven Dependency

For logging messages, SCOP Framework adds Logback to pom.xml:

...
<properties>
   ...
   <logback.version>1.5.1</logback.version>
   ...
</properties>
...
<dependencies>
   ...
   <dependency>
			<groupId>ch.qos.logback</groupId>
			<artifactId>logback-classic</artifactId>
			<version>${logback.version}</version>
	 </dependency>
   ...
</dependencies>
...

Classpath

This installs the following dependencies to your project’s classpath.

+-Maven Dependencies
 \- ...
 \- logback-classic:jar:1.5.1.jar
 \- logback-core:jar:1.5.1.jar
 \- ...
 \- org.slf4j:slf4j-api:jar:1.7.30.jar
 \- ...

SLF4J (the Simple Logging Facade for Java) is used by Logback as its native interface.

Configuration File

There is a default logback.xml located under src/main/resources.

<configuration>
    <!-- Remove completely the status-information of Logback -->
    <statusListener class="ch.qos.logback.core.status.NopStatusListener" />

    <!-- Console Appender -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%-5level] [%-20logger{35}] %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Root Logger -->
    <root level="info">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Thanks to this logback.xml file, SCOP Framework projects can generate log messages and modify the configuration of the loggers.

Debugging Using Logback

SCOP Framework models can get complicated, so there are several built-in Logback mechanisms for troubleshooting.

Troubleshooting Logback Configuration

Firstly, we need to ensure that Logback is correctly configured. To do so, we can turn on debug logging and remove NopStatusListener:

<configuration debug="true">
	<!-- Remove completely the status-information of Logback 
	<statusListener class="ch.qos.logback.core.status.NopStatusListener" /> -->
  ...
</configuration>

As Logback processes the configuration, it will display status updates in the console.

22:42:56,864 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
22:42:56,864 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/Onder.Gurcan/git/mage.abmproject/target/classes/logback.xml]
22:42:56,865 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
22:42:56,865 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/C:/Users/Onder.Gurcan/git/mage.abmproject/target/classes/logback.xml]
22:42:56,865 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/C:/Users/Onder.Gurcan/.m2/repository/scop-framework/mage.api/1.0.0-a.1/mage.api-1.0.0-a.1.jar!/logback.xml]
22:42:56,996 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
22:42:56,997 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
22:42:57,007 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
22:42:57,016 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
22:42:57,050 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.FileAppender]
22:42:57,053 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
22:42:57,054 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
22:42:57,057 |-INFO in ch.qos.logback.core.FileAppender[FILE] - File property is set to [logs/log.log]
22:42:57,061 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
22:42:57,061 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
22:42:57,061 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
22:42:57,061 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
22:42:57,062 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@5af0a4a - Registering current configuration as safe fallback point

If any issues arise while Logback is processing the configuration file, it will display notifications on the console.

Convention for Logger Names

Each Logger has a Logger a name which represents its logging context. The structure of logging contexts follows a similar pattern to the Java object hierarchy:

A logger is an ancestor when its name, followed by a dot, prefixes a descendant logger‘s name,
A logger is a parent when there are no ancestors between it and a child.

SCOP Framework follows the following customized conventions for logger names:

Agent and all its subclasses uses the agentCanonicalClassName.agentName pattern (e.g., mage.cs.project.model.MyAgent.MyAgent-1),
Role and all its subclasses uses the loggers of their owner agent,
All other classes uses their canonical class names (e.g., mage.cs.project.MyClass).

By default, each agent has a dynamic logger with an associated file appender which export the dedicated log files for each agent under the data\output\log folder using the agentName.log pattern. The file appender uses the [%X{tick}][%logicalDate] " + agentName + " %msg%n encoding pattern for the logs.

Modifying Logger Levels

We can set the level for any logger. The possible levels are, in order of precedence: TRACE, DEBUG, INFO, WARN and ERROR.

...
    <logger name="mage.cs.project.model.MyAgent" level="WARN" />
    <logger name="mage.cs.project.MyClass" level="DEBUG" />
...

If a level is not explicitly assigned to a Logger, it inherits the level of its closest ancestor. The root logger defaults to INFO.

...
    <!-- Root Logger -->
	<root level="INFO">
		<appender-ref ref="STDOUT" />
	</root>
...

Disabling Loggers

We can disable any existing logger (especially the ones of agents) by setting its level to OFF.

...
    <logger name="mage.cs.project.model.MyAgent" level="OFF" />
...

Defining/Modifying Appenders

Loggers are responsible for sending LoggingEvents to Appenders, which do the actual logging. Generally, logging is associated with writing output to a file or the console, however Logback can be capable of a lot more. Logback offers various convenient appenders.

MAGE Variables in Logback

The SCOP Framework provides custom variables that can be used in Logback for enhanced logging purposes. These variables allow you to capture and log important context-specific information, such as the simulation time, which can be crucial for analyzing and debugging simulation runs.

Simulation Time (tick)

It’s often crucial to log the simulation time (tick) alongside other log information.

To configure Logback to include tick, modify your logback.xml configuration to include the simulation time in the log pattern. Use the %X{tick} placeholder to retrieve the value of the current tick.

<configuration>
    <!-- File Appender -->
    <property name="LOG_DIR" value="logs"/>
    <property name="LOG_FILE" value="log"/>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${LOG_DIR}/${LOG_FILE}.log</file>
        <append>false</append>
        <encoder>
            <pattern>%-4relative [%-5level] %logger{35} - %msg [Tick: %X{tick}]%n</pattern>
        </encoder>
    </appender>
</configuration>

With this configuration, your log entries might look like this:

 10 [INFO ] MyAgent - Starting simulation step [Tick: 135]
 20 [INFO ] MyAgent - Completed simulation step [Tick: 144]

This setup ensures that the tick is consistently included in each log entry, providing clear context for the timing of events within the simulation.

Custom Variables in Logback

To include a custom variable in your log entries using Logback, you need to do a few things:

1.	Make the custom veriable accessible to Logback: Ensure your custom variable is available to the logging framework. This can be done by setting the custom variable in the MDC (Mapped Diagnostic Context).
2.	Modify the logback.xml to include the custom variable: Update the pattern in the encoder to include the simulation time.

Here’s a step-by-step approach:

Step 1: Set the Custom Variable in MDC

In your simulation code, you can set the custom variable in MDC like this:

import org.slf4j.MDC;

public void logCustomVariable(long customVariable) {
    MDC.put("customVariable", String.valueOf(customVariable));
}

Call logCustomVariable(long customVariable) with the current value of the custom variable whenever its value is updated.

Step 2: Modify logback.xml to Include Custom Variable

Update your logback.xml to use the %X{customVariable} placeholder, which will be replaced by the value stored in the MDC under the key customVariable.

Here’s an example of your logback.xml:

<configuration>
    <!-- File Appender -->
    <property name="LOG_DIR" value="logs"/>
    <property name="LOG_FILE" value="log"/>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${LOG_DIR}/${LOG_FILE}.log</file>
        <append>false</append>
        <encoder>
            <pattern>%-4relative [%-5level] %logger{35} - %msg [Custom variable: %X{customVariable}]%n</pattern>
        </encoder>
    </appender>
</configuration>

Resources

For further information regarding how to use Logback, you can see the following resources:

A Guide To Logback

Feedback

Was this page helpful?

Glad to hear it! Please tell us how we can improve.

Sorry to hear that. Please tell us how we can improve.

Last modified January 10, 2025: Update URLs (8b75002)