What is the correct logging configuration?

[mattso]

Hi all,

  I am in the middle of repackaging my application for EAP 6.1 and are having trouble with logging configuration.

  My application used to pack everything into a single SAR, along with log4j.xml and thing would work fine.  Now that I am using EAP 6.1, I found out that I need to move certain components out into global modules.  That includes all the custom appenders I have created (extending from RollFileAppender).

  I have added the necessary java options to my standalone.sh to point to the location of my log4j.xml (while also setting log4j.debug = true).  However, I am not seeing the appenders gets called.

  Since the logging is happening in the global module and not my EAR anymore, I cannot do the "exclude log4j dependency in jboss-deployment-structure.xml + pack log4j.xml into META-INF" to resolve my issue.

  I would like to know:

1) Does JBoss ignored my log4j.xml because my loggers is under global module, which is from a different class loader than application?

2) Can I convert my log4j.xml into standalone.xml (logging sub-system) to resolve my issue?  If yes, any guide available that I can follow?

  Thanks in advance for your help!

Matthew

[jamezp]

1) Does JBoss ignored my log4j.xml because my loggers is under global module, which is from a different class loader than application?

In general, yes. JBoss AS/EAP and WildFly don't use log4j. In the logging subsystem if a log4j.xml file is found in a deployment and the org.jboss.as.logging.per-deployment system property is set to true (the default), then the logging subsystem will attempt to configure logging based on that configuration file. Which means that only deployments can be configured with log4j automatically.

2) Can I convert my log4j.xml into standalone.xml (logging sub-system) to resolve my issue?  If yes, any guide available that I can follow?

As much as I'd like to say yes, the answer is more maybe You can define log4j appenders as custom handlers (custom-handler) in the logging subsystem. The problem though was there was a fairly critical bug in EAP 6.1 which makes the appenders not append anything after a restart. The issue is fixed in WildFly and will be fixed in EAP 6.1.1. Also if you have a support contract there is a patch available for it somewhere.

So what is the best solution? Of course my take will be you ditch log4j and convert your appenders to JUL handlers (or extend the org.jboss.logmanager.ExtHandler) I realize this is probably not practical though.

Something that might work is to add a dependency to the org.jboss.log4j.logmanager module for the global module where your custom appenders are located. Then provide a log4j.xml configuration in your SAR/META-INF directory. I don't know the deployment cycle for a SAR so this may or may not get processed by the logging subsystem. If it does I think it should work. The catch though is it would only work for the SAR, e.g. if any other deployments depend on the SAR they will likely not get the same logging configuration.

Hope this helps a little at least.

--

James R. Perkins

[mattso]

Hi James,

  Thanks for your answer - I have struggled with this for the past 2 weeks and I am glad that your answer confirmed my dobut, that log4j in global module is not supported.

  I will convert my log4j to standalone.xml first to see if at least my appender gets pickup.   Next, I will try your suggestion to pack the log4j.xml in my SAR and set the dependency in my global module to see if that works.  In either case, I will share my result here. 

  Thanks for telling me with the issue concerning appending on EAP 6.1.  That leads me to think if I should jump the ship to JUL because I don't know the release time frame of EAP 6.1.1.  Any idea? 

  Again, thanks for your help!

Matthew

[jamezp]

Excellent, thanks Matthew!

I don't actually know when EAP 6.1.1 will be released.

If however you do plan on switching to JUL just let me know if you have any questions. That I do know a little about . Purely my opinion, and probably a little biased too, but JUL handlers are probably more portable in the long term. Essentially all log4j appenders are just being wrapped in a JBoss Log Manager handler when they are defined as custom handlers. In a worst case scenario you could wrap each appender in their own JUL handler and use the handler as a custom-handler for a workaround.

--

James R. Perkins

[mattso]

That is a feasible solution - I am talking with my management to see if that's achievable in our delivery time frame.  I will definitely get back to you once we decided to make the move.  Thanks a lot for your suggestions!

[mattso]

Hi James,

  I converted my log4j.xml to standalone.xml.  Some of them uses size-rotating handler while other uses custom-handler.  Nonetheless, I am experencing some strange errors.

  I set the debug flags on, and when I started my Jboss, I see that the 'setFile' method gets called for all the handler entries.  Yet, they kept repeating and it finally leads to system error where too many files has opened.  This happens to all handlers entries, regardless rather it's custom-handler or not.

  I have posted some of my standalone.xml logging subsystem entries here.  Would you please let me know if I am doing something wrong?  Thanks!

Matthew

(P.S.  The reason we have our custom-handler is because we want to use size-rotating yet we want to name the rotated file with timestamp and '.log. extension.  There doesn't seem to be such option availble in the standard size-rotating handler.)

====================================================================================================

        <subsystem xmlns="urn:jboss:domain:logging:1.2">
            <size-rotating-file-handler name="FILE" autoflush="true">
                <formatter>
                    <pattern-formatter pattern="%d %-5p [%c] %m%n"/>
                </formatter>
                <file relative-to="jboss.server.base.dir" path="log.0/server.log"/>
                <append value="true"/>
    <rotate-size value="1024k" />
    <max-backup-index value="50"/>
    <encoding value="UTF-8" />
            </size-rotating-file-handler>
