0 Replies Latest reply on Feb 5, 2014 7:09 AM by Siddhesh Malpani

    Duplicate logs in log files generated by JBoss EAP 6.1

    Siddhesh Malpani Newbie

      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..