Duplicate logs in log files generated by JBoss EAP 6.1
Hi all..
I have copied a demo project of quickstarts to get the basics of logging in JBoss EAP 6.1.
I changed it to add the MDC in the project.
The project is running fine and also recording the logs in the specified files with the MDC values.
But the problem is, it writing the duplicate logs into the log files..
Following are the files that I am using for configuration:
1. Standalone.xml (Added the following subsystem element in the file)
<subsystem xmlns="urn:jboss:domain:logging:1.2">
<async-handler name="TRACE_QS_ASYNC">
<level name="TRACE"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_TRACE"/>
</subhandlers>
</async-handler>
<async-handler name="DEBUG_QS_ASYNC">
<level name="DEBUG"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_DEBUG"/>
</subhandlers>
</async-handler>
<async-handler name="INFO_QS_ASYNC">
<level name="INFO"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_INFO"/>
</subhandlers>
</async-handler>
<async-handler name="WARN_QS_ASYNC">
<level name="WARN"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_WARN"/>
</subhandlers>
</async-handler>
<async-handler name="ERROR_QS_ASYNC">
<level name="ERROR"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_ERROR"/>
</subhandlers>
</async-handler>
<async-handler name="FATAL_QS_ASYNC">
<level name="FATAL"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="FILE_QS_FATAL"/>
</subhandlers>
</async-handler>
<console-handler name="CONSOLE">
<level name="ALL"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
</console-handler>
<periodic-rotating-file-handler name="FILE" autoflush="true">
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="server.log"/>
<suffix value=".yyyy-MM-dd"/>
<append value="true"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_TRACE" autoflush="true">
<level name="TRACE"/>
<filter-spec value="levels(TRACE)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.trace.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_DEBUG" autoflush="true">
<level name="DEBUG"/>
<filter-spec value="levels(DEBUG)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.debug.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_INFO" autoflush="true">
<level name="INFO"/>
<filter-spec value="levels(INFO)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.info.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_WARN" autoflush="true">
<level name="WARN"/>
<filter-spec value="levels(WARN)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.warn.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_ERROR" autoflush="true">
<level name="ERROR"/>
<filter-spec value="levels(ERROR)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.error.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<periodic-rotating-file-handler name="FILE_QS_FATAL" autoflush="true">
<level name="FATAL"/>
<filter-spec value="levels(FATAL)"/>
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n"/>
</formatter>
<file relative-to="jboss.server.log.dir" path="quickstart.fatal.log"/>
<suffix value=".yyyy.MM.dd"/>
</periodic-rotating-file-handler>
<logger category="com.arjuna">
<level name="WARN"/>
</logger>
<logger category="org.apache.tomcat.util.modeler">
<level name="WARN"/>
</logger>
<logger category="org.jboss.as.config">
<level name="DEBUG"/>
</logger>
<logger category="sun.rmi">
<level name="WARN"/>
</logger>
<logger category="jacorb">
<level name="WARN"/>
</logger>
<logger category="jacorb.config">
<level name="ERROR"/>
</logger>
<logger category="org.jboss.as.quickstarts.logging">
<level name="ALL"/>
<handlers>
<handler name="TRACE_QS_ASYNC"/>
<handler name="DEBUG_QS_ASYNC"/>
<handler name="INFO_QS_ASYNC"/>
<handler name="WARN_QS_ASYNC"/>
<handler name="ERROR_QS_ASYNC"/>
<handler name="FATAL_QS_ASYNC"/>
</handlers>
</logger>
<logger category="com.eurexrepo.ntp.util">
<level name="TRACE"/>
<handlers>
<handler name="TRACE_QS_ASYNC"/>
<handler name="DEBUG_QS_ASYNC"/>
<handler name="INFO_QS_ASYNC"/>
<handler name="WARN_QS_ASYNC"/>
<handler name="ERROR_QS_ASYNC"/>
<handler name="FATAL_QS_ASYNC"/>
</handlers>
</logger>
<root-logger>
<level name="INFO"/>
<handlers>
<handler name="CONSOLE"/>
<handler name="FILE"/>
</handlers>
</root-logger>
</subsystem>
2. logging.properties
loggers=jacorb,com.arjuna,org.jboss.as.quickstarts.logging,org.jboss.as.config,org.apache.tomcat.util.modeler,jacorb.config,sun.rmi,com.eurexrepo.ntp.util
logger.level=INFO
logger.handlers=CONSOLE,FILE
logger.jacorb.level=WARN
logger.jacorb.useParentHandlers=true
logger.com.arjuna.level=WARN
logger.com.arjuna.useParentHandlers=true
logger.org.jboss.as.quickstarts.logging.level=ALL
logger.org.jboss.as.quickstarts.logging.useParentHandlers=true
logger.org.jboss.as.quickstarts.logging.handlers=DEBUG_QS_ASYNC,INFO_QS_ASYNC,TRACE_QS_ASYNC,FATAL_QS_ASYNC,ERROR_QS_ASYNC,WARN_QS_ASYNC
logger.org.jboss.as.config.level=DEBUG
logger.org.jboss.as.config.useParentHandlers=true
logger.org.apache.tomcat.util.modeler.level=WARN
logger.org.apache.tomcat.util.modeler.useParentHandlers=true
logger.jacorb.config.level=ERROR
logger.jacorb.config.useParentHandlers=true
logger.sun.rmi.level=WARN
logger.sun.rmi.useParentHandlers=true
logger.com.eurexrepo.ntp.util.level=TRACE
logger.com.eurexrepo.ntp.util.useParentHandlers=true
logger.com.eurexrepo.ntp.util.handlers=DEBUG_QS_ASYNC,INFO_QS_ASYNC,TRACE_QS_ASYNC,FATAL_QS_ASYNC,ERROR_QS_ASYNC,WARN_QS_ASYNC
# Additional handlers to configure
handlers=FILE_QS_DEBUG,FILE_QS_FATAL,FILE_QS_INFO,FILE_QS_ERROR,FILE_QS_TRACE,FILE_QS_WARN
handler.FILE_QS_DEBUG=org.jboss.logmanager.handlers.PeriodicRotatingFileHandler
handler.FILE_QS_DEBUG.level=DEBUG
handler.FILE_QS_DEBUG.filter=levels(DEBUG)
handler.FILE_QS_DEBUG.formatter=FILE_QS_DEBUG
handler.FILE_QS_DEBUG.properties=enabled,autoFlush,append,fileName,suffix
handler.FILE_QS_DEBUG.enabled=true
handler.FILE_QS_DEBUG.autoFlush=true
handler.FILE_QS_DEBUG.append=true
handler.FILE_QS_DEBUG.fileName=C\:\\Install\\jBoss\\jboss-eap-6.1\\standalone\\log\\quickstart.debug.log
handler.FILE_QS_DEBUG.suffix=.yyyy.MM.dd
handler.DEBUG_QS_ASYNC=org.jboss.logmanager.handlers.AsyncHandler
handler.DEBUG_QS_ASYNC.level=DEBUG
handler.DEBUG_QS_ASYNC.formatter=DEBUG_QS_ASYNC
handler.DEBUG_QS_ASYNC.handlers=FILE_QS_DEBUG
handler.DEBUG_QS_ASYNC.properties=enabled,queueLength,overflowAction
handler.DEBUG_QS_ASYNC.constructorProperties=queueLength
handler.DEBUG_QS_ASYNC.enabled=true
handler.DEBUG_QS_ASYNC.queueLength=1024
handler.DEBUG_QS_ASYNC.overflowAction=BLOCK
formatter.FILE_QS_DEBUG=org.jboss.logmanager.formatters.PatternFormatter
formatter.FILE_QS_DEBUG.properties=pattern
formatter.FILE_QS_DEBUG.constructorProperties=pattern
formatter.FILE_QS_DEBUG.pattern=%d{HH\:mm\:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n
formatter.DEBUG_QS_ASYNC=org.jboss.logmanager.formatters.PatternFormatter
formatter.DEBUG_QS_ASYNC.properties=pattern
formatter.DEBUG_QS_ASYNC.constructorProperties=pattern
formatter.DEBUG_QS_ASYNC.pattern=%d{HH\:mm\:ss,SSS} %-5p [%c] %X{userName} - %X{sessionId} (%t) %s%E%n
##Similarly other handlers..
Following the files that I am using in the project:
1. LoggingExample.java
package org.jboss.as.quickstarts.logging;
import org.jboss.logging.Logger;
import org.jboss.logging.MDC;
public class LoggingExample
{
// a JBoss Logging 3 style level (FATAL, ERROR, WARN, INFO, DEBUG, TRACE), or a special level (OFF, ALL).
private static Logger log = Logger.getLogger(LoggingExample.class.getName());
static
{
MDC.put("userName", "Siddhesh");
MDC.put("sessionId","1234567890");
logFatal();
logError();
logWarn();
logInfo();
logDebug();
logTrace();
MDC.remove("userName");
MDC.remove("sessionId");
}
public static void logInfo()
{
if (log.isEnabled(Logger.Level.INFO))
{
log.info("THIS IS AN INFO MESSAGE");
}
}
public static void logDebug()
{
if (log.isEnabled(Logger.Level.DEBUG))
{
log.debug("THIS IS A DEBUG MESSAGE");
}
}
.
.
.//Similarly other methods..
}
2. home.jsp
<%@ page language="java" contentType="text/html; charset=UTF-8" pageEncoding="UTF-8"%> <%@ page import="org.jboss.as.quickstarts.logging.LoggingExample" %> <!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd"> <html> <head> <meta http-equiv="Content-Type" content="text/html; charset=UTF-8"> <title>Logging Quickstart</title> </head> <body> <% LoggingExample.logDebug(); LoggingExample.logError(); LoggingExample.logFatal(); LoggingExample.logInfo(); LoggingExample.logTrace(); LoggingExample.logWarn(); %> Log Messages have been written. Please check your console as well as <i>/JBoss_Home</i>/standalone/log for messages </body> </html>
3. index.html
Actual output:
a. quickstart.debug-
21:49:48,885 DEBUG [org.jboss.as.quickstarts.logging.LoggingExample] Siddhesh - 1234567890 (http-localhost/127.0.0.1:8080-1) THIS IS A DEBUG MESSAGE
21:49:48,885 DEBUG [org.jboss.as.quickstarts.logging.LoggingExample] - (http-localhost/127.0.0.1:8080-1) THIS IS A DEBUG MESSAGE
b. quickstart.info-
21:49:48,885 INFO [org.jboss.as.quickstarts.logging.LoggingExample] Siddhesh - 1234567890 (http-localhost/127.0.0.1:8080-1) THIS IS AN INFO MESSAGE
21:49:48,886 INFO [org.jboss.as.quickstarts.logging.LoggingExample] - (http-localhost/127.0.0.1:8080-1) THIS IS AN INFO MESSAGE
.
.
.... and same continues with other log files.
Expected output:
a. quickstart.debug-
21:49:48,885 DEBUG [org.jboss.as.quickstarts.logging.LoggingExample] Siddhesh - 1234567890 (http-localhost/127.0.0.1:8080-1) THIS IS A DEBUG MESSAGE
b. quickstart.info-
21:49:48,885 INFO [org.jboss.as.quickstarts.logging.LoggingExample] Siddhesh - 1234567890 (http-localhost/127.0.0.1:8080-1) THIS IS AN INFO MESSAGE
Actually I have 2 questions related with this post:
A. Why are the logs redundant logs getting generated..??
B. When I reload the page, logs without MDC are getting generated for every reload, whereas I expect the logs with MDC to be generated.
Even the smallest help is appreciated. Thanks..