Application log is cut off after switching to 7.1.2/7.2.0

[maksymg]

Hi,

We are migrating our application from JBoss 4, and due to a bug in 7.1.1.Final, I start debugging it against 7.1.2/7.2.0 built from source (standalone-ha, unpacked war). To my surprise, any log messages from my application and other libraries under WEB-INF/lib like springframework are cut off the jboss log output. Since it works fine in 7.1.1.Final and I made identical changes to the server configuration, I suspect it's due to some new feature like per-deployment logging configuration. My WEB-INF/lib doens't contain any logging jars, but there are some log4j.properties in the class path which where successfully ignored in 7.1.1. We use commons-logging. Can someone clarify how to enable per-deployment logging for standalone unpacked war, if it's disabled; or what's to look for to fix this mistery. Other than that application starts and works fine.

Thanks,

Maksym

[kristjan273]

I hope it won't look like I hijacked a thread, but I was about to ask the exactly same clarification on logging. I was also using 7.1.1.Final and recently built 7.1.2.Final from sources to keep up with recent release.

I am using mostly log4j(org.apache.log4j.Logger) in legacy part of app and some jboss-logging (org.jboss.logging.Logger) in new part of app. So what I see when app is started (same setup as 7.1.1) in as 7.1.2 is the following:

- apache logger produces : 00:27:23,263 INFO  [stdout] (MSC service thread 1-4) INFO  class.....

- jboss logger produces no lines!?

Started digging around what could change (and as Maksym already stated) I came to same conclusion that it might be something on 'per-deployment' logging. So I excluded log4j jboss module with 'jboss-deployment-structure.xml' and put log4j jar  directly to ear (with some log4j.properties file in the /lib) as suggested here https://docs.jboss.org/author/display/AS71/How+To#HowTo-HowdoIuselog4j.propertiesorlog4j.xmlinsteadofusingtheloggingsubsystemconfiguration%3F . Result is that now log4j logger seem to produce loglines fine, but still no jboss-logging logger lines are produced. And contrary to Maksym I would not like to use per-deployment logging since I need a runtime change of logging categories/levels (which is not possible to achieve by using 'per-deployment' logging as far as I understand currently).

So I kindly ask to hint us what is the (supposed) proper way of using logging in as >7.1.2 or provide some link to more descriptive documentation on issue.

Thank you in advance,

A

[kristjan273]

Preliminary, after going through James's pull request on issue as-514 I see that new system property is introduced org.jboss.as.logging.per-deployment which is true by default.

I set this to false until I clarify the above and I get the behaviour as I was used to in 7.1.1.Final.

But still (James?) if someone can give some more clarification what is the supposed behaviour of the logging as already asked above?

tnx & brg,

A

[maksymg]

Aleš Bregar wrote:

Preliminary, after going through James's pull request on issue as-514 I see that new system property is introduced org.jboss.as.logging.per-deployment which is true by default.

I set this to false until I clarify the above and I get the behaviour as I was used to in 7.1.1.Final.

Indeed setting org.jboss.as.logging.per-deployment=false restores 7.1.1 logging behaviour. Thanks Ales. So I'm all set for debugging, but in production it's very important to be able to define dynamically logging category per application without redeploying it. So it would be nice to get more details on how it's all is going to work.

Thanks,

M

[jamezp]

I think I can help shed some light on this

In 7.1.1 and lower if you wanted to use a log4j or any other type of logging configuration you would have to use the jboss-deployment-structure.xml to exclude the servers logging dependencies you were using and include them into your deployment. In 7.1.2 and up we made a change for the per-deployment logging.

What is per-deployment? (This will be better documented in the next version of the documentation FWIW)

What we are doing now is looking into your deployment for 5 types of logging configuration files: log4.properties, log4j.xml, jboss-log4j.xml, jboss-logging.properties or logging.properties. If one of these configuration files is found then that deployment will get its own log context and be configured via the configuration file. This means that if you were using log4j as your logging framework before and want to use your appenders, then it will "just work". There is a note to the per-deployment logging though. When it's being used you can't use the logging subsystem configuration for that deployment.

Good find on the system property, org.jboss.as.logging.per-deployment. What that does is disables the above. If you set that property to false, the deployment scanner will not look for configuration files. This sounds like what you are looking for Maksym. You have configuration files inside your deployment, but you'd rather use the logging subsystem to configure all your logging.

