6

I have a web-application which I want to log for. There is some default logging provided by a logging.properties file, which I am unable to influence. It logs the server startup, shutdown, etc.

These are examples of such logs (normal ones, nothing wrong here):

2016/01/22 12:25:10  INFO (ApplicationContext.java:671 [ServerService Thread Pool -- 64]) - Initializing Spring root WebApplicationContext
2016/01/22 12:25:13  INFO (ConfigureListener.java:202 [ServerService Thread Pool -- 64]) - Initializing Mojarra 2.1.28-jbossorg-6  for context '/MyServices'
2016/01/22 12:25:15  INFO (DeploymentHandlerUtil.java:137 [ServerService Thread Pool -- 28]) - JBAS015859: Deployed "MyServices.war" (runtime-name : "MyServices.war")
2016/01/22 12:25:15  INFO (BootstrapListener.java:93 [Controller Boot Thread]) - JBAS015874: JBoss EAP 6.4.0.GA (AS 7.5.0.Final-redhat-21) started in 27257ms - Started 485 of 520 services (63 services are lazy, passive or on-demand)

Now I also have logging in my application for my own methods, specified using:

private static final org.slf4j.Logger LOG = org.slf4j.LoggerFactory.getLogger(PropertiesValues.class);
...
LOG.info("Properties loaded.");

The problem is that when these logs are hit, the causes double logging, where each line has two timestamps, two log levels, and two sources, such as:

2016/01/22 11:50:49  INFO (AbstractLoggingWriter.java:71 [ServerService Thread Pool -- 111]) - 2016/01/22 11:50:49  INFO (EnvironmentLoader.java:128 [ServerService Thread Pool -- 111]) - Starting Shiro environment initialization.
2016/01/22 11:50:49  INFO (AbstractLoggingWriter.java:71 [ServerService Thread Pool -- 111]) - 2016/01/22 11:50:49  INFO (EnvironmentLoader.java:141 [ServerService Thread Pool -- 111]) - Shiro environment initialized in 125 ms.
...
2016/01/22 11:51:20  INFO (AbstractLoggingWriter.java:71 [http-localhost/127.0.0.1:8443-6]) - 2016/01/22 11:51:20  INFO (PropertiesValues.java:101 [http-localhost/127.0.0.1:8443-6]) - Properties loaded.

Note the logs are being processed twice. That is - Each line that would be printed is run through the logger again, resulting in two timestamps, two log levels, and two sources. I can get around this by changing the last line in my log4j.properties file:

log4j.rootLogger=INFO, STDOUT
log4j.additivity.rootLogger=false
log4j.appender.STDOUT=org.apache.log4j.ConsoleAppender
log4j.appender.STDOUT.Target=System.out
log4j.appender.STDOUT.layout=org.apache.log4j.PatternLayout
log4j.appender.STDOUT.layout.ConversionPattern=%d{yyyy/MM/dd HH:mm:ss} %5p (%F:%L [%t]) - %m%n

To only be %m but I feel that this is a poor solution, and results in the source being shown as AbstractLoggingWriter.java:71 for everything.

Is there a way to make it so that my logs show the correct method and line number, and are formatted how I choose, rather than the server? At the same time, I also don't want to lose the logging provided by the server.

My Maven dependencies are:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.7.5</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.5</version>
</dependency>
<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>
Addison
  • 7,322
  • 2
  • 39
  • 55
  • 4
    I cannot see your so-called "double logging" in your example. Can you be more specific on your problem? – Adrian Shum Jan 25 '16 at 07:14
  • Just an advise: try not log method, classname, line number etc. The way these information is retrieved is extremely slow and they rarely give useful information for your diagnosis. – Adrian Shum Jan 25 '16 at 07:17
  • I don't see any double logging, as Adrian Shum stated. – Tunaki Jan 25 '16 at 10:17
  • 1
    Sorry for poorly describing the logging problem. A better way of phrasing it might be that all of the log outputs are logged by a second logger. If you check the example, you'll see that each line has 2 timestamps, 2 error levels (e.g: INFO), and 2 lines where the error came from. – Addison Jan 27 '16 at 09:54
  • 2
    @AdrianShum No reason to downvote this, have a look at the messages properly... – František Hartman Jan 29 '16 at 12:38
  • 1
    1. All messages are different. I don't see what you mean by 2 lines. 2. I don't even see any "error" – Adrian Shum Jan 29 '16 at 12:53
  • @frant.hartm We're all looking properly at the messages. They're all different. Could you point to duplicated lines? – Tunaki Jan 30 '16 at 16:16
  • 2
    @Tunaki That's the point - there are no duplicated lines! OP never said there are. The duplication is in the message, which has following pattern: "timestamp level class thread - timestamp level class thread - message" and OP asks where the duplicated "timestamp level class .." come from – František Hartman Jan 30 '16 at 16:31
  • @frant.hartm That is your interpretation of the question, which is different. It is really unclear what the OP is asking. – Tunaki Jan 30 '16 at 16:34

3 Answers3

5

We had the same problem with our application, we fixed that by adding the following in jboss-deployment-structure.xml to WEB-INF in the web application:

<?xml version="1.0" encoding="utf-8"?>
<jboss-deployment-structure>
   <deployment>
       <!-- Exclusions allow you to prevent the server from automatically adding some dependencies -->
       <exclude-subsystems>  
           <subsystem name="logging" />
       </exclude-subsystems>  
   </deployment>
</jboss-deployment-structure>
SunSear
  • 230
  • 4
  • 9
  • 1
    This didn't work perfectly, but got me a lot closer to an answer. The logging to STDOUT is apparently unfixable, but with this I could ensure that the second parse of the logger was disabled, (meaning no logging to STDOUT), but it logged properly to a file, which is the most important thing. – Addison Jan 31 '16 at 22:50
1

It's hard to say exactly what's happening, but I'll try to guess. I see you use JBoss, it uses commons-logging to log events. You set log4j to output to stdout. Possibly Logger from JBoss grabs what's being sent to stdout and logs it, so you have a message decorated twice.

Try to use org.jboss.logging.Logger from JBoss instead of slf4j Or as a dirty trick you may try to switch off log4j output by adding log4j.appender.STDOUT.Threshold=off to log4j.properties

Dmitry P.
  • 824
  • 5
  • 14
  • The first one disabled logging. The second one did nothing, but may have been meant to be `log4j.appender.STDOUT.Threshold=off`, which resulted in no logging. Thanks for trying though - But I strongly suspect the problem is with some sort of second logger (maybe whatever `AbstractLoggingWriter` is) taking the input from log4j and re-logging it. – Addison Jan 27 '16 at 10:07
  • @Addison Yep, I meant STDOUT. Looks like JBoss logging is not configured to log to console and when you log something it writes info to log file. In this case I think the most reliable way is to edit logging.properties used by JBoss and use `org.jboss.logging.Logger` as described [here](https://access.redhat.com/documentation/en-US/JBoss_Enterprise_Application_Platform/6/html/Development_Guide/Add_Logging_to_an_Application_with_JBoss_Logging.html) – Dmitry P. Jan 27 '16 at 10:32
0

My understanding of what is occurring here is as follows :

There are two implementations of log4j that are interleaving although they were not intended to.

One approach performs a decoration in a super class and logs messages in the current class. Another performs both decoration and logging in given class but still calls super class ( for some reason).

Now due to a mix-up in class-loading, the super-class is from one implementation of log4j (which handles the decoration) and there is also another class which is now again (either newer or older version) handling the decoration as well as message logging.

This as per my understanding explains why the decoration is duplicated but there is no corruption of the message as a whole.

Try starting up jboss with 

-verbose:class
jvm option and pipe the output to a file. This will help identify from which jars the classes are being loaded.

You can then decide if that is how you wanted things to be.

Ravindra HV
  • 2,558
  • 1
  • 17
  • 26