Wildly logging subsystem - handler to route all to log4j

[nuno.godinhomatos]

The use case is simple.

Imagine a jdk stand alone application - no container.

You use a couple of different libraries from A, B or C.

Some use java util logging, some use slf4j, some use log4j, some use whatever.

You want a uniform logging, you have your own special appenders for say log4j1.

You do not want to lose time migrating to log4j2 yet, it is not a problem.

So - task is easy.

You start your application the -Dlogj4j=/some/arbitrary/path/to/configurationFile.[xml|| properties], and then you add to you application cllasspath all sorts of SLF4j dependencies to JUL to SLF4j, jboss logging to slf4j, etc, until you get the slf4j to log4j.

You are set to go.

So this is the JDK scenario.

Now the problem.

Imagine you want to do exctly the same thing in wildfly.

Wildfly conveniently comes with all bindings from java util logging to wildfly log manager, log4j to wildly log manager etc..

In the end you have your subsystem logging where you can sepicy some handlers, typically something among those provided like rolling file appender.

Now, say we do not want to do this.

We really want ALL logging, not just that of some arbitrary deployment.

We want cross cutingly all logging to go log4j where you have your own special appenders.

How can we do this?

I have spotted the following guide.

Using Apache Log4j 2 as logger for WildFly 9 - Java Tipps + Tricks

It seems to be answer I am looking for.

In a phrase:

What I really want, is to get exactly the same behavior, that I would have if my application from the very begging only had as logging just with SLFJ4j as the logging infrastructure: all log to slf4j, slf4j logs to log4j, I control the log4j,xml properties where I have my own existing appenders.

Why I am skeptical about the above guide:
(a) If the handler to be implemented is a Java Util Logging to Log4j handler - than this spells disaster.

Why? Because java util logging as an API is unusable. Some examples ...

- The thread ids are integers and not long, becomming corrupted since a Thread.getThreadId() is not an integer.

- Java util logging events if I recall correctly, do not even have a thread name in there.

- Java util logging has no concept for the MDC api of Slf4j and Log4j - and an application logging with Slf4j might be adding additional metadata such as LogContext (userId) to log data to a specific dedicated file per user - as an exmaple.

All of this, does not exist in Jdk logging.

So at the API level - I simply suspect that If I have work with JDK logging it is a lost battle from the start.

(b) From what I have been able to see in a sample applciation, if have the subsytem logging enabled.

Even apache logging maps to the wildfly log manager handlers. Because the logging of

private static final org.apache.log4j.Logger LOG4J_LOGGER = org.apache.log4j.Logger

            .getLogger(LongOnServerRestEndpoint.class);

I see, ends up in the server.log file - all correctly.

I undestand that jboss logging may be a superior.

But the point is, we have a universe of log4j appenders that at this point are not to be implemented log4j2 appenders or jboss logging appenders, or appenders on any other sort of logging implementation.

In short routing every log to self4j and slf4j to log4j is ideal.

And this is not be done at deployment level - but at application wide level.

So that any logging event reported by the app server is fully getting handle by these special appenders.

Therefore, is the above guide the way to go?

By using JUL there we would not be losing metadata in the transform to log4j events?

And our log4j events would not be retro feeding back to the widlfly log manager?

Many thanks for some insight into this.

I will ultimately test the above approach - but I would prefer to avoid going into a black hole.

Thanks for the help.

[nuno.godinhomatos]

Just a quick note, I am now convinced the approach on the paper is a nice way to go.

I have seen that wildfly does not use the vanilla log records from java util logging, and has its extension class with information on steroids.

org.jboss.logmanager.ExtLogRecord <--- And this guy here looks like a nice implementat of a log record.

So therefore, the subsystem logging from wildfly looks like the perfect spot to what I wish.

All I have to make sure is that the subsytem does not enable log4j to slf4j to avoid a loop around of log records.

With log4j 2 logging this would not be a problem apprently.

But with log4j1 it likely is.

[nuno.godinhomatos]

Yup,

THe handler approach is quite ideal.

I did find myself writing a Java Util  logging to Log4j logging router, based on what slf4j that when it routes JUL to SLF4J and then later on what it does when it rouws SLF4j to Log4j.

But one you re-invent the wheel once a again to the routing from A to B.

