JBoss 7.1.1-Final logging from Startup EJB

[firebet99]

My overall goal is to figure out why my application will not log using the JBoss logging subsystem. The most it seems to do is output errors into the console and server.log file using stderr but I get no logging below that despite changing standalone.xml root logger to DEBUG and it doesn't appear to log using my package structure. Every other 3rd party piece of code seems to log except my app and it's driving me crazy.

I initially suspected a rogue log4j.properties file somewhere in the 3rd party application libraries is messing up things. -Dlog4j.debug did seem to pickup an erroneous properties file, but even after removing that, I still can't log as it now finds no appenders for my classes and the JBoss logging subsystem settings seem to be getting ignored.

In order to isolate the problem I created a standalone EAR to test with.

I have a basic EAR file with one jar that contains a single class annotated with @Startup with a @PostConstruct method that simply logs 4 statements at debug, info, warn and error.

I include the Apache commons logging 1.1.1 jar in the EAR/lib folder, I create loggers using LogFactory and Log

org.apache.commons.logging.Log;

org.apache.commons.logging.LogFactory;

There is no log4j.xml or log4j.properties file in my test deployment, so I am (maybe incorrectly) expecting Apache commons to use the JBoss logging subsystem settings, however I get the familiar:
log4j:WARN No appenders could be found for logger

when the application starts deploying and the @PostConstruct code is run.

I suspect this is because the EJB is being deployed and the @PostConstruct method is being executed _before_ the JBoss logging subsystem starts? When running the full application, the logging subsystem appears to be one of the last things started. I assume this is why the logging.properties file is included (I read the note on the wiki about that)?

Finally, if I add java.util.logging.Logger to the EJB and output the same logging statements using that, it works.

My questions are:

1) How should I configure logging using Apache Commons Logging if I want to log from EJB startup beans and I want to use the JBoss logging subsystem? (Can it be done?) I've seen a lot of posts on how to disable JBoss logging to use log4j in an application deployment, but not many on actually getting it to work! The Apache commons logging does not appear to work. If I change the logger in the EJB classes to java.util.logging.Logger it works but I don't want to mix logging implementations within the project.

2)  It seems odd that logging is started so late, potentially after application code has started to execute... Can the start order of subsystems be changed to start logging subsystem before EJBs are deployed?

3) Is there an 'easy' way of forcing the deployment (in 7.1.1) to ignore any 3rd party log4j configuration files and only use the JBoss logging subsystem? From what I've read, the logger implementation scans for configuration files in the deployment and will use the first one it finds. I want to stop it doing this I guess. I also want to avoid having to specify a log4j.configuration=/path/to/external/file

4) Can I debug the JBoss logging subsystem to figure out why my application class log statements are being ignored/thrown away despite me setting the high-level package to DEBUG?

Hoping the answer isn't "upgrade to Wildfly 8.0" as that will be difficult from a project perspective.

I can post files/logs/config/etc if required.

Many thanks for any insights.

[jamezp]

Are you including apache-commons-logging and/or log4j in your deployment?

1) How should I configure logging using Apache Commons Logging if I want to log from EJB startup beans and I want to use the JBoss logging subsystem? (Can it be done?) I've seen a lot of posts on how to disable JBoss logging to use log4j in an application deployment, but not many on actually getting it to work! The Apache commons logging does not appear to work. If I change the logger in the EJB classes to java.util.logging.Logger it works but I don't want to mix logging implementations within the project.

As long as you don't include the logging frameworks in your deployment it should work.

2)  It seems odd that logging is started so late, potentially after application code has started to execute... Can the start order of subsystems be changed to start logging subsystem before EJBs are deployed?

Logging doesn't start after a deployment. Well I guess in 7.1.1.Final you could potentially see a small gap coming from the logging.properties and when the subsystem configuration gets started, but it would be small and likely not happen after a deployment is processed. This won't happen in WildFly or JBoss EAP 6 as logging is internally configured a bit differently.

3) Is there an 'easy' way of forcing the deployment (in 7.1.1) to ignore any 3rd party log4j configuration files and only use the JBoss logging subsystem? From what I've read, the logger implementation scans for configuration files in the deployment and will use the first one it finds. I want to stop it doing this I guess. I also want to avoid having to specify a log4j.configuration=/path/to/external/file

In 7.1.1.Final the logging subsystem does not look for logging configuration files. That only happens in JBoss EAP 6 and WildFly.

4) Can I debug the JBoss logging subsystem to figure out why my application class log statements are being ignored/thrown away despite me setting the high-level package to DEBUG?

Definitely, but you'd have to create the patch The logging subsystem drastically changed after 7.1.1.Final so back porting anything could be rather difficult.

HTH,

--

James R. Perkins

[firebet99]

James, many thanks for responding. You have it nailed in the first line "am I including log4j in the deployment?". Not in my EAR file deployment but re-checking the settings of standalone.xml I found a custom globally inherited module for GridGain (part of our project setup that I had forgotten about).

Tracing through the custom GridGain module configuration, it loads a log4j jar as one of it's library references.  I changed the GridGain module configuration to omit the references to log4j and slf4j in the resources section and added a module dependency to the JBoss org.apache.log4j module and now the configuration works as expected.

Lessons learned: Always test with a fresh installation...

As an aside, in response to your answer to my second question about when the logging subsystem starts, I think I was getting confused over the output I was seeing in the logs in relation to the deployment of the EJBs. The message "Logging subsystem started" seemed to come after the EJBs were deployed and after log4j failed to find a logger for my classes, leading me to think that @PostConstruct was somehow being executed before the logging subsystem was initialized. I can now see from the working configuration that this isn't the case, and that the logging subsystem starts before any logging output from the EJB which is what I would expect, e.g. don't execute any code until the app server is fully started...

Thanks again.