What?

This project contains several utilities to supplement MuleSoft's out of the box logger and enforce logging standards on application logs.

• The custom logger processor builds and logs Java HashMap with the given key-value pairs thus providing a way to generate consistent and structured log messages:
• The timer scope records the amount of time it takes to execute the processors inside the scope and logs the time elapsed.
• The notification logger listens to the Mule runtime's engine notifications and logs when flows start and end.

Why?

One of the reasons for developing this custom module is to feed JSON logs to log analyzers like Splunk, ELK etc. When these log analyzers receive structured logs(JSON), It is easy on the log analyzer side to create reports, dashboards etc. Below are the things this Logger can do when compared to out-of-the-box MuleSoft's logger component.

• Easy to use for a Mule developer to log necessary and sufficient data.
• Log metadata with each log message like application name, version, environment, location info etc.
• Log any number of data points within a log message thus enabling log analyzer to have sufficient data to create stunning reports.
• Log exceptions.
• Log Correlation ID.
• Optionally log location info with each log message.
• Tracepoints compatibility to measure request, response times and such.

Changes

Please refer to GitHub releases for continued changelog

NOTE: Java 17 is supported with 3.x versions.

2.1.1

• Fixes
  • Fixed implementation to only create and register one Notification Listener. Duplicates were being created and registered leading to duplicate flow logs

2.1.0

• Added
  • Implementation to optionally compress or encrypt the payload within the logger operations
• Updated
  • Custom Logger class log method to optionally log the encrypted, compressed or raw payload string

1.2.1

• Added system property 'avio.logger.mapmessage = true' to utilize a MapMessage instead of ObjectMessage for logging, this allows for filtered logs. See Simplified Logging section below.
• Supports 4.1 - 4.4 releases of the Mule Runtime

Using the Custom Logger Processor

Here is how mule-custom-logger looks like in action.

Global configuration:

Log Operation:

This will log Java HashMap as shown below.

INFO  2019-07-01 19:10:59,412 [[MuleRuntime].cpuLight.24: [sample].sampleFlow.CPU_LITE @18c7b87e] [event: dccaf190-9c5d-11e9-9fcf-38f9d373e316] com.avio: {ext={additionalKey1=additionalValue1, additionalKey2=additionalValue2}, exception={detail=null, type=null, statusCode=null}, app_name=sample, app_version=1.0.0, log={trace_point=START, payload=null, correlation_id=a86212d5-d5c0-4b78-96cc-863f581a6ac0, message=This is nothing but a sample log message}, location={line_in_file=17, component=avio-core:custom-logger, file_name=sample.xml, root_container=sampleFlow, location=sampleFlow/processors/1}, env=dev, timestamp=2019-07-02T00:10:59.412Z}

With this custom module producing HashMap,

• It would be handy in log4j2.xml to take this HashMap and convert to desired formats using log4j2 layouts. There are many out-of-the-box log4j layouts available here. See https://logging.apache.org/log4j/2.x/manual/layouts.html.
• Let appenders in log4j2 decide what layout to use to send to it specified destination.

Below is the out-of-the-box log4j2 JSON layout(wrapped in Console appender) to convert the HashMap produced by the custom module to JSON.

<Console name="Console" target="SYSTEM_OUT">
    <JSONLayout objectMessageAsJsonObject="true"/>
</Console>

Dont forget to add this appender to your root or any of your loggers. See below

<AsyncRoot level="INFO">
    <AppenderRef ref="file"/>
    <AppenderRef ref="Console"/>
</AsyncRoot>

There are several attributes provided by this JSONLayout that you can play with. Above log4j layout definition produces the JSON like below.