Then it is just a matter of waiting for the subsytem logger to startup our new handler.

Once all properties on our custom handler are provided to our handler (e.g. jboss.server.log.dir), we are set to configure our logger implemenation:

new PropertyConfigurator().doConfigure(log4jWlsPropertiesFile.getAbsolutePath(),

                LogManager.getLoggerRepository());

And then it is just a matter of extending the modules folder (not the sysb.base) modules folder - I find that quite dirty. The base folder should be left untouched.

With a stream of modules that add to the classpath e.g.:

1. Log4j1 - the old log4j in this case

2. All your custom appenders - that are the reason you are in the first place trying to fight against the tide. Some appendrs can be quite smart, and it is not really worth the effort to re-implement everything based a different logging api. Too much effort.

3. You should make your module has as well a dependency on the org.jboss.logmanager, becaause otherwise you cannot approach the org.jboss.logmanager.ExtLogRecord .

And quite frankly, without this class org.jboss.logmanager.ExtLogRecord  ... having to use java util logging valine LogRecord ... there is no hope at al. You might as well not log.

But all in all I am quite satisfied with the logging subsytem from wildfly.

I think there is a bit of lack of documentation, on how people can tune the subsytem - namely with this handler approach, to when needed continue using the logging infrascture from widlfly plus an alternate logging infrascture if reuired.

In my case, for the time being, I want the console logger from the wildfly to be doing log handling as that is useful during development time to see on eclipse the console pumped with messages.

But for file writing or other types of data writing,then  I need my appenders implemented in whichver logging framework they were originally written.

And I think this flexibility is absolutely critical.

Good thing that Wildfly does not really get in the way ... but i struggled with lack of information I must say.

Kindest regards.

[nuno.godinhomatos]

Hi,

I would like to add the following note.

I have the impression that there is some sort of undeterministic behavior in the class loading doing the logging subystem intialization.

There is already open a thread concerning eclipse startup errors where sometimes the logmanager class cannot be found. That happen without any apparent reason.

But now, in code that I was directly working I have come to an interesting problem.

Yesteday, I was convinced I had the core of the log routing mechanism working.

Debugging was working fine. Triggering server start was working fine.

Then today, for no explainable reason exceptions like the following popped up:

------------------------------------

2017-08-25 14:50:59,597 ERROR [stderr] (Controller Boot Thread) log4j:ERROR

A "org.apache.log4j.PatternLayout" object is not assignable to a "org.apache.log4j.Layout" variable.

2017-08-25 14:50:59,597 ERROR [stderr] (Controller Boot Thread)

log4j:ERROR The class "org.apache.log4j.Layout" was loaded by

2017-08-25 14:50:59,598 ERROR [stderr] (Controller Boot Thread)

log4j:ERROR [ModuleClassLoader for Module "company.org.apache.log4j1:main" from local module loader @5b1d2887

(finder: local module finder @46f5f779 (roots: C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules,C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules\system\layers\base))]

whereas object of type

2017-08-25 14:50:59,598 ERROR [stderr] (Controller Boot Thread) log4j:ERROR

"org.apache.log4j.PatternLayout" was loaded by [ModuleClassLoader for Module "org.jboss.log4j.logmanager:main" <----- This guy has common classes

from local module loader @5b1d2887 (finder: local module finder @46f5f779 (roots: C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules,C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules\system\layers\base))].

-------------------------------------

In short, when I was writing the new modules mocules/company/whateverpath/main/module.xml

I had already at that point in time been concerned of precisely problems like this.

I had hunted for modules/sys/base/log4j / org.log4j

And I had not found anything. So I was not sure if there would be some module hidden somewhere with log4j like code.

But hey, everything had worked fine.

And today the above exception.

So that is an indication that the boot logic seems to have some degree of indeterminism in class loading - even if the module.xml architecture should in theory ensure that this is not the case.

To me it looks like it must be the case.

To me this change of behavior looks quite critical.

Now I tried configuring my module of appeders that depends on the log4j implementation to exclude the log4j core implementation and instead use the one bundled in the base modules.

To try to be safe from problems like this.

This of course did not work, because the org.jboss.log4j.logmanager lacks the property configurator class, which I need to read my log4j.properties file.

