AEM comes bundled with SLF4J, and therefore already has support for log back 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:
To utilize MDC, there are two main steps:
- Populating the MDC Object (Map)
- Referencing the MDC Properties (Logging Pattern)
/**
* 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:
* 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
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 the 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.xml with the following contents:
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 the 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.xml with 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:
<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 “:-” delimiter 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 at 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
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 “:-” delimiter 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 at 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:
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: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 a 6.3 instance. The logic for setting OSGi configuration properties for header, cookie, and parameters could be mirrored in this example if desired.
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 a 6.3 instance. The logic for setting OSGi configuration properties for header, cookie, and parameters could be mirrored in this example if desired.
Source:
No comments:
Post a Comment
If you have any doubts or questions, please let us know.