Breaking down the Log4j PatternLayout

byGonzalo Marcos -

We saw recently in this previous post, an overview of the built-in Layouts provided by the Log4j framework. PatternLayout is used to format the log messages into a desired structure or pattern before they are sent to the appenders (like files, consoles, or external systems)

In this post, we will dive deeper into this Layout is built, how to understand its conversion patterns and go through some examples.

The PatternLayout

PatternLayout is the most commonly used layout in Log4j due to its flexibility, as it is highly customizable and supports a wide range of specifiers.

As a matter of fact, PatternLayout is the Layout that Mule uses to format the logs by default and it’s the layout that we can see for Cloudhub and Runtime Fabric in the Anypoint control plane.

This Layout allows us to define a custom format for our log messages using a conversion pattern string. This string can include various placeholders (conversion specifiers) that represent different parts of the log event, such as the date, log level, thread name, and message.

The format and the logged info in this layout is defined by a conversion pattern. Let’s see in detail how the conversion patterns work:

Conversion Patterns

A conversion pattern is made of literal text and a conversion specifier. We can insert any literal text within the conversion pattern.

To identify a conversion specifier, each conversion specifier starts with a percent sign (%) and is followed by a conversion character and an optional format modifier.
  • A conversion character specifies the type of info to be logged - date, category, thread, message...
  • The format modifier controls how that conversion character is displayed - field width, padding, justification, color...

Conversion Specifiers

Here's a list of common conversion specifiers and their meanings:

%d: Date and time

  • Formats the date and time of the log event.. You can customize the format with d{pattern}, where pattern is a date format string like yyyy-MM-dd HH:mm:ss.
  • Example: %d{yyyy-MM-dd HH:mm:ss.SSS} outputs 2024-08-25 14:45:23.123


%p: Log level

  • Displays the log level (e.g., DEBUG, INFO, ERROR).
  • Example: %p might output INFO.


%c: Logger name

  • Outputs the logger name (usually the class name).
  • Example: %c{1} might output MyClass.


%C: Fully Qualified Class Name

  • Displays the fully qualified class name.
  • Example: %C might output com.example.MyClass


%m: The log message

  • The actual log message passed by the logger.
  • Example: If you log logger.info("Hello, world!"), %m would output Hello, world!.


%M: Method name 

  • Outputs the method name where the log statement was made.
  • Example: %M might output myMethod.


%t: Thread Name

  • Outputs the name of the thread that logged the event.
  • Example: %t might output main.


%n: Newline character

  • Outputs a newline character.


%F: File name 

  • Outputs the file name where the log statement was made.
  • Example: %F might output MyClass.java


%L: Line number

  • Outputs the line number where the log statement was made.
  • Example: %L might output 42.


%x: NDC (Nested Diagnostic Context) information.


%X{key}: MDC (Mapped Diagnostic Context)

  • Outputs a value from the MDC (useful for adding contextual information like user IDs or session IDs).
  • Example: %X{userId} might output user123 if userId is stored in the MDC.


%l: Location information 

  • Provides location information about where the log event occurred (class name, method, and line number).
  • Example: %l might output com.example.MyClass.myMethod(MyClass.java:42).


%r: Relative Time

  • The time (in milliseconds) elapsed since the application started.
  • Example: %r might output 123456.

Format Modifiers

Here's the list of format modifiers and their meanings:

Width

  • Sets the minimum width of the output for the conversion pattern. If the data is shorter than this width, it will be padded (by default, with spaces) to reach the required width. 
  • Syntax: %-<width>p
  • Example: %-5p: The log level will be padded with spaces to a minimum width of 5 characters. For example, INFOwill appear as INFO (with an extra space).

Precision

  • Controls the maximum number of characters to be printed. If the data exceeds this length, it will be truncated.
  • Syntax: %.<precision>c
  • Example:
    • %.3c: For the logger name com.example.MyClass, only the last 3 parts will be shown as example.MyClass.


Left Alignment

  • Aligns the text to the left within the specified width. This is indicated by a minus sign (-) in front of the width.
  • Syntax: %<width>-c
  • Example:
- %20-c: The logger name will be right-aligned within a 20-character width.
- %-20c: The logger name will be left-aligned within a 20-character width.


Truncation

  • Limits the number of characters printed from a string. If the string is longer than the specified precision, it is truncated.
  • Syntax: %.<precision>c
  • Example:
    • %.5m: Only the first 5 characters of the message will be printed. For example, if the message is Hello, world!, only Hello will be shown.