Because of all of the above, the module now looks like tis:

<module xmlns="urn:jboss:module:1.5" name="company.org.apache.log4j1">

  <resources>

     <resource-root path="log4j-1.2.17.jar" />

<!-- Our MDC appenders -->

<resource-root path="company-logging-appenders-log4j-1.0.1.jar"/>

  </resources>

  <dependencies>   

      <!-- Wildfly bundles log4j 1 in their maintained module.

We therefore cannot include log4j ourselves to avoid class loading problems.-->

<module name="org.jboss.log4j.logmanager">

<exports>

<exclude path="org/apache/log4j/**" /> ------------------------ Here I try to dodge the random bullet on class loading

</exports>

</module>

     <module name="javax.api"/>

<module name="org.slf4j"/>

  </dependencies>

</module>

I hope this information is of use.

Kindest regards.

[ctomc]

If I understand you correctly, all you actually want it to use your custom log4j appenders with wildfly. Right?

[nuno.godinhomatos]

That is correct.

Essentially.

What I am doing now, is that I have in the subsytem configuration something that looks like this:

<subsystem xmlns="urn:jboss:domain:logging:3.0">

            <console-handler name="CONSOLE">

                <level name="INFO"/>

                <formatter>

                    <named-formatter name="COLOR-PATTERN"/>

                </formatter>

            </console-handler>

            <custom-handler name="ROOT_WILDFLY_TO_LOG4J" class="com.company.logging.wildfly.CompnayJulToLog4jHandler" module="compnay.logginglog4j1">

                <properties>

                    <property name="jbossServerLogDir" value="${jboss.server.log.dir}"/>

                </properties>

            </custom-handler>

            <logger category="com.arjuna">

                <level name="DEBUG"/>

            </logger>

            <logger category="org.jboss.jca">

                <level name="INFO"/>

            </logger>

            <logger category="org.jboss.as.connector">

                <level name="INFO"/>

            </logger>

            <logger category="org.jboss.as.config">

                <level name="INFO"/>

            </logger>

            <logger category="sun.rmi">

                <level name="WARN"/>

            </logger>

            <root-logger>

                <level name="INFO"/>

                <handlers>

                    <handler name="CONSOLE"/>

<handler name="ROOT_WILDFLY_TO_LOG4J"/>

                </handlers>

            </root-logger>

            <formatter name="PATTERN">

                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (thread: %t) %s%e%n"/>

            </formatter>

            <formatter name="COLOR-PATTERN">

                <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (thread: %t) %s%e%n"/>

            </formatter>

        </subsystem>

That means, I get the benefit of being able to use the wildfly handlers, if i want.

But i get the benefit as well of logging with any of our handlers.

Such as specific MDC handlers - that write dedicated log files for specific Mdc contexts and such.

The writing of CompnayJulToLog4jHandler is in fact quite trivial, because when the log manager from wildfly is calling our handler, we are in the same thread context it would seem as the caller of the log statement.

So in fact, I can use simply LOG4J_LOGGER.log() apis, without needing to go through the pain of builiding the interal LogRercords from log4j manually.

So you can pretty much route from Jul Logging to Log4j in a way that is similar to how slf4j solves the problem.

Not 100% similar, because they create Slf4jLogger wrappers where they map each public slf4j logging api to a corresponding log4j api call.

And in our routing case it is sufficient to just have an api to route a JUL LogRecord from wildlfy to a LOG.() statement on log4j.

So that part is difficult.

Where I seem to still be struggling is with the classpath.

I believe I still have not solved the problem of how to isolate this logging module from the built int log4j implementation within wildfly.

Sometimes logging is working perfectly.

Sometimes, during startup I am still getting the exceptions:

---------------------------------------------------------------------------

2017-08-27 11:20:58,814 INFO  [org.jboss.as.server] (thread: Controller Boot Thread) WFLYSRV0039: Creating http management service using socket-bindin

g (management-http)

2017-08-27 11:20:58,829 INFO  [org.xnio] (thread: MSC service thread 1-6) XNIO version 3.4.0.Final

2017-08-27 11:20:58,836 INFO  [org.xnio.nio] (thread: MSC service thread 1-6) XNIO NIO Implementation Version 3.4.0.Final

