Duplicate logs in log files generated by JBoss EAP 6.1
malpanisiddhesh Feb 5, 2014 7:09 AMHi 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..