Why is the log4j configuration not fully applied?

[Stefan Hanke]

Hi everyone,

In my project the log4j configuration seems to be applied only half, what I'm doing wrong?

I've add log4j (v.1.2.17) to my vert.x application (v.3.2.0) using gradle wrapper

build.gradle:

...
dependencies {
    compile "io.vertx:vertx-core:3.2.0"
    compile "io.vertx:vertx-web:3.2.0"
    compile "log4j:log4j:1.2.17"
}
...

I've added a simple log4j.properties file to src/main/resources:

log4j.appender.Stdout=org.apache.log4j.ConsoleAppender
log4j.appender.Stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.Stdout.layout.conversionPattern=%d %-5p [%x] [%c] %m%n
log4j.rootLogger=DEBUG,Stdout

I build my application with:

./gradlew clean shadowJar

The jar file contains the log4j.properties file in the root path.

Now I start my application with:

java -jar build/libs/vert.x-angular-jwt-3.2.0-fat.jar -Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory

The result is:

2016-01-08 17:29:34,677 DEBUG [] [io.netty.util.internal.logging.InternalLoggerFactory] Using Log4J as the default logging framework
2016-01-08 17:29:34,682 DEBUG [] [io.netty.util.ResourceLeakDetector] -Dio.netty.leakDetection.level: simple
2016-01-08 17:29:34,682 DEBUG [] [io.netty.util.ResourceLeakDetector] -Dio.netty.leakDetection.maxRecords: 4
2016-01-08 17:29:34,695 DEBUG [] [io.netty.channel.MultithreadEventLoopGroup] -Dio.netty.eventLoopThreads: 8
2016-01-08 17:29:34,704 DEBUG [] [io.netty.util.internal.PlatformDependent0] java.nio.Buffer.address: available
2016-01-08 17:29:34,704 DEBUG [] [io.netty.util.internal.PlatformDependent0] sun.misc.Unsafe.theUnsafe: available
2016-01-08 17:29:34,704 DEBUG [] [io.netty.util.internal.PlatformDependent0] sun.misc.Unsafe.copyMemory: available
2016-01-08 17:29:34,705 DEBUG [] [io.netty.util.internal.PlatformDependent0] java.nio.Bits.unaligned: true
2016-01-08 17:29:34,705 DEBUG [] [io.netty.util.internal.PlatformDependent] Java version: 8
2016-01-08 17:29:34,705 DEBUG [] [io.netty.util.internal.PlatformDependent] -Dio.netty.noUnsafe: false
2016-01-08 17:29:34,705 DEBUG [] [io.netty.util.internal.PlatformDependent] sun.misc.Unsafe: available
2016-01-08 17:29:34,705 DEBUG [] [io.netty.util.internal.PlatformDependent] -Dio.netty.noJavassist: false
2016-01-08 17:29:34,706 DEBUG [] [io.netty.util.internal.PlatformDependent] Javassist: unavailable
2016-01-08 17:29:34,706 DEBUG [] [io.netty.util.internal.PlatformDependent] You don't have Javassist in your class path or you don't have enough permission to load dynamically generated classes.  Please check the configuration for better performance.
2016-01-08 17:29:34,706 DEBUG [] [io.netty.util.internal.PlatformDependent] -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
2016-01-08 17:29:34,706 DEBUG [] [io.netty.util.internal.PlatformDependent] -Dio.netty.bitMode: 64 (sun.arch.data.model)
2016-01-08 17:29:34,706 DEBUG [] [io.netty.util.internal.PlatformDependent] -Dio.netty.noPreferDirect: false
2016-01-08 17:29:34,736 DEBUG [] [io.netty.channel.nio.NioEventLoop] -Dio.netty.noKeySetOptimization: false
2016-01-08 17:29:34,736 DEBUG [] [io.netty.channel.nio.NioEventLoop] -Dio.netty.selectorAutoRebuildThreshold: 512
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.numHeapArenas: 8
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.numDirectArenas: 8
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.pageSize: 8192
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.maxOrder: 11
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.chunkSize: 16777216
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.tinyCacheSize: 512
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.smallCacheSize: 256
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.normalCacheSize: 64
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2016-01-08 17:29:34,811 DEBUG [] [io.netty.buffer.PooledByteBufAllocator] -Dio.netty.allocator.cacheTrimInterval: 8192
2016-01-08 17:29:34,831 DEBUG [] [io.netty.util.internal.ThreadLocalRandom] -Dio.netty.initialSeedUniquifier: 0x88168f0db51ef773 (took 0 ms)
2016-01-08 17:29:34,863 DEBUG [] [io.netty.buffer.ByteBufUtil] -Dio.netty.allocator.type: unpooled
2016-01-08 17:29:34,863 DEBUG [] [io.netty.buffer.ByteBufUtil] -Dio.netty.threadLocalDirectBufferSize: 65536
2016-01-08 17:29:34,863 DEBUG [] [io.netty.buffer.ByteBufUtil] -Dio.netty.maxThreadLocalCharBufferSize: 16384
2016-01-08 17:29:34,865 DEBUG [] [io.netty.util.NetUtil] Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo)
2016-01-08 17:29:34,866 DEBUG [] [io.netty.util.NetUtil] /proc/sys/net/core/somaxconn: 128
Jan 08, 2016 5:29:34 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer
INFORMATION: Succeeded in deploying verticle

As you can see netty detects the log4j configuration and uses it (first logline). The DEBUG level and the PatternLayout is also correct.
However the classes from io.vertx still uses the JUL with its ugly pattern layout (last logline)

When I use log4j directly in my verticle it is working fine, only the LoggerFactory of vert.x isn't aware of log4j. What I'm doing wrong?

Thank you,
Stefan Hanke

[Nat]

You need to set a system property: http://vertx.io/docs/apidocs/io/vertx/core/logging/Logger.html

[Alexander Lehmann]

I think you have to put the -D before that -jar option, otherwise its not ending up as the correct property type.

[Stefan Hanke]

Thanks Alexander, your right the order is important.

The following comand works fine:

java -Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory -jar build/libs/vert.x-angular-jwt-3.2.0-fat.jar

However, it is still broken if I use the --redeploy argument:

java
 -Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory
 -jar build/libs/vert.x-angular-jwt-3.2.0-fat.jar

 --redeploy="src/**/*.java" 
 --on-redeploy='./gradlew shadowJar'

Redeployment itself works fine but again JUL is used! I assume that the log4j system property is not forwarded to the redeploy process.

Any idea how to get vertx running with redeploy option and log4j?

[Alexander Lehmann]

I had problems getting the redeploy option working at all due to some problem with the classpath, this affects logger delegate config as well.

For now, I am using a project called vertx-hot that does redeploy at bit different, which works with log4j as long as I include the log4j jar in the project IIRC.

https://github.com/dazraf/vertx-hot

[Clement Escoffier]

Hi,

Could you provide a reproducer for the redeploy issue, or describe it in more details. It should not change how the class path is computed.

BTW, in redeploy mode, you need to pass JVM options using -Djava-opts=“-Dvertx-logger-delegate-factory-class-name=…"

Clement

-- 
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/e5af9859-34f8-428c-995d-2dad244b56d2%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Stefan Hanke]

Again many thanks for your replies.

I managed it in a very simple way, just extend the standard vertx launcher:

public class Log4JLauncher extends Launcher {
   
    public static void main(String[] args) {
        System.setProperty("vertx.logger-delegate-factory-class-name", "io.vertx.core.logging.Log4jLogDelegateFactory");
        new Log4JLauncher().dispatch(args);
    }

}

Change the MainClassName of your application from 'io.vertx.core.Launcher' to your customized launcher and you're done.
Now everytime Log4J is used without the need to pass System properties via comandline / maven / gradle or what ever you're using.

[Alexander Lehmann]

Hi Clement,

I looked at a few messages from the group (including one with your explanation video for eclipse) and I figured out what I was missing.

I am currently using a maven project with the fatjar option to run the redeploy command and then use the same project in Eclipse to change the files, with the following script

call mvn package -DskipTests=true
java -cp "target/classes;target/vertx-redeploy-logging-0.0.1-SNAPSHOT-fat.jar" io.vertx.core.Launcher run cx.lehmann.vertx.LoggingTest --redeploy="target\classes\**\*.class" --launcher-class=io.vertx.core.Launcher --java-opts="-Dvertx.logger-delegate-factory-class-name=io.vertx.core.logging.Log4jLogDelegateFactory"

This way the redeploy works with log4j.

[Clement Escoffier]

Hi, 

Something I need to highlight on the documentation is why you need jvmOpts in redeploy mode. This is because, the redeploy spawns a new process running the application and terminates-relaunches it upon changes (this avoid leaks). So, JVM arguments must be passed using jvmOpts.

That said, it would be useful to “copy” the -D options passed to the Launcher. However I can only retrieve the ones passed to Launcher:

java -Dfoo=bar io.vertx.core.Launcher -> cannot get it (it’s not an “option”)

java io.vertx.core.Launcher -Dfoo=bar -> can retrieve it and pass it to the spawn process

Clement

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/5f5de05d-9535-44cd-884c-95def5f9978b%40googlegroups.com.