2017-08-27 11:20:58,881 INFO  [org.jboss.remoting] (thread: MSC service thread 1-3) JBoss Remoting version 4.0.21.Final

2017-08-27 11:20:58,883 ERROR [stderr] (thread: Controller Boot Thread) log4j:ERROR A "org.apache.log4j.PatternLayout" object is not assignable to a "

org.apache.log4j.Layout" variable.

2017-08-27 11:20:58,884 ERROR [stderr] (thread: Controller Boot Thread) log4j:ERROR The class "org.apache.log4j.Layout" was loaded by

2017-08-27 11:20:58,885 ERROR [stderr] (thread: Controller Boot Thread) log4j:ERROR [ModuleClassLoader for Module "company.org.apache.log4j1:main" fr

om local module loader @1c2c22f3 (finder: local module finder @18e8568 (roots: C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules,C:\dev\appserver\

wildfly\wildfly-10.1.0.Final\modules\system\layers\base))] whereas object of type

2017-08-27 11:20:58,885 ERROR [stderr] (thread: Controller Boot Thread) log4j:ERROR "org.apache.log4j.PatternLayout" was loaded by [ModuleClassLoader

for Module "org.jboss.log4j.logmanager:main" from local module loader @1c2c22f3 (finder: local module finder @18e8568 (roots: C:\dev\appserver\wildfly

\wildfly-10.1.0.Final\modules,C:\dev\appserver\wildfly\wildfly-10.1.0.Final\modules\system\layers\base))].

---------------------------------------------------------------------------

I had hoped that with my export/excludes combo on the module definition  my module would be free from the interference from the org.jboss.log4j.logmanager:main.

But it seems that I cannot get this behavior to be consistent.

That is quite a pain.

I am considering the possibility of hacking up a jar - where I include the missing log4j packages for configuration that are not bundled by org.jboss.log4j.logmanager:main.

When I am creating a new wildfly domain, I am copying over to the configuration/ folder a dynamically created log4jwildfly.properties file, that this com.company.logging.wildfly.CompnayJulToLog4jHandler will need to read.

But the classes that allow log4j to configure itself with this configuration file lack in the  org.jboss.log4j.logmanager:main.

Quite a struggle.

[nuno.godinhomatos]

I have now tried to start and stop wildfly 15 times in a row.

And the classpath is working exactly as I want it, the logging is wroking flawlessly.

But I really am not confident that the solution is good yet ... In fact I am sure it is not.

I know that the logging exception I had above can happen for no obvious reason during boot of the app server.

I wonder if I can improve the modules.xml metadata to better ensure that the classloader for the modules does not approach the builting log4j.

But I think I will be safest if I can pull of a hack where I do not need bundle in myself and log4j module.

I will use as temporary dirty solution what I have implemented, and I think i will cook up a slashed up log4j jar file with needed classes to pull off a log4j configuration.

Then I can be 100% certain that the Rolling Fille appender, the patter layouts etc... all come from the library that is bundled by wildfly.

I do not trust the module.xml subsystem 100% to give me this level of isolation, i think there is some degree of randomness there when two or more libraries have the same classes.

[nuno.godinhomatos]

I have now made a new experiment to try to get rid once and for all from the Module class loader problem that sometimes takes place.

I did what I never wanted to do which is to go to an base module of wildfly, in particular the org.jbos.logmanager.log4j and tried to add in there the appenders.

Otherwise, what I have seen is the module isolation would ensure that the org.jboss.logmanager.log4j/org/apachage/log4j/PropertyConfigurator - would have class not found exception while trying read a properties file with any log4j appenders outside of this specific module

So fine, I visit the  org.jboss.logmanager.log4j/ and I hack the module.xml to have as additional resources the package of appenders we need to be able to interpret the log4j.properties file we want to consume.

And then ..

My original fear with using the log4j bundled by wildfly came true - essentially an infeed loop of recursing logging of the same statement.

When we use this wildfly module as our Log4j implementation, what will happen is that when the log4j reads our properties files it does respect all the appenders in there but it must be additionally always be injecting a wildfly specific appender to route from Log4j to the wildfly log manager.

As a result, at the very first log message we go to an infinite loop of logging the same statement until we get a stack overflow for gooing too dep.

E.g.

