1 Reply Latest reply on Feb 27, 2014 2:25 PM by jamezp

    Strange log4j behaviour with multiple ear sharing a class with custom layout

    mlaporta

      Hi All,

      in my application I have some ear's with log4j.xml inside. The layout of each ear look like this:

       

      connector.ear

      ├── connectors-service-ejb.jar

      ├── META-INF

      │   ├── application.xml

      │   ├── jboss-deployment-structure.xml

      │   ├── jboss-ejb-client.xml

      │   └── log4j.xml

      └── connector-singleton.jar

       

      The log4j.xml used look like this:

       

      <?xml version="1.0" encoding="UTF-8" ?>

      <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

      <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

       

       

        <appender name="APPLICATION" class="org.apache.log4j.DailyRollingFileAppender">

        <param name="DatePattern" value="'.'yyyy-MM-dd" />

        <param name="File" value="${jboss.server.log.dir}/connector1.log" />

        <param name="Append" value="true" />

        <layout class="org.apache.log4j.PatternLayout">

        <param name="ConversionPattern" value="%d [%c][%t] [%p]:%L - %m%n" />

        </layout>

        </appender>

       

       

        <appender name="JSON_FILE" class="org.apache.log4j.DailyRollingFileAppender">

        <param name="DatePattern" value="'.'yyyy-MM-dd" />

        <param name="File" value="${jboss.server.log.dir}/json-connector1.log" />

        <param name="Append" value="true" />

        <layout class="com.myspace.log4j.Log4jJsonLayout" />

        </appender>

       

        <appender name="JSON_STAT" class="org.apache.log4j.DailyRollingFileAppender">

        <param name="DatePattern" value="'.'yyyy-MM-dd" />

        <param name="File" value="${jboss.server.log.dir}/json-twitter.log" />

        <param name="Append" value="true" />

        <layout class="com.myspace.log4j.SimpleJsonLayout" />

        </appender>

       

       

        <logger name="com.myspace.queue.consumer.QueueMessageStat"

        additivity="false">

        <level value="INFO" />

        <appender-ref ref="JSON_STAT" />

        </logger>

       

        <category name="com.myspace.connector1">

        <priority value="ERROR" />

        </category>

        <category name="org">

        <priority value="ERROR" />

        </category>

        <category name="kafka">

        <priority value="ERROR" />

        </category>

       

        <root>

        <priority value="ERROR" />

        <appender-ref ref="APPLICATION" />

        <appender-ref ref="JSON_FILE" />

        </root>

      </log4j:configuration>

       

       

      The class com.myspace.queue.consumer.QueueMessageStat is inside a common shared module.

      The two  layout classes  are inside a same common shared module. In order to correctly load the layout I add the common module dependencies to the following module:

      <module xmlns="urn:jboss:module:1.1" name="org.jboss.log4j.logmanager">

      ..

      </module>

       

      The problem is the JSON_STAT appender.Each ear should log in a different log filename:

       

      -rw-rw-r-- 1 michele michele      0 feb 26 08:55 json-rssblog.log

      -rw-rw-r-- 1 michele michele      0 feb 26 08:55 rsscrawler-connector.log

      -rw-rw-r-- 1 michele michele      0 feb 26 08:55 rssblog-connector.log

      -rw-rw-r-- 1 michele michele      0 feb 26 08:55 google-connector.log

      -rw-rw-r-- 1 michele michele      0 feb 26 08:55 bing-connector.log

      -rw-rw-r-- 1 michele michele   5882 feb 26 09:40 facebook-connector.log

      -rw-rw-r-- 1 michele michele   6370 feb 26 09:40 json-facebook.log

      -rw-rw-r-- 1 michele michele  24310 feb 26 09:53 json-rsscrawler.log

      -rw-rw-r-- 1 michele michele   8385 feb 26 09:56 json-google.log

      -rw-rw-r-- 1 michele michele 262490 feb 26 09:58 twitter-connector.log

      -rw-rw-r-- 1 michele michele 398051 feb 26 09:58 json-twitter.log

      -rw-rw-r-- 1 michele michele   1159 feb 26 09:59 json-bing.log

       

      But this not happen. For example in json-bing.log I found  twitter/facebook logs:

       

      {"timestamp":1393402366486,"date":"Feb 26, 2014 9:12:46 AM","hostname":"orion","username":"michele","level":"INFO","thread":"Twitter4J Async Dispatcher[0]","classname":"com.myspace.queue.kafka.consumer.QueueMessageStat","linenumber":53,"topic":"TWITTER_INPUT","rx":0,"rxRate":0.0,"tx":1,"txRate":0.1}

      {"timestamp":1393402408071,"date":"Feb 26, 2014 9:13:28 AM","hostname":"orion","username":"michele","level":"INFO","thread":"Twitter4J Async Dispatcher[0]","classname":"com.myspace.queue.kafka.consumer.QueueMessageStat","linenumber":53,"topic":"TWITTER_INPUT","rx":0,"rxRate":0.0,"tx":1,"txRate":0.1}

      {"timestamp":1393405129963,"date":"Feb 26, 2014 9:58:49 AM","hostname":"orion","username":"michele","level":"INFO","thread":"Timer-3","classname":"com.myspace.queue.kafka.consumer.QueueMessageStat","linenumber":53,"topic":"FACEBOOK_INPUT","rx":0,"rxRate":0.0,"tx":1,"txRate":0.1}

      {"timestamp":1393405147341,"date":"Feb 26, 2014 9:59:07 AM","hostname":"orion","username":"michele","level":"INFO","thread":"Timer-2","classname":"com.myspace.queue.kafka.consumer.QueueMessageStat","linenumber":53,"topic":"FEED_INPUT","rx":0,"rxRate":0.0,"tx":41,"txRate":4.1}

       

      Sometimes only a json-*.log is used with all log inside?

      Is this happening because the QueueMessageStat is shared between ears? How to solve it?

      Any clue?

       

       

      thanks Michele

        • 1. Re: Strange log4j behaviour with multiple ear sharing a class with custom layout
          jamezp

          Anything logging through the category com.myspace.queue.consumer.QueueMessageStat will end up in json-twitter.log in the configuration you have. Are you after getting different WAR's in the EAR to log into different files? If that's the case and the com.myspace.queue.consumer.QueueMessageStat is shared, that won't work. The logger from com.myspace.queue.consumer.QueueMessageStat will be configured with which ever module accesses it first.

           

          The only way to fix this would be to create a new instance of com.myspace.queue.consumer.QueueMessageStat for each module and ensure the logger is not static.

           

          --

          James R. Perkins