I'm trying to integrate a Log4J2 Appender to RabbitMQ in an already working and logging java application.
The application is build as a gradle project. Before the integration of spring-rabbit, the build.gradle file looked like this:
group 'Name'
version '1.18.7'
apply plugin: 'java'
apply plugin: 'com.github.johnrengelman.shadow'
sourceCompatibility = 1.8
repositories {
mavenCentral()
}
dependencies {
[...]
compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.10.0'
compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.10.0'
compile group: 'com.lmax', name: 'disruptor', version: '3.3.7'
[...]
}
jar {
manifest {
attributes 'Main-Class': 'the.main.Clazz'
}
}
buildscript {
repositories {
maven {
url "https://plugins.gradle.org/m2/"
}
}
dependencies {
classpath group: 'com.github.jengelman.gradle.plugins', name: 'shadow', version: '2.0.2'
}
}
The log4j2.xml file, positioned in the src/resources folder, contains this (before rabbitMQ):
<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorInterval="15">
<Appenders>
<Console name="STDOUT">
<PatternLayout>
<Pattern>%d [%highlight{%-6p}{STYLE=DEFAULT, noConsoleNoAnsi=true}] %C{1}.%M(%F:%L) - %m%n%throwable</Pattern>
</PatternLayout>
</Console>
<RandomAccessFile name="ASYNC_FILE" fileName="logs/app.log" immediateFlush="false" append="true">
<PatternLayout>
<Pattern>%d [%-6p] %C{1}.%M(%F:%L) - %m%n%throwable</Pattern>
</PatternLayout>
</RandomAccessFile>
</Appenders>
<Loggers>
<Root level="info">
<AppenderRef ref="STDOUT"/>
</Root>
<Logger name="my.package" level="info" additivity="false">
<AppenderRef ref="ASYNC_FILE"/>
</Logger>
</Loggers>
</Configuration>
The application runs nicely, as well as from the IDE and the JAR, built with the shadowJar plugin.
Now, the mystery begins. Simply by adding the spring-rabbit dependency...
compile group: 'org.springframework.amqp', name: 'spring-rabbit', version: '2.0.2.RELEASE'
...logging starts to behave very strange. Started from the IDE, everything works still nice. Adding the following appender to the log4j2.xml works fine:
<RabbitMQ name="RABBIT_MQ"
host="my.host.name" port="5672" user="logger" password="logger" virtualHost="loggerhost"
exchange="logs" exchangeType="fanout" declareExchange="false"
applicationId="app-xyz" routingKeyPattern="%X{applicationId}.%c.%p"
contentType="text/plain" contentEncoding="UTF-8" generateId="true" deliveryMode="NON_PERSISTENT"
charset="UTF-8"
senderPoolSize="3" maxSenderRetries="5">
<PatternLayout>
<Pattern>%d [%-6p] %C{1}.%M(%F:%L) - %m%n%throwable</Pattern>
</PatternLayout>
</RabbitMQ>
I see the log messages delivered via the RabbitMQ server.
But when I build and run the JAR file built with :shadowJar, logging stops working. On STDOUT, I see the following:
ERROR StatusLogger Unrecognized format specifier [d]
ERROR StatusLogger Unrecognized conversion specifier [d] starting at position 16 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [thread]
ERROR StatusLogger Unrecognized conversion specifier [thread] starting at position 25 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [level]
ERROR StatusLogger Unrecognized conversion specifier [level] starting at position 35 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [logger]
ERROR StatusLogger Unrecognized conversion specifier [logger] starting at position 47 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [msg]
ERROR StatusLogger Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [n]
ERROR StatusLogger Unrecognized conversion specifier [n] starting at position 56 in conversion pattern.
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console. Set system property 'log4j2.debug' to show Log4j2 internal initialization logging.
ERROR StatusLogger Unrecognized format specifier [d]
ERROR StatusLogger Unrecognized conversion specifier [d] starting at position 16 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [thread]
ERROR StatusLogger Unrecognized conversion specifier [thread] starting at position 25 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [level]
ERROR StatusLogger Unrecognized conversion specifier [level] starting at position 35 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [logger]
ERROR StatusLogger Unrecognized conversion specifier [logger] starting at position 47 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [msg]
ERROR StatusLogger Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
ERROR StatusLogger Unrecognized format specifier [n]
ERROR StatusLogger Unrecognized conversion specifier [n] starting at position 56 in conversion pattern.
When I start the application JAR with the -Dlog4j2.debug option I see a lot of messages, and some seem to say, that the configuration cannot be loaded (which is still at the same place). Here an excerpt:
DEBUG StatusLogger Using configurationFactory org.apache.logging.log4j.core.config.ConfigurationFactory$Factory@2a33fae0
ERROR StatusLogger No log4j2 configuration file found. Using default configuration: logging only errors to the console. Set system property 'log4j2.debug' to show Log4j2 internal initialization logging.
I even used the -Dlog4j.configurationFile option, pointing directly to the XML in the file system, but the result stays the same.
Again, starting the application from the IDE and not via java -jar ... works fine. It seems to me as if the spring-rabbitmq dependency brings some extra log4j stuff that interferes with my configuration. I'm totally fishing in murky waters.
So, after a lot of research I can answer my question with the following.
It is not enough to simply add the Spring-Rabbit-MQ org.springframework.amqp:spring-rabbit dependency to let the Log4J2 configuration fail. It's the combination with another dependency, that is not listed in my example: com.fasterxml.jackson.core:jackson-databind.
To sum it up. This does not work:
compile group: 'com.fasterxml.jackson.core', name: 'jackson-databind', version: '2.9.3'
compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.10.0'
compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.10.0'
compile group: 'com.lmax', name: 'disruptor', version: '3.3.7'
compile group: 'org.springframework.amqp', name: 'spring-rabbit', version: '2.0.2.RELEASE'
But this works (without Spring):
compile group: 'com.fasterxml.jackson.core', name: 'jackson-databind', version: '2.9.3'
compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.10.0'
compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.10.0'
compile group: 'com.lmax', name: 'disruptor', version: '3.3.7'
And this works (without Jackson):
compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.10.0'
compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.10.0'
compile group: 'com.lmax', name: 'disruptor', version: '3.3.7'
compile group: 'org.springframework.amqp', name: 'spring-rabbit', version: '2.0.2.RELEASE'
So the combination of Jackson and Spring breaks Log4J2. Interestingly, without Jackson, my program works as well, even if Jackson is under heavy use. Let's have a look on that, what gradle dependecies has to say:
compile - Dependencies for source set 'main' (deprecated, use 'implementation ' instead).
+--- org.apache.logging.log4j:log4j-api:2.10.0
+--- org.apache.logging.log4j:log4j-core:2.10.0
| \--- org.apache.logging.log4j:log4j-api:2.10.0
+--- com.lmax:disruptor:3.3.7
\--- org.springframework.amqp:spring-rabbit:2.0.2.RELEASE
+--- org.springframework.amqp:spring-amqp:2.0.2.RELEASE
| \--- org.springframework:spring-core:5.0.3.RELEASE
| \--- org.springframework:spring-jcl:5.0.3.RELEASE
+--- com.rabbitmq:amqp-client:5.1.2
| \--- org.slf4j:slf4j-api:1.7.25 -> 1.8.0-alpha2
+--- com.rabbitmq:http-client:1.3.1.RELEASE
| +--- org.apache.httpcomponents:httpclient:4.5.3
| | +--- org.apache.httpcomponents:httpcore:4.4.6
| | +--- commons-logging:commons-logging:1.2
| | \--- commons-codec:commons-codec:1.9 -> 1.11
| \--- com.fasterxml.jackson.core:jackson-databind:2.9.2
| +--- com.fasterxml.jackson.core:jackson-annotations:2.9.0
| \--- com.fasterxml.jackson.core:jackson-core:2.9.2
+--- org.springframework:spring-context:5.0.3.RELEASE
| +--- org.springframework:spring-aop:5.0.3.RELEASE
| | +--- org.springframework:spring-beans:5.0.3.RELEASE
| | | \--- org.springframework:spring-core:5.0.3.RELEASE (*)
| | \--- org.springframework:spring-core:5.0.3.RELEASE (*)
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| +--- org.springframework:spring-core:5.0.3.RELEASE (*)
| \--- org.springframework:spring-expression:5.0.3.RELEASE
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-messaging:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-tx:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-web:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
\--- org.springframework.retry:spring-retry:1.2.1.RELEASE
\--- org.springframework:spring-core:4.3.9.RELEASE -> 5.0.3.RELEASE (*)
Oh, wait, there's also a Jackson within the Spring AMQP. Well, that solves the riddle, why I can still use Jackson after removing the dependency. But this is very intransparent to me and depends on the Spring AMQP package to deliver a core dependency for me. So what I finally did is this, and it seems to work:
compile group: 'com.fasterxml.jackson.core', name: 'jackson-databind', version: '2.9.3'
compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.10.0'
compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.10.0'
compile group: 'com.lmax', name: 'disruptor', version: '3.3.7' version: '2.12.0'
compile (group: 'org.springframework.amqp', name: 'spring-rabbit', version: '2.0.2.RELEASE') {
exclude group: 'com.fasterxml.jackson.core', module: 'jackson-databind'
}
The dependency tree looks like the following now:
compile - Dependencies for source set 'main' (deprecated, use 'implementation ' instead).
+--- com.fasterxml.jackson.core:jackson-databind:2.9.3
| +--- com.fasterxml.jackson.core:jackson-annotations:2.9.0
| \--- com.fasterxml.jackson.core:jackson-core:2.9.3
+--- org.apache.logging.log4j:log4j-api:2.10.0
+--- org.apache.logging.log4j:log4j-core:2.10.0
| \--- org.apache.logging.log4j:log4j-api:2.10.0
+--- com.lmax:disruptor:3.3.7
\--- org.springframework.amqp:spring-rabbit:2.0.2.RELEASE
+--- org.springframework.amqp:spring-amqp:2.0.2.RELEASE
| \--- org.springframework:spring-core:5.0.3.RELEASE
| \--- org.springframework:spring-jcl:5.0.3.RELEASE
+--- com.rabbitmq:amqp-client:5.1.2
| \--- org.slf4j:slf4j-api:1.7.25 -> 1.8.0-alpha2
+--- com.rabbitmq:http-client:1.3.1.RELEASE
| \--- org.apache.httpcomponents:httpclient:4.5.3
| +--- org.apache.httpcomponents:httpcore:4.4.6
| +--- commons-logging:commons-logging:1.2
| \--- commons-codec:commons-codec:1.9 -> 1.11
+--- org.springframework:spring-context:5.0.3.RELEASE
| +--- org.springframework:spring-aop:5.0.3.RELEASE
| | +--- org.springframework:spring-beans:5.0.3.RELEASE
| | | \--- org.springframework:spring-core:5.0.3.RELEASE (*)
| | \--- org.springframework:spring-core:5.0.3.RELEASE (*)
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| +--- org.springframework:spring-core:5.0.3.RELEASE (*)
| \--- org.springframework:spring-expression:5.0.3.RELEASE
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-messaging:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-tx:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
+--- org.springframework:spring-web:5.0.3.RELEASE
| +--- org.springframework:spring-beans:5.0.3.RELEASE (*)
| \--- org.springframework:spring-core:5.0.3.RELEASE (*)
\--- org.springframework.retry:spring-retry:1.2.1.RELEASE
\--- org.springframework:spring-core:4.3.9.RELEASE -> 5.0.3.RELEASE (*)
I must admit that I not fully understand why the combination of two Jackson dependencies brings the Log4J2 configuration down, but now it works with this strategy:
And what I really don't get: Why do all combinations work from within the IDE, but later fail when running the JAR?