SNOW-142981: Debug logs can't be turned off

[pr3mar]

Hi,

I have been trying to bump the version to 3.11.0+ (up to the latest 3.12.1)
and I am getting some strange logs from net.snowflake.client.jdbc.internal.io.netty.*:

15:41:30.048 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
15:41:30.052 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.ResourceLeakDetector - -Dnet.snowflake.client.jdbc.internal.io.netty.leakDetection.level: simple
15:41:30.052 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.ResourceLeakDetector - -Dnet.snowflake.client.jdbc.internal.io.netty.leakDetection.targetRecords: 4
15:41:30.074 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
15:41:30.077 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - Java version: 8
15:41:30.083 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
15:41:30.084 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
15:41:30.085 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
15:41:30.085 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - direct buffer constructor: available
15:41:30.086 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
15:41:30.086 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
15:41:30.086 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
15:41:30.086 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
15:41:30.087 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)
15:41:30.087 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
15:41:30.089 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
15:41:30.090 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 954728448 bytes
15:41:30.090 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 8
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 8
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
15:41:30.091 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
15:41:30.092 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
15:41:30.092 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
15:41:30.092 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
15:41:30.092 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
15:41:30.099 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
15:41:30.099 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
15:41:30.122 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.buffer.AbstractByteBuf - -Dnet.snowflake.client.jdbc.internal.io.netty.buffer.bytebuf.checkAccessible: true
15:41:30.124 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: net.snowflake.client.jdbc.internal.io.netty.util.ResourceLeakDetector@49293b43
15:41:31.342 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
15:41:31.342 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
15:41:31.342 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
15:41:31.342 [main] DEBUG net.snowflake.client.jdbc.internal.io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8

I am using my own log4j.properties file and I can successfully control the output of all other dependencies, apart from net.snowflake.client.jdbc.internal.io.netty.*. There is something on the output just at the program initialization, and nothing afterwards.

I am using scala, with the following logger dependency:

    "com.typesafe.scala-logging"  %% "scala-logging-slf4j"   % "2.1.2"

I tried all possible combinations to disable the log level or increase the threshold, including the official documentation but with no luck whatsoever.

[pr3mar]

bump
ping @ankitbhatnagarsf, @snowstakeda, please help

[sfc-gh-stakeda]

Added to the backlog.

[pr3mar]

@snowstakeda this is a real pain for us, could you please bump the priority of this ticket?

[sfc-gh-stakeda]

forwarded to dev manager and pm.

[pr3mar]

ping @sfc-gh-stakeda, any progress on this one? It's really a pain

[sfc-gh-stakeda]

@pr3mar I'm afraid this is the best place to increase the priority higher. I've already forwarded your feedback to the team. We are dealing with issues in the queue. If you need further assistance, please file a support ticket for escalation. Thanks.

[pr3mar]

ping @sfc-gh-stakeda anything?

[pr3mar]

I unassigned @mknister by mistake, sorry

[sfc-gh-mknister]

Hi @pr3mar , is this still an issue with the latest driver version?

[jatcwang]

Hi @sfc-gh-mknister, this is still an issue for us too.

We're using slf4j (logback) and I have tried to force -Dnet.snowflake.jdbc.loggerImpl=net.snowflake.client.log.SLF4JLogger, but I suspect the issue is coming from the shaded netty dependency in jdbc-snowflake. (net.snowflake.client.jdbc.internal.io.netty.util)

[bogdanpetrovic0]

@sfc-gh-mknister Any progress/update on this? Looks like it is still a problem.

[sfc-gh-wfateem]

Hi @pr3mar @bogdanpetrovic0 @jatcwang,

Can either one of you share the exact log4j settings you have set? I don't see this issue and we haven't seen anyone else complain about this problem either.

Here's an example of what I have in my log4j.properties file:

log4j.appender.FILE=org.apache.log4j.FileAppender
log4j.appender.FILE.file=./snowflake_jdbc.log
log4j.appender.FILE.ImmediateFlush=true
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d{yy/MM/dd HH:mm:ss} %t %p %c{1}: %m%n

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.target=System.err
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{yy/MM/dd HH:mm:ss} %t %p %c{1}: %m%n

log4j.logger.net.snowflake.client=INFO,FILE

With those settings, I don't see any logging messages produced by the JDBC driver except for a single log message. The only time I would see the output you're complaining about is if I change log4j.logger.net.snowflake.client to DEBUG. I tested this with version 3.13.12.

[sfc-gh-wfateem]

Just following up on this again @jatcwang @pr3mar @bogdanpetrovic0
Can one of you give me additional details on how you're configuring log4j for your application?
Just in case this wasn't clear in my last comment, here's an example of how you would enable debugging for the JDBC driver but turn off the shaded netty library's logging:

log4j.appender.FILE=org.apache.log4j.FileAppender
log4j.appender.FILE.file=./snowflake_jdbc.log
log4j.appender.FILE.ImmediateFlush=true
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d{yy/MM/dd HH:mm:ss} %t %p %c{1}: %m%n

log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.target=System.err
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{yy/MM/dd HH:mm:ss} %t %p %c{1}: %m%n

log4j.logger.net.snowflake.client=DEBUG,FILE
log4j.logger.net.snowflake.client.jdbc.internal.io.netty=INFO,FILE

If you want to turn off logging for all classes under net.snowflake.client (which would include netty) then you can simply use:

log4j.logger.net.snowflake.client=INFO,FILE

Hope this helps.

[pr3mar]

hi @sfc-gh-wfateem, this issue is 2 years old, and I can no longer verify the suggested solution.
I hope you can look into the issues in a more timely manner in the future :)

[sfc-gh-wfateem]

Hi @pr3mar,

Yeah, sorry about that. This definitely fell off the radar and was only revived by a recent comment by @bogdanpetrovic0. But as they say, "better late than never," right? :)

I'm pretty confident the issue here is related to log4j settings and is not a JDBC driver issue. I confirmed that I was able to turn on the shaded netty library's logging and back off. If anyone else has this issue, please refer to my previous comment.

I'm going to close this off for now.

[jLabadan3Q]

Same issue here. How can I turn off the SFSession:

Feb 11, 2025 4:26:52 AM net.snowflake.client.core.SFSession open
INFO: Opening session with server: https://ma71176xxxxxxxxx