Padding

  • Adds padding to the left or right of the data if it is shorter than the specified width.
  • Syntax: %<padding>c
  • Example:
    • %10c: Pads the logger name to ensure it occupies 10 characters.
    • %-10c: Pads the logger name to the left to ensure it occupies 10 characters.

Combination of Width and Precision

  • You can combine width and precision modifiers to both limit and pad the data.
  • Syntax: %<width>.<precision>c
  • Example:
    • %20.5c: The logger name will be truncated to 5 characters and then right-aligned within a 20-character width.


Default Padding Character

- By default, padding is done with spaces. However, you can change the padding character using a single quotation mark followed by the character.
- Syntax: %'-<width>c
- Example:
- %'-20c: The logger name will be left-aligned within a 20-character width, padded with hyphens (-).


Negation of Width

  • If the width is negative, the field is left-aligned, and the padding character is added to the right.
  • Syntax: %<width>c
  • Example:
    • %5c: The logger name will be right-aligned within a 5-character width.
    • %5.-5c: The logger name will be truncated to 5 characters, padded to the left with spaces to occupy 5 characters.


Examples: 

Example 1: Basic Log Output

Pattern:

%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} - %m%n


Conversion Pattern Explained:

  • %d{yyyy-MM-dd HH:mm:ss}: The date and time of the log entry, formatted as yyyy-MM-dd HH:mm:ss.
  • %-5p: The log level (INFO, ERROR, etc.), left-aligned and padded to a width of 5 characters.
  • %c{1}: The name of the logger (usually the class name), displaying only the last part of the package.
  • %m: The log message.
  • %n: A newline.


Sample Output:

2024-09-06 12:34:56 INFO MyClass - Starting the Mule application
2024-09-06 12:34:57 DEBUG MyClass - Processing the input data
2024-09-06 12:34:58 ERROR MyClass - An error occurred: NullPointerException


Example 2: Detailed Log with Thread and Class Information

Pattern:

%d{ISO8601} [%t] %-5p %C{1}.%M:%L - %m%n


Conversion Pattern Explained:

  • %d{ISO8601}: Logs the timestamp using the ISO8601 format.
  • [%t]: Logs the thread name in square brackets.
  • %-5p: The log level, left-aligned and padded to a width of 5 characters.
  • %C{1}: The fully qualified class name, but only the last part.
  • %M: The method name where the log event occurred.
  • %L: The line number where the log event occurred.
  • %m: The log message.
  • %n: A newline.


Sample Output:

2024-09-06T12:34:56.123+0200 [main] INFO MyClass.main:23 - Starting the Mule application
2024-09-06T12:34:57.456+0200 [main] DEBUG MyClass.processData:45 - Processing the input data
2024-09-06T12:34:58.789+0200 [main] ERROR MyClass.handleError:67 - An error occurred: NullPointerException

Example 3: Log with Mapped Diagnostic Context (MDC)

Pattern:

xml
Copy code
%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} [%X{transactionId}] - %m%n

Conversion Pattern Explained:

  • %d{yyyy-MM-dd HH:mm:ss}: The timestamp in the format yyyy-MM-dd HH:mm:ss.
  • %-5p: The log level, left-aligned and padded to a width of 5 characters.
  • %c{1}: The last part of the logger's name (e.g., the class name).
  • [%X{transactionId}]: Logs a custom value (transactionId) from the MDC (Mapped Diagnostic Context).
  • %m: The log message.
  • %n: A newline.

Sample Output:

2024-09-06 12:34:56 INFO MyClass [txn12345] - Starting the Mule application
2024-09-06 12:34:57 DEBUG MyClass [txn12345] - Processing the input data
2024-09-06 12:34:58 ERROR MyClass [txn12345] - An error occurred: NullPointerException



Example 4: JSON-like Log Output for Log Aggregation

Pattern:

{ "timestamp": "%d{yyyy-MM-dd'T'HH:mm:ss.SSSZ}", "level": "%-5p", "logger": "%c{1}", "thread": "%t", "message": "%m" }%n

Conversion Pattern Explained:

  • %d{yyyy-MM-dd'T'HH:mm:ss.SSSZ}: The timestamp in ISO8601 format with milliseconds and timezone.
  • "level": "%-5p": The log level, left-aligned and padded to a width of 5 characters.
  • "logger": "%c{1}": The last part of the logger's name (e.g., the class name).
  • "thread": "%t": Logs the thread name.
  • "message": "%m": Logs the actual message in the log.
  • %n: A newline.


Sample Output:

{ "timestamp": "2024-09-06T12:34:56.123+0200", "level": "INFO ", "logger": "MyClass", "thread": "main", "message": "Starting the Mule application" }
{ "timestamp": "2024-09-06T12:34:57.456+0200", "level": "DEBUG", "logger": "MyClass", "thread": "main", "message": "Processing the input data" }
{ "timestamp": "2024-09-06T12:34:58.789+0200", "level": "ERROR", "logger": "MyClass", "thread": "main", "message": "An error occurred: NullPointerException" }


Example 5: Log with Stack Trace for Exceptions

Pattern:

%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1} - %m%n%ex

ConversionPattern Explained:

  • %d{yyyy-MM-dd HH:mm:ss}: The timestamp in yyyy-MM-dd HH:mm:ss format.
  • %-5p: The log level, left-aligned and padded to a width of 5 characters.
  • %c{1}: The last part of the logger name.
  • %m: The message.
  • %n: A newline.
  • %ex: The exception stack trace, if an exception is logged.

Sample Output:

2024-09-06 12:34:58 ERROR MyClass - An error occurred: NullPointerException
java.lang.NullPointerException: null
    at com.example.MyClass.handleError(MyClass.java:67)
    at com.example.MyClass.processData(MyClass.java:45)
    at com.example.MyClass.main(MyClass.java:23)

Example 6: Minimal Log Output

Pattern:

%d{HH:mm:ss} %-5p %m%n

ConversionPattern Explained:

  • %d{HH:mm:ss}: Logs only the time in HH:mm:ss format.
  • %-5p: The log level, left-aligned and padded to a width of 5 characters.
  • %m: The log message.
  • %n: A newline.

Sample Output:

12:34:56 INFO  Starting the Mule application
12:34:57 DEBUG Processing the input data
12:34:58 ERROR An error occurred: NullPointerException

Example 7: Rolling File Log with Full Details

Pattern:

%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5p %c{1} - %m%n%ex

ConversionPattern Explained:

  • %d{yyyy-MM-dd HH:mm:ss.SSS}: The timestamp with milliseconds.
  • [%t]: Logs the thread name.
  • %-5p: The log level, left-aligned and padded to a width of 5 characters.
  • %c{1}: The last part of the logger name.
  • %m: The log message.
  • %n: A newline.
  • %ex: The exception stack trace, if any.

Sample Output:

2024-09-06 12:34:56.123 [main] INFO  MyClass - Starting the Mule application2024-09-06 12:34:57.456 [main] DEBUG MyClass - Processing the input data2024-09-06 12:34:58.789 [main] ERROR MyClass - An error occurred: NullPointerException
java.lang.NullPointerException: null
    at com.example.MyClass.handleError(MyClass.java:67)
    at com.example.MyClass.processData(MyClass.java:45)
    at com.example.MyClass.main(MyClass.java:23)


Example 8: Default Mulesoft PatternLayout

In this example let’s have a look at the default PatternLayout that Mule predefines for all the apps. This is the layout that we’d see in our logs if we don’t change anything in the log4j.

Pattern:

 <PatternLayout pattern="%-5p %d [%t] [processor: %X{processorPath}; event: %X{correlationId}] %c: %m%n"/>

ConversionPattern Explained:

  • %-5p: Log level, padded to 5 characters.
  • %d: Date and time of the log event.
  • [%t]: Name of the thread
  • %X{processorPath}
  • %X{correlationId} - correlation Id of the mule message
  • %c: Logger name, that is, the class name that generated the log
  • %m - The log message
  • %n - New line character

Sample Output:

INFO 2024-09-06 18:30:07,203 [[MuleRuntime].uber.08: [logging-tests].myFlow.CPU_LITE @350ae338] [processor: myFlow/processors/0; event: a8cfaa50-6c75-11ef-be6f-38f9d3cde3d6] org.mule.runtime.core.internal.processor.LoggerMessageProcessor: "Hello Gon!"

Where:
  • %-5p: Log level, padded to 5 characters = INFO
  • %d: Date and time of the log event = 2024-09-06 18:30:07, 203
  • [%t]: Name of the thread = [[MuleRuntime].uber.08: [logging-tests].myFlow.CPU_LITE @350ae338]
  • %X{processorPath} = myFlow/processors/0
  • %X{correlationId} - correlation Id of the mule message = a8cfaa50-6c75-11ef-be6f-38f9d3cde3d6
  • %c: Logger name, that is, the class name that generated the log = org.mule.runtime.core.internal.processor.LoggerMessageProcessor
  • %m - The log message = "Hello Gon!"
  • %n - New line character
Tags
Previous Post Next Post