{
    "app_name": "sample",
    "app_version": "1.0.0",
    "env": "dev",
    "ext": {
        "additionalKey1": "additionalValue1",
        "additionalKey2": "additionalValue2"
    },
    "location": {
        "component": "avio-core:custom-logger",
        "file_name": "sample.xml",
        "line_in_file": "16",
        "location": "sampleFlow/processors/1",
        "root_container": "sampleFlow"
    },
    "log": {
        "category": "com.avio",
        "correlation_id": "33af6200-018b-42af-8ec1-ebdbf29c0505",
        "level": "INFO",
        "message": "This is nothing but a sample log message",
        "tracePoint": "START"
    },
    "thread": "[MuleRuntime].cpuLight.23: [sample].sampleFlow.CPU_LITE @27346628",
    "timestamp": "2019-05-17T15:06:34.592Z"
}

Important: If you are using this kind of approach(HashMap + JSONLayout in log4j2.xml) for any MuleSoft CloudHub projects, and if you want to see JSON logs in CloudHub console, The CloudHub appender provided by MuleSoft defaults to one pattern and it ignores any layout you specify. Most of the log4j2 appenders should accept layouts though.

Using Compression and Encryption (v 2.1.x and higher)

The compression and encyrption functionality allows you to compress, encrypt, or apply both to the payload string that is being logged. The mule modules for Crypto and Compression are being utilized seemlessly incorporate this functionality into your Mule project.

To use this functionality, be sure you are using at or above v2.1.0, navigate to your AVIO Logger configuration. Once in the configuration you can access the new tabs Compression and Encryption. In the Compression tab, select from the list of support compressing strategies. For the Encryption tab, select the algorithm you want to utilize, and finally supply the password that will be used to encrypt.

Example of logger configuration that utilizes compression with the compressor attribute:

  <avio-logger:config name="ts-logger-test-config-compression-applied" doc:name="AVIO Logger Config" doc:id="5b6cabea-3a64-48ae-81a7-1c28c45e70cb" applicationVersion="#[p('api.version')]" defaultCategory="com.avioconsulting.mule" compressor="GZIP"/>

Example of logger configuration that is utilizing encryptionAlgorithm and encryptionPassword to implement encryption of the payload

  <avio-logger:config name="ts-logger-test-config-encryption" doc:name="AVIO Logger Config" doc:id="e4f60146-7ee7-404a-a177-ac187c874bdd" applicationVersion="#[p('api.version')]" defaultCategory="com.avioconsulting.mule" encryptionAlgorithm="PBEWithHmacSHA512AndAES_128" encryptionPassword="${secure::encryption.password}"/>

Support for automatically including trace and span IDs in each log (v2.2.x+)

This feature is designed to be used in tandom with the Mule OpenTelemetry Module. If the Mule OpenTelemetry Module is included in your project, AVIO Logger will automatically include the following attributes in each log's messageAttributes section.

• traceId - Trace id of the current request
• spanId - Span Id for the component used for creating context
• spanIdLong - Long number value of the spanId for services that require a long number for Span IDs (i.e DataDog)
• traceIdLongLowPart - Long value of the Trace Id Low part

If the OpenTelemetry Module is not in use, there is no configuration necessary and the logs will not include these additional messageAttributes.

Format As Json (v2.3 onwards)

Some Log4J appenders (eg. OpenTelemetry Appender) may not support using Log4j Layouts but the log aggregation backend may require log messages in JSON format. In such scenarios, it is possible to format the lag message as JSON string.

Mule Custom Logger v2.3 introduced a new configuration flag to format the log message as a JSON string -

  <avio-logger:config name="AVIO_Logger_Config_Json"
    applicationName="${otel.service.name}"
    applicationVersion="1.0"
    environment="#[p('mule.env')]"
    formatAsJson="true">	// Configure to format as JSON
  </avio-logger:config>

Following two sample log statements shows the difference.

Log without JSON formatting prints the java string version of the object -