...
...
            <custom-handler name="StoreTrailAppender" class="com.jj.log4j.MyRollingFileAppender" module="com.jj.log4j">
   <formatter>
       <pattern-formatter pattern="[slf5s.start][%x] %d[slf5s.DATE] %p[slf5s.PRIORITY] %m[slf5s.MESSAGE]%n"/>
   </formatter>
   <properties>
    <property name="File" value="${jboss.server.base.dir}/log.0/jjlogs/storetrail.txt"/>
    <property name="Append" value="true"/>
    <property name="MaxFileSize" value="104857k"/>
    <property name="Encoding" value="UTF-8"/>
   </properties>
  </custom-handler>
  <custom-handler name="AuditTrailAppender" class="com.jj.log4j.MyRollingFileAppender" module="com.jj.log4j">
   <formatter>
       <pattern-formatter pattern="[slf5s.start][%x] %d[slf5s.DATE] %p[slf5s.PRIORITY] %m[slf5s.MESSAGE]%n"/>
   </formatter>
   <properties>
    <property name="File" value="${jboss.server.base.dir}/log.0/jjlogs/audittrail.txt"/>
    <property name="Append" value="true"/>
    <property name="MaxFileSize" value="104857k"/>
    <property name="Encoding" value="UTF-8"/>
   </properties>
  </custom-handler>
...
...
...
            <size-rotating-file-handler name="JBossHistoryAppender" autoflush="true">
                <formatter>
                    <pattern-formatter pattern="%d %-5p %m%n"/>
                </formatter>
                <file relative-to="jboss.server.base.dir" path="log.0/jjlogs/jbosshistory.txt"/>
                <append value="true"/>
    <rotate-size value="1024k" />
    <max-backup-index value="5"/>
    <encoding value="UTF-8" />
            </size-rotating-file-handler>
            <size-rotating-file-handler name="ThreadHistoryAppender" autoflush="true">
                <formatter>
                    <pattern-formatter pattern="%d %-5p %m%n"/>
                </formatter>
                <file relative-to="jboss.server.base.dir" path="log.0/jjlogs/threadhistory.txt"/>
                <append value="true"/>
    <rotate-size value="1024k" />
    <max-backup-index value="5"/>
    <encoding value="UTF-8" />
            </size-rotating-file-handler>
...
...
            <console-handler name="CONSOLE">
                <level name="INFO"/>
                <formatter>
                    <pattern-formatter pattern="%d %-5p [%t][%c{1}] %m%n"/>
                </formatter>
            </console-handler>
            <file-handler name="JSR77" autoflush="true">
                <formatter>
                    <pattern-formatter pattern="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>
                </formatter>
                <file relative-to="jboss.server.base.dir" path="log.0/jsr77.log"/>
                <append value="false"/>
  <encoding value="UTF-8" />
            </file-handler>
...
...
  <logger category="STDOUT" use-parent-handlers="false">
   <level name="INFO"/>
   <handlers>
       <handler name="CONSOLE"/>
   </handlers>
  </logger>
  <logger category="jj.storetrail" use-parent-handlers="false">
   <level name="INFO"/>
   <handlers>
       <handler name="StoreTrailAppender"/>
   </handlers>
  </logger>
  <logger category="jj.audittrail" use-parent-handlers="false">
   <level name="INFO"/>
   <handlers>
       <handler name="AuditTrailAppender"/>
   </handlers>
  </logger>
  <logger category="org.jboss.mx.loading" use-parent-handlers="false">
   <level name="INFO"/>
   <handlers>
       <handler name="UCL"/>
   </handlers>
  </logger>
...
...
  <root-logger>
   <level name="INFO"/>
   <handlers>
       <handler name="CONSOLE"/>
       <handler name="FILE"/>
   </handlers>
  </root-logger>
</subsystem> 

[jamezp]

Hmm.. ...that seems odd. When the file is set it should be closing the other writer/output stream that was created. There was an issue where the same configuration changes were getting executed multiple times, but still the file shouldn't be leaving open output streams. You could try replacing the org.jboss.logmanager library with the version 1.4.3.Final where the multiple execution was fixed.

It's not documented and you would have to use it as a custom-handler, but there is a org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler that will rotate on the size or date.

--

James R. Perkins

[mattso]

Hi James,

  Yes, that library solvd the infinite 'setFile' calls that causes the "Too many open file" system error.  I will continue to check the rest of the stuff.

  Also, thanks for the suggestion on PeriodicSizeRotatingFileHanndler - I am looking into it's usage and see if it support what I want.

  Many many thanks for your help and speedy reply!

Matthew

[lbreuss]

For the sake of completeness, a working config:

<custom-handler name="kettle_logger_periodic_size" class="org.jboss.logmanager.handlers.PeriodicSizeRotatingFileHandler" module="org.jboss.logmanager">
    <formatter>
        <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />
    </formatter>
    <properties>
        <property name="fileName" value="${jboss.server.log.dir}/kettle.log"/>  
        <property name="rotateSize" value="1000000"/> 
        <property name="maxBackupIndex" value="99"/>        
        <property name="suffix" value=".yyyy-MM-dd_hh"/>
        <property name="autoFlush" value="true"/>
        <property name="append" value="true"/>
    </properties>
</custom-handler>