####2017-08-27 14:46:31,184 ThreadId:1 DEBUG javax.management.mbeanserver - Send create notification of object java.lang:name=Compressed Class Space,type=MemoryPool <LogContext:none> <main>

####2017-08-27 14:46:31,184 ThreadId:1 DEBUG javax.management.mbeanserver - Send create notification of object java.lang:name=Compressed Class Space,type=MemoryPool

Therefore, it is clear at this point in time that the approach of creating your own independent module outside of sys/base is the way to go.

The only problem of the right approach here, is that the class loading module management is not 100% consistent.

[nuno.godinhomatos]

There is definitely a very strange behavior - i would call it an unkown bug - in the wildfly boot procedure in regards to module loading and isolation.

The following module is what I decided to keep using.

This module.xml configuration is bugy, but I found in the end no advantage to have a RouterModule -> depent upon -> Log4j Module + Appenders. The class path issue happens with either approach.

So a single module approach is simplest to maintain.

The module looks as follows.

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

<module xmlns="urn:jboss:module:1.1" name="company.logginglog4j1">

  <resources>

<!-- The pure log4j implementation we want to use  -->

     <resource-root path="log4j-1.2.17.jar" />

<!-- Our appenders -->

<resource-root path="company-logging-log4j-1.0.1.jar"/>

<!-- Wildfly to log4j routing -->

     <resource-root path="company-wildfly-logging-tool-1.0.0-SNAPSHOT.jar"/>

<!-- This could be interesting if we wanted to add log4j properties file in this folder to be looked up by the module code. -->

     <resource-root path="."/>

  </resources>

  <dependencies>

<!-- This where we dump the log4j implementation libraries that we will need to use. -->

     <!-- module name="company.org.apache.log4j1" /-->

<!-- The wildfly bundled implementation we DO NOT want to use. It routes the logManager - and we do not want this.

In addition it is isolated in such a manner thta it would not accept any additional appenders unless we hack the module

resources to include our own appenders. Using a Logger from this package ensures infinite recursive logging cause by our routing handler.

-->

<module name="org.jboss.log4j.logmanager">

<exports>

<exclude path="/**" />

<exclude path="**" />

</exports>

<imports>

<exclude path="/**" />

<exclude path="**" />

</imports>

</module> 

<module name="org.apache.log4j">

<exports>

<exclude path="/**" />

<exclude path="**" />

</exports>

<imports>

<exclude path="/**" />

<exclude path="**" />

</imports>

</module> 

<!--

Depends on the jbos log manager due to its extend java util logg class.

-->

<module name="org.jboss.logmanager">

<imports>

<include path="org/jboss/logmanager/ExtLogRecord" />

</imports>

</module>

<module name="org.slf4j">

<imports>

<include path="org/slf4j" />

</imports>

</module> 

  </dependencies>

</module>

What you can see in the above module is that I try in any way possible to get rid of the bundled log4j implementation from withing this module.

And this is only partially successful.

The behavior I see is that:

(1) During automatic domain creation the class loading issue of the same class having been loaded by different modules is present.

(2) The first time I invoke the start wildfly bat from within my domain bin/ folder - the issue is present.

After that I can call the start wildfly bat as many times I want the issue goes away and logging is perfect.

(3) If I switch my start mode to use eclipse.

The first time eclipse tries to start the wildfly domain the issue is there.

The 2nd and nth time eclipse tries to start the domain, there is no more issue.

(4) If I stop working with eclipse and go back to the bin bat files, the issue is there the first time. And then goes away.

It is as if for each start mode flavor of wildfly, the first shot for that start mode is a flop.

The 2nd to nth time is a success.

Switching mode of starting the app server gives me a flop. And then good again.

This is quite a nasty issue.

CI build jobs will have to be tweaked to do a frivolous start and stop call. So that on the second start call the logging is working properly.

Can anyone give a recommendation on setting up the modules in such a way that I am certain to not have to deal with the log4j implementation of wildfly?

Or otherwise, how can I hack the log4j wildfly implementation so that when I configure it, it stops have its routing behavior to log-manager. I would like for this behavior to be killed.

Then I could switch to use the bundled log4j implementation - even if I must say - this behavior does not give a good indication that the module subsystem is stable.

Many thanks.