INFO 2024-07-16 12:58:53,183 [[MuleRuntime].uber.10: [simple-otel].simple-otel-log-flow-custom-logger.CPU_LITE @2306b18c] [processor: simple-otel-log-flow-custom-logger/processors/1; event: 0d99c380-4345-11ef-b9db-ca89f39a1b65] com.avioconsulting.api: {timestamp=2024-07-16T07:28:53.183Z, appName=simple-otel, appVersion=1.0, env=dev, correlationId=0d99c380-4345-11ef-b9db-ca89f39a1b65, message=Sample otel custom log, messageAttributes={traceId=fc010d3d5393cfd1606e2dd3adc56049, traceIdLongLowPart=6948541662255997001, spanId=8d267add2300b701, spanIdLong=10170951898656454401}, exception={statusCode=null, detail=null}}

Log with JSON formatting prints correctly formatted JSON string -

INFO 2024-07-16 12:58:53,189 [[MuleRuntime].uber.10: [simple-otel].simple-otel-log-flow-custom-logger.CPU_LITE @2306b18c] [processor: simple-otel-log-flow-custom-logger/processors/2; event: 0d99c380-4345-11ef-b9db-ca89f39a1b65] com.avioconsulting.api: {"timestamp":"2024-07-16T07:28:53.188Z","appName":"simple-otel","appVersion":"1.0","env":"dev","correlationId":"0d99c380-4345-11ef-b9db-ca89f39a1b65","message":"Sample otel custom log Json","messageAttributes":{"traceId":"fc010d3d5393cfd1606e2dd3adc56049","traceIdLongLowPart":"6948541662255997001","spanId":"8d267add2300b701","spanIdLong":"10170951898656454401"},"exception":{}}

Using the Timer Scope

The timer scope allows you to unobtrusively measure the time taken to execute the processors within the scope. For example, if you had a complex Transform Message processor that you wanted to time, you could place it inside the scope to get an INFO level log of how many milliseconds it took to execute.

To use the timer scope, pull it in from the AVIO Core section of the palette and fill in the two required values, Timer Name and Category. After that, check the App Level properties and validate they're what you desire. Now you're good to go!

Using the Custom Logger Notification Listener

The custom logger notification listener implements an interface that allows it to be notified when flows start and end. It's also able to retrieve your avio-logger:config global element and match its App Level properties to your custom loggers'. Note that (unless overriden) all flow start/stop messages will have a category suffix of .flow.

To use the custom logger notification listener navigate to your logger's global configuration and check the box for Enable Flow Logs

You can also override the global configuration elements by specifying properties. The available properties are as follows:

• appName
• appVersion
• env
• category - Note, this completely overrides the category, i.e. it does not use the baseCategory from the global configuration as a prefix.

How?

Use from Maven Central

Mule Custom Logger v2.0.0 and later are published to Maven Central. To use the module, you can simply add following dependency to your application's pom.xml -

<dependency>
  <groupId>com.avioconsulting.mule</groupId>
  <artifactId>mule-custom-logger</artifactId>
  <version>LATEST_RELEASE_VERSION</version>
  <classifier>mule-plugin</classifier>
</dependency>

Use from Local Maven Repository

You can install the module to local maven repository and use it for testing purpose.

• First, Clone this GitHub repository into your local machine.
• Get your Anypoint's organization ID and
  • Place it in pom.xml group id tag. <groupId>YOUR_ORG_ID</groupId>.

Now run mvn clean install to install this maven project in your local .m2 repository.

When you install this project into your machine's local .m2 repository, You can include this dependency(see below) in your mule projects. When you included this dependency in your project's pom.xml, AVIO's custom logger component automatically shows up in mule project's pallete and using this logger afterwards is just a drag away.

<dependency>
    <groupId>YOUR_GROUP_ID</groupId>
    <artifactId>mule-custom-logger</artifactId>
    <version>LATEST_VERSION_FROM_POM</version>
    <classifier>mule-plugin</classifier>
</dependency>

Push to anypoint private exchange

Alternatively, you can push this mule custom component to your anypoint organization's private exchange so that all developers inside that organization can use it. Here are the steps,

• First, Clone this GitHub repository into your local machine.
• Get your Anypoint's organization ID and
  • Place it in pom.xml group id tag. <groupId>YOUR_ORG_ID</groupId>.
  • Place it in url tag under distribution management tag. See below

<distributionManagement>
  <repository>
    <id>anypoint-exchange</id>
    <name>Corporate Repository</name>
    <url>https://maven.anypoint.mulesoft.com/api/v1/organizations/YOUR_ORG_ID/maven</url>
    <layout>default</layout>
  </repository>
</distributionManagement>

• Include exchange credentials in your settings.xml under servers section and with the matching server id with the repository id in pom's distribution management tag.
• Run mvn clean deploy to deploy this custom component into your anypoint exchange.
• Now, click on "search on exchange" in your mule project pallete, login and install component in your project.

Simplified Logging

When developing and debugging code locally, the complete log message is rarely necessary, only a small subset. To be able to filter messages, the logger code must use a MapMessage component, instead of an ObjectMessage. This MapMessage can then be filtered in a Log4j pattern.

• Create a src/main/resources/local/log4j2.xml file - This file will only be used when running locally

<?xml version="1.0" encoding="utf-8"?>
<Configuration>
  <Appenders>
    <Console name="CONSOLE" target="SYSTEM_OUT">
      <!-- the pattern can be modified to your need -->
      <PatternLayout pattern="%5p [%d] %K{log}%n" />
    </Console>
  </Appenders>
  <Loggers>
    <AsyncRoot level="INFO">
      <!-- don't forget to enable the appender -->
      <AppenderRef ref="CONSOLE"/>
    </AsyncRoot>
  </Loggers>
</Configuration>

• Update pom.xml to include the following profiles - Using the local profile will copy the src/main/resources/local directory into the project output directory, overriding the original log4j2.xml

. . .
<profiles>
  <profile>
    <!-- using maven pass in -Plocal to use this profile -->
    <id>local</id>
    <build>
      <plugins>
        <plugin>
          <artifactId>maven-resources-plugin</artifactId>
          <version>3.1.0</version>
          <executions>
            <execution>
              <id>local-log4j2</id>
              <phase>process-resources</phase>
              <goals>
                <goal>copy-resources</goal>
              </goals>
              <configuration>
                <resources>
                  <resource>
                    <!-- copies the 'local' folder to outputDirectory -->
                    <directory>src/main/resources/local/</directory>
                    <filtering>true</filtering>
                  </resource>
                </resources>
                <outputDirectory>${project.build.outputDirectory}</outputDirectory>
                <overwrite>true</overwrite>
              </configuration>
            </execution>
          </executions>
        </plugin>
      </plugins>
    </build>
  </profile>
  <profile>
    <!-- Standard profile for normal builds -->
    <id>other</id>
    <activation>
      <activeByDefault>true</activeByDefault>
    </activation>
    <build>
      <resources>
        <resource>
          <directory>src/main/resources</directory>
          <excludes>
            <exclude>local/**</exclude>
          </excludes>
        </resource>
        <resource>
          <!-- Helps IntelliJ understand src/main/mule is a source directory too -->
          <directory>src/main/mule</directory>
        </resource>
      </resources>
    </build>
  </profile>
</profiles>
. . .

• From Studio, Run -> Run Configurations
  • Add VM Argument: -Davio.logger.mapmessage=true
  • Add Maven command line arguments: -Plocal

Sample Log

 INFO [2021-11-03 10:14:29,744] {trace_point=START, payload=OrderId : 548102842, correlation_id=b25b770a.ee7a.4820.8abc.9346ff693840, message=Start of flow}
 INFO [2021-11-03 10:14:29,773] {trace_point=FLOW, payload={
  "orderId": 548102842,
  "customerId": "ARG-12934",
  "items": [
    "CP-123",
    "CP-452"
  ]
}, correlation_id=correlationId, message=Here is my message}
 INFO [2021-11-03 10:14:29,775] {trace_point=END, payload=OrderId : 548102842, correlation_id=b25b770a.ee7a.4820.8abc.9346ff693840, message=End of flow}