Out of the box, AEM provides a pattern based logging system which comes pre-configured with an MessageFormat pattern for logging. This is a somewhat legacy messaging format, which, for most applications, has been updated with a “Logback” implementation. The main reason for said replacement is the flexibility that logback techniques can offer, including a more customized log pattern support, in addition to the ability to add in mapped variables, or in logback terminology, Mapped Diagnostic Context, or MDC. AEM comes bundled with SLF4J, and therefore already has support for logback patterns, and more importantly, MDC. What is missing here is how to populate the variable which needs to be logged on each request, and how to manipulate your logging patterns to accommodate said variable.
Step 1: Create a Sling Filter
To utilize MDC, there are two main steps:
- Populating the MDC Object (Map)
- Referencing the MDC Properties (Logging Pattern)
In AEM, every request flows through a filter chain, meaning we need to populate the MDC variable early enough in the filter that we can successfully log those variables later. The easiest way to do this is to set the scope of a custom filter to be at the request level, order 0:
/**
* The SlingFilterScope.REQUEST is important as MDC needs to be configured prior
* to any logger being executed in the page rendering.
*/
@SlingFilter(
label = "Sample MDC Filter",
description = "Sample implementation of custom MDC properties.",
order = 0,
scope = SlingFilterScope.REQUEST)
Then you need to import the MDC object into your class:
import org.slf4j.MDC;
The rest of the logic is up to you! The request object gives you direct access to the following:
- ResourceResolver (Access to JCR)
- Request Headers
- You can use a RequestWrapper to customize
- Request Cookies
- Request Parameters
And of course, you can always use a customized service user for more targeted JCR access. For sake of simplicity, this example includes logic to read a request parameter named “appId”.
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
FilterChain filterChain) throws IOException, ServletException {
final SlingHttpServletRequest request = (SlingHttpServletRequest) servletRequest;
try {
insertIntoMDC(request);
filterChain.doFilter(request, servletResponse);
} finally {
clearMDC();
}
}
private void clearMDC() {
for (String key : MDC_CUSTOM_KEYS) {
MDC.remove(key);
}
}
private void insertIntoMDC(SlingHttpServletRequest request) {
//logic can go here to take value from request object.
// Can also utilize ResourceResolver from same request.
// If needed, can also write a generic OSGi Configuration
// (String Array Properties) to read from standard request objects,
// i.e cookies, headers, and parameters.
MDC.put(APPLICATION_ID,request.getParameter(APPLICATION_ID));
}
That is it! Deploy the filter and we will have (the ability) to log a passed in request parameter into your log.
Here’s the full class for those copy/pasters:
package com.perficient.commons.core.filters;
import org.apache.felix.scr.annotations.sling.SlingFilter;
import org.apache.felix.scr.annotations.sling.SlingFilterScope;
import org.apache.sling.api.SlingHttpServletRequest;
import org.slf4j.MDC;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import java.io.IOException;
/**
* The SlingFilterScope.REQUEST is important as MDC needs to be configured prior
* to any logger being executed in the page rendering.
*/
@SlingFilter(
label = "Sample MDC Filter",
description = "Sample implementation of custom MDC properties.",
order = 0,
scope = SlingFilterScope.REQUEST)
public class MDCLoggerFilter implements javax.servlet.Filter{
public static final String APPLICATION_ID = "appId";
private static final String[] MDC_CUSTOM_KEYS = {
APPLICATION_ID,
};
public void init(FilterConfig filterConfig) throws ServletException {
}
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse,
FilterChain filterChain) throws IOException, ServletException {
final SlingHttpServletRequest request = (SlingHttpServletRequest) servletRequest;
try {
insertIntoMDC(request);
filterChain.doFilter(request, servletResponse);
} finally {
clearMDC();
}
}
private void clearMDC() {
for (String key : MDC_CUSTOM_KEYS) {
MDC.remove(key);
}
}
private void insertIntoMDC(SlingHttpServletRequest request) {
//logic can go here to take value from request object.
// Can also utilize ResourceResolver from same request.
// If needed, can also write a generic OSGi Configuration
// (String Array Properties) to read from standard request objects,
// i.e cookies, headers, and parameters.
MDC.put(APPLICATION_ID,request.getParameter(APPLICATION_ID));
}
public void destroy() {
}
}
Step 2: Updating the Logging Pattern
This step actually helped uncover an issue in the latest AEM versions. At time of writing, AEM “Logging Logger Configurations” do not properly leverage the “Apache Sling Logging Logger” pattern variable. Instead, it references the “default” pattern, found in the configuration for org.apache.sling.commons.log.LogManager. As a work-around, we will update the “default” LogManager instead of updating the application-specific “Logging Logger” pattern. You can perform this update directly in AEM:
Or, my recommendation, create an associated OSGi configuration within your code repository’s associated config folder ( /apps/<project>/config) named org.apache.sling.commons.log.LogManager.xmlwith the following contents:
<?xml version="1.0" encoding="UTF-8"?>
<jcr:root xmlns:sling="http://sling.apache.org/jcr/sling/1.0" xmlns:cq="http://www.day.com/jcr/cq/1.0" xmlns:jcr="http://www.jcp.org/jcr/1.0" xmlns:nt="http://www.jcp.org/jcr/nt/1.0"
jcr:primaryType="sling:OsgiConfig"
org.apache.sling.commons.log.pattern="%d{dd.MM.yyyy HH:mm:ss.SSS} *%level* [%X{appId:-NoAppId}] [%thread] %logger %msg %ex%n"
org.apache.sling.commons.log.file.size="'.'yyyy-MM-dd"
org.apache.sling.commons.log.file="logs/error.log"
org.apache.sling.commons.log.file.number="7"
org.apache.sling.commons.log.level="info"
org.apache.sling.commons.log.maxOldFileCountInDump="3"
org.apache.sling.commons.log.numOfLines="10000"
org.apache.sling.commons.log.maxCallerDataDepth="7"
org.apache.sling.commons.log.packagingDataEnabled="{Boolean}false"/>
You will notice that in the above example I use a different format for the pattern string. One that may look more familiar is the default MessagePattern format:
{0,date,yyyy-MM-dd HH:mm:ss.SSS} {4} [{3}] {5}
In this default pattern, each number corresponds with a given data point, as described in the official docs. In our case, you see variables prefixed with a percentage sign. Odd! Well, fortunately, there is also a mapping for these, which we can also map using the official logback documentation.
The most interesting of the group is the %X variable. This is what exposes your custom MDC variables. In the above example, %X{appId:-NoAppID}” defines a placeholder for a property named “appId” as well as its default text, “NoAppId”. The standard for supplying defaults for any MDC object is to use the “:-” delimeter followed by the default text. Therefore, %X{appId} would output an empty string if null, whereas %X{appId:-NoAppId} would output “NoAppId” if null.
Similarly, to output all of the configured MDC variables, simply do not specify the variable you want to output: %X. If configured this way, the entire MDC map would be output as a comma separated list.
For a much deeper look on all possible variable mappings, I would highly suggest taking a look at the official logback documentation, which I will link to again here: https://logback.qos.ch/manual/layouts.html#conversionWord
Step 3: Check out the results
Once you’ve pushed the updated configuration and your custom sling filter, the changes should be active! If you followed the exact steps above, you’ll see a lot of “NoAppID” messages. Do not fret – this is because we never requested a page with the “appId” request parameter. For example, a simple we-retail request ( http://localhost:4502/content/we-retail/ca/en/experience.html ) should result in:
24.09.2018 12:41:36.819 *WARN* [NoAppId] [0:0:0:0:0:0:0:1 [1537818095824] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /etc/designs/we-retail 24.09.2018 12:41:36.915 *INFO* [NoAppId] [0:0:0:0:0:0:0:1 [1537818095824] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.day.cq.wcm.core.impl.designer.SystemDesign Initialized system design at /etc/designs/default in 13ms 24.09.2018 12:41:38.432 *WARN* [NoAppId] [0:0:0:0:0:0:0:1 [1537818095824] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /apps/clientlibs/granite/jquery-ui 24.09.2018 12:41:40.303 *INFO* [NoAppId] [0:0:0:0:0:0:0:1 [1537818100301] GET /home/users/Z/ZxNe0kWWedMwcd2ZAFhp.infinity.json HTTP/1.1] org.apache.sling.engine.impl.SlingRequestProcessorImpl service: Resource /home/users/Z/ZxNe0kWWedMwcd2ZAFhp.infinity.json not found
However, if we change the URL to add our appId, http://localhost:4502/content/we-retail/ca/en/experience.html?kp.appId=RMAPP, we get the following:
24.09.2018 12:43:39.305 *WARN* [RMAPP] [0:0:0:0:0:0:0:1 [1537818219292] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /apps/clientlibs/granite/jquery-ui 24.09.2018 12:43:39.305 *WARN* [RMAPP] [0:0:0:0:0:0:0:1 [1537818219292] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /etc/cloudsettings/default/contexthub.kernel 24.09.2018 12:43:39.309 *WARN* [RMAPP] [0:0:0:0:0:0:0:1 [1537818219292] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /etc/designs/we-retail 24.09.2018 12:43:39.436 *WARN* [RMAPP] [0:0:0:0:0:0:0:1 [1537818219292] GET /content/we-retail/ca/en/experience.html HTTP/1.1] com.adobe.granite.ui.clientlibs.impl.HtmlLibraryManagerImpl No library configured at /apps/clientlibs/granite/jquery-ui
Obviously, the true power of these entries will show when leveraging JCR and the Resource Resolver. Potentially a topic for another day. Have fun and good luck tinkering!
Kudos
I want to give appropriate recognition to the initial implementation in which this was derived: https://github.com/chetanmeh/sling-logback. Unfortunately, this package no longer functions without modification on an 6.3 instance. The logic for setting OSGi configuration properties for header, cookie, and parameters could be mirrored in this example if desired.
Nice post, thanks. Unfortunately, the new cfg.json config for the logging only supports the {0,date,yyyy-MM-dd HH:mm:ss.SSS} {4} [{3}] {5} notation, and despite reading all the renevan docs, and trying more than 50 different combinations, I believe it is not possible to log MDC variables now in AEM. e.g. {0,date,yyyy-MM-dd HH:mm:ss.SSS} %X{appId:-NoAppID} {4} [{3}] {5} does not work, nor any variation of it (using a filter which has appId set). Debugging without correlation tokens is harder. I hope someone finds a way.