This is just a rough general overview, but feel free to ask more questions if you need/want further clarification.

--

James R. Perkins

[maksymg]

James,

You answer clarifies a lot, but it's not what I expected from new "application per-deployment" feature. For us it's actually making things worse if we run JBoss 7 in domain mode compare to what we have right now with JBoss 4. Let me explain:

• Currently we are running multiple identical (the same code base) EARs that are spreaded accross a few JBoss 4 clusters. If a production problem arises, we locate right JBoss nodes and adjust log4j.xml to collect more information. The major flow now - we start seeing log messages from all EARs hosted on the cluster not the one having the problem. There is no way to filter messages by context path. But at least we do not see log messages from different JBoss clusters
• Now with JBoss 7 in domain mode (we'd like to try it), turning debug level would force all server groups to start filling log files across all nodes... regardless even if they hosts that EAR at all. That's hardly usable especially if some other EAR experiences different problem (mean you need to collect debug for different category)

Using internal log4.properties ... doesn't solve one major problem - how to adjust them on a fly?  We can't disturb production by redeploying applications.

In ideal world I would love to see ability to customize logger category per deployment or the whole logger subsystem to make logging trully configurable outside the deployment. At least have it per server group or node?

To your question why we keep log4j.properties inside, it's purely requirement of SmartGWT library, that I believe simply a bad design. So far we didn't find a way how to get read of it. We always prefer to have logging configuration to be fully outside of our code.

So my question would be, do you have any plans to implement something I described above?

Thanks a lot,

M

[jamezp]

Maksym,

The first question I have is what kind of appenders are you using in log4j?

If they're just file appenders or the console appenders then what you would need to do is convert those configurations to the XML configuration in your domain.xml. That will allow you to change log levels on the fly with no problems and is configured based on the profile. You would also need to set the system property org.jboss.as.logging.per-deployment to false since SmartGWT requires a log4j.properties file.

The only time anything would need to be redeployed or restarted is if you decide you have to use a log4j configuration file on your deployments. This is because it needs to go through the deployment process in order for the configuration to be found and reloaded.

When using the logging subsystem everything happens at runtime, so it is my prefered approach.

Feel free to paste or attach your log4j.properties file if you have questions too. I can have a look and see if it can be converted easily to use the logging subsystem.

--

James R. Perkins

[maksymg]

James,

In my case your suggestion won't work for multiple reasons:

• SmartGWT initializes the whole logging subsystem fully programatically ignoring everything that might be defined by a web container. It uses a fixed named log4j.isc.config.xml. If you remove it it simply fails to start. I guess they originally expected it to run on web container that has no own logging subsystem. The only way to fix it it is to rewrite their code (confirmed by SmartGWT). To overcome it and dynamically debugging their internal output in production, I left just ConsoleAppender inside log4j.isc.config.xml and then control output in jboss log4j.xml with STDOUT category. It's curcumbent but it works.

My first question is do you picked up log4j.isc.config.xml when jboss per-deployment is on? I hope not since it has a not standard name you mentioned. The rest of our code just use commons-logging & sl4j in standard way, so it's controled seemlessly by jboss logging.

log4j.isc.config.xml content is:

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

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

...

</log4j:configuration">

• Each my Java project has log4j.properties defined in test resources, so they are copied when we deploy unpack war using MyEclipse. There is no way to disable it, so I simple turn off jboss per-deployment in my development enviroment. That's minor inconvience and doesn't not affect production.
•   Currently in Jboss 4 logging beside FileAppender, we use SMTPAppender to send email for some errors we are interested at the particular moment.

My second question is what is the best way to add SMTPAppender alike appender to JBoss logging? The only what I found on forums is defining a custom logging inside application. It won't work for us, because we want to define category on a fly without redeploying applications. Do you have plans to build such?

Last question: you didn't answer the question I asked earlier - are there any plans to support customized context per deployment inside domain.xml? For example under domain/deployments/deployment=X/subsystem=jboss:domain:logging

Thanks a lot,

M

[jamezp]

Maksym,

My first question is do you picked up log4j.isc.config.xml when jboss per-deployment is on?

No the per-deployment scanning will not pick up the log4j.isc.config.xml. So you're safe there.

My second question is what is the best way to add SMTPAppender alike appender to JBoss logging?

The only is to use a custom handler. This custom handler could be set as a module and woudn't require any kind of restart or redployment. All handlers or loggers configured via the logging subsystem can be changed at runtime. The only part that requires a reload is if you change the file, though we're hoping to get rid of that requirement. Here is the link to a nice article about it https://community.jboss.org/wiki/CreatingACustomLoggingHandlerInJBOSSAs710Final. You can definitely create loggers on the fly and attach a handler. Maybe just define the handler and only assign it to the loggers you want it to handle.

Last question: you didn't answer the question I asked earlier - are there any plans to support customized context per deployment inside domain.xml?

Sorry about that :-) There are not real plans to have a custom context for every deployment, but we are working of a concept of logging profiles. You would just need to add an entry to your MANIFEST.MF for the profile and then you can just configure that profiles configuration.

--

James R. Perkins

[maksymg]

James,

Thanks a lot!!!

Maksym

[narve2]

Hi,

I'm unable to get per-deployment logging to work properly in JBoss7.1.2 and it seems that you are the man to ask, mr Perkins

This makes me feel rather stupid, because our needs are very simple: We just want to specify a priority and a format for our application-specific logging, and an extra file appender  (in the standard log-directory) with debug logging. Our application is deployed as an EAR and have lots of legacy code that uses JUL.

I've tried varous combinations of including/excluding the org.apache.log4j-module, bundling/not bundling log4j.jar, etc. I don't mind bundling log4j.jar/jul-to-slf4j-1.6.4.jar/whatever. I can also deploy an extra logging-dummy-ear/jar/whatever - anything goes. What I don't want is to have to modify dozens of separate standalone.xml-files on different JBoss installations, and try to keep them up to date.

I can get the effect I want (a separate file with debug info and a suitable format for console and server.log) by modifying the logging subsystem in standalone.xml. However I am unable to get the same effect by bundling the configuration file in the ear.

If I do this in standalone.xml (this is a slightly simplified version) I get what I want:

            <periodic-rotating-file-handler name="MYFILE">
                <level name="TRACE"/>
                <formatter>
                    <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-7p %-17.17c{2} %-20.20C{1}  %X{handle} %X{from} %s%E%n"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="myfile.log"/>
                <suffix value=".yyyy-MM-dd"/>
                <append value="true"/>
            </periodic-rotating-file-handler>
            <logger category="Insights">
                <level name="TRACE"/>
                <handlers>
                    <handler name="MYFILE"/>
                </handlers>
            </logger>

But I just can't get this to work using a bundled log4j.xml. The best I can achieve is that the myfile.log is created - but my output never goes there, it stays at 0 bytes. Here is the sample log4j.xml

<?xml version="1.0" ?>
<!DOCTYPE log4j:configuration SYSTEM "http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/xml/doc-files/log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" >
    <appender name="MYFILE" class="org.apache.log4j.RollingFileAppender">
        <param name="file" value="C:\\Dev\\jboss\\jboss-as\\build\\target\\jboss-as-7.1.2.Final\\standalone\\log\\myfile.log"/>
        <param name="MaxFileSize" value="100KB"/>
        <param name="MaxBackupIndex" value="10"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%r,%c{1},%t] %m%n"/>
        </layout>
    </appender>
    <category name="Insights">
        <priority value="TRACE"/>
        <appender-ref ref="MYFILE"/>
    </category>
</log4j:configuration>

The logging code is typically Logger.getLogger( "Insights.Activity").info/fine( xxx )  (from code inside jars inside lib-dir in ear-file).

Can you please advice what the "correct" way to achieve this is? Would it help to convert all logging to use slf4j? (This is planned for a future release, but if needed we can do it earlier).

[jamezp]

Do you not want to add the configuration to the logging subsystem so you don't have to manage it on several servers? If that's the case you could just write a script to modify them.

logging-configuration.cli

# Batch the commands
batch

# Add the handler
/subsystem=logging/periodic-rotating-file-handler=MYFILE:add(level=TRACE, formatter="%d{HH:mm:ss,SSS} %-7p %-17.17c{2} %-20.20C{1}  %X{handle} %X{from} %s%E%n", suffix=".yyyy-MM-dd", append=true, file={"relative-to"=>"jboss.server.log.dir","path"=>"myfile.log"})

# Add the logger
/subsystem=logging/logger=Insights:add(level=TRACE, handlers=["MYFILE"])

# Run the batch
run-batch

Then assuming you called the file logging-configuration.cli you would run it like so:

%JBOSS_HOME%\bin\standalone.bat --connect --file=C:\path\to\file\logging-configuration.cli

(Assuming you're using Windows too from the path in the log4j configuration)

The main advantage of doing this is you could manage the logging configuration via CLI, CLI GUI or the web console.

Note: The following assumes you downloaded and built 7.1.2 from source.

If you would rather package your configuration like you're trying to do it should work. Are you using log4j in your application? I noticed in you wrote "Logger.getLogger( "Insights.Activity").info/fine( xxx )". The "fine" makes me think you're using J.U.L. If that's the case then a log4j configuration wouldn't work. You could however use a logging.properties file configuration and that should work. It should look something like the following

loggers=Insight

logger.Insight.level=TRACE
logger.Insight.handlers=MYFILE 

handlers=MYFILE 

handler.MYFILE=org.jboss.logmanager.handlers.PeriodicRotatingFileHandler
handler.MYFILE.formatter=PATTERN
handler.MYFILE.properties=autoFlush,append,fileName,suffix
handler.MYFILE.constructorProperties=fileName,append
handler.MYFILE.autoFlush=true
handler.MYFILE.append=true
handler.MYFILE.fileName=C:\\Dev\\jboss\\jboss-as\\build\\target\\jboss-as-7.1.2.Final\\standalone\\log\\myfile.log
handler.MYFILE.suffix=.yyyy-MM-dd 

formatter.PATTERN=org.jboss.logmanager.formatters.PatternFormatter
formatter.PATTERN.properties=pattern
formatter.PATTERN.constructorProperties=pattern
formatter.PATTERN.pattern=%d{HH:mm:ss,SSS} %-7p %-17.17c{2} %-20.20C{1}  %X{handle} %X{from} %s%E%n

Hope this helps.

--

James R. Perkins

[narve2]

Hi, thanks for an extensive reply! A few comments below:

Then assuming you called the file logging-configuration.cli you would run it like so:

%JBOSS_HOME%\bin\standalone.bat --connect --file=C:\path\to\file\logging-configuration.cli

(Assuming you're using Windows too from the path in the log4j configuration)

This didn't work --connect is not one of the commands that standalone.bat recognizes. Perhaps you meant one of the other batch-files? Unfortunately, none of them seems to recognize --connect as a valid command. I also tried the jconsole.bat, which seems to be unable to load any of the jboss jars and thus fails at connecting to anything. I can only assume that most developers use linux and that the batch-files haven't been tested properly. I'll try the linux variants, and if I get them to work that should suffice - I can run the command from one of the (Linux) servers instead of my local (Windows) computer. I can also try to find out what the problem with the batch files are - if I manage to fix those I'll send you a note/patch/pull request.

Note: The following assumes you downloaded and built 7.1.2 from source.

If you would rather package your configuration like you're trying to do it should work. Are you using log4j in your application? I noticed in you wrote "Logger.getLogger( "Insights.Activity").info/fine( xxx )". The "fine" makes me think you're using J.U.L. If that's the case then a log4j configuration wouldn't work. You could however use a logging.properties file configuration and that should work. It should look something like the following

Yes, I've built 7.1.2 from source. Of course, "Logger.getLogger(...)" was ambigous but you were right in assuming that I referred to JUL. Since JBoss redirects JUL logging I thought I could use log4j.xml to configure my logging based on that. I will try the logging.properties approach, but I think we will just convert our logging to use SLF4J sooner rather than later.

Assuming that all code has been converted to SLF4J, will JBoss pick up a log4j.xml file and configure my logging then? Or is there another way to specify, in the deployment artifact itself, extra logging configuration somehow? Or will I have to wait for the "logging profiles" you mentioned above?

[jamezp]

Oops that was a typo it shouldn't be standalone.bat it should be jboss-cli.bat.

Even using slf4j will not work with a log4j configuration. I suppose in theory with logback it would, but I've not tested it at all. The log records need to be processed through a log manager, which means the loggers need to be created on that log manager. You're better off either using JBoss Logging or slf4j and using the logging.properties configuration file. It would likely be faster than using log4j anyway.

--

James R. Perkins

[narve2]

OK, I will try that approach. Thanks for helping out!