Details
-
Bug
-
Resolution: Not a bug
-
Minor
-
None
-
jre 1.8
jul-to-slf4j 1.7.26 (but SLF4JBridgeHandler hasn't changed much as of 1.7.33)
logback-classic 1.2.3 (but JULHelper hasn't changed much as of 1.8.0)
Log messages are sent using java.util.logging.
SLF4JBridgeHandler and LevelChangePropagator are enabled (I was running PlayFramework which does this automatically)
logback.xml contains <logger name="com.sun.mail.util" level="DEBUG"/>
jre 1.8 jul-to-slf4j 1.7.26 (but SLF4JBridgeHandler hasn't changed much as of 1.7.33) logback-classic 1.2.3 (but JULHelper hasn't changed much as of 1.8.0) Log messages are sent using java.util.logging. SLF4JBridgeHandler and LevelChangePropagator are enabled (I was running PlayFramework which does this automatically) logback.xml contains <logger name="com.sun.mail.util" level="DEBUG"/>
Description
LevelChangePropagator is inconsistent with jul-to-slf4j for intermediate values FINER, CONFIG, and any other custom jul Level that you construct. When you logger.finer(), it becomes DEBUG, but when you set the level to DEBUG, then logger.finer() messages disappear. This violates Logback’s Basic selection rule: “A log request of level p issued to a logger having an effective level q, is enabled if p >= q.”
When I configured the level for the logger com.sun.mail.util to ALL in my logback.xml, I observed log messages with level DEBUG. But when I configured the logger's level to DEBUG in logback.xml, the logger became disabled! The library I was observing used java.util.logging and conditionally did
if (logger.isLoggable(Level.FINER)) logger.finer("")
Current implementations
jul-to-slf4j's SLF4JBridgeHandler.callPlainSLF4JLogger: given jul level x, it maps to a slf4j level y:
- x ≤ FINEST = 300 → TRACE
- FINEST < x ≤ FINE = 500 → DEBUG
- including FINER = 400
- FINE < x ≤ INFO = 800 → INFO
- including CONFIG = 700
- INFO < x ≤ WARNING = 900 → WARN
- WARNING < x → ERROR
- including SEVERE = 1000 -> TRACE
LevelChangePropagator's JULHelper.asJULLevel: given slf4j level y, it maps to a jul level x.
- slf4j ALL → jul ALL
- TRACE → FINEST
- DEBUG → FINE
- INFO → INFO
- WARN → WARNING
- ERROR → SEVERE
- OFF → OFF
The problem is that these x values are all at the top of the jul-to-slf4j intervals, but java.util.logging.Logger.isLoggable will reject any message whose level is less than this x. So jul-to-slf4j will log a FINER message as DEBUG, but if you set the slf4j level to DEBUG, then FINER messages are rejected.
Proposed implementation:
I think the correct behavior is for LevelChangePropagator to return the minimum value in each jul-to-slf4j interval rather than the maximum value, so that any jul message that is converted to a given logback level will be enabled when the logback logger is set to that level.
- slf4j TRACE → jul ALL = Integer.MIN_VALUE
- DEBUG → FINEST + 1 = 301
- INFO → FINE + 1 = 501
- WARN → INFO + 1 = 801
- ERROR → WARNING + 1 = 901
- OFF → OFF (this is special-cased in java.util.logging.Logger.isLoggable)