LogAccessor.debug(CharSequence) eagerly renders LogMessage since spring-core 7 switched from spring-jcl to commons-logging

[hendrikdonvil]

LogAccessor.debug(CharSequence) eagerly renders LogMessage since spring-core 7 switched from spring-jcl to commons-logging

Summary

LogAccessor.debug(CharSequence) and its sibling overloads pass the argument straight to
Log.debug(Object) without checking isDebugEnabled(). They rely on the underlying
org.apache.commons.logging.Log implementation to short-circuit.

That assumption held as long as spring-jcl provided that implementation: its
LogAdapter$Slf4jLocationAwareLog#debug(Object) checks the level before calling
String.valueOf(message).

As of Spring Framework 7, spring-core depends on Apache commons-logging instead of
spring-jcl. Apache's Slf4jLogFactory$Slf4jLocationAwareLog#debug(Object) has no such check —
it calls String.valueOf(message) unconditionally.

The consequence is that every LogAccessor.debug(LogMessage.format(...)) call now fully renders
its lazy LogMessage even when DEBUG is disabled, and the resulting string is discarded by SLF4J.
Because LogMessage exists precisely to make that rendering lazy, and because Spring and its
portfolio projects use this idiom extensively, the cost is significant.

Affected versions

• Spring Framework 7.0.8 (via Spring Boot 4.1.0)
• commons-logging 1.3.5
• Not affected: Spring Framework 6.2.x (verified against 6.2.8 and 6.2.19)

Root cause

1. LogAccessor delegates the level check, inconsistently

org.springframework.core.log.LogAccessor (spring-core 7.0.8), disassembled:

public void debug(java.lang.CharSequence);
   0: aload_0
   1: getfield      #7    // Field log:Lorg/apache/commons/logging/Log;
   4: aload_1
   5: invokeinterface #65 // InterfaceMethod org/apache/commons/logging/Log.debug:(Ljava/lang/Object;)V
  10: return

No guard. Note that the Supplier overload in the same class does guard:

public void debug(java.util.function.Supplier<? extends java.lang.CharSequence>);
   0: aload_0
   1: getfield      #7
   4: invokeinterface #37 // InterfaceMethod org/apache/commons/logging/Log.isDebugEnabled:()Z
   9: ifeq          25
  ...

This asymmetry is the heart of the issue: debug(CharSequence) is only lazy if the Log
implementation makes it lazy.

2. The Log implementation changed

spring-jcl — org.apache.commons.logging.LogAdapter$Slf4jLocationAwareLog#debug(Object):

   1: instanceof    #16   // class java/lang/String
  14: invokeinterface #46 // InterfaceMethod org/slf4j/spi/LocationAwareLogger.isDebugEnabled:()Z
  30: getstatic     #28   // Field FQCN
  36: invokestatic  #32   // Method java/lang/String.valueOf:(Ljava/lang/Object;)Ljava/lang/String;

String.valueOf is reached only when the message is already a String or DEBUG is enabled.

commons-logging 1.3.5 — org.apache.commons.logging.impl.Slf4jLogFactory$Slf4jLocationAwareLog:

public void debug(java.lang.Object);
   1: bipush        10    // LocationAwareLogger.DEBUG_INT
   5: invokespecial #15   // Method log:(ILjava/lang/Object;Ljava/lang/Throwable;)V

private void log(int, java.lang.Object, java.lang.Throwable);
   1: getfield      #9    // Field logger:Lorg/slf4j/spi/LocationAwareLogger;
  12: invokestatic  #55   // Method java/lang/String.valueOf:(Ljava/lang/Object;)Ljava/lang/String;
  19: invokeinterface #65 // InterfaceMethod org/slf4j/spi/LocationAwareLogger.log:(...)

No level check anywhere in the path. The non-location-aware variant
(Slf4jLogFactory$Slf4jLog#debug(Object)) behaves the same way.

3. The dependency swap

spring-core 6.2.8  -> org.springframework:spring-jcl
spring-core 6.2.19 -> org.springframework:spring-jcl
spring-core 7.0.8  -> commons-logging:commons-logging

With Spring Framework 7 there is no spring-jcl on the classpath at all, so Apache's
implementation is the only one available.

Impact, as measured

Measured with JDK Flight Recorder (settings=profile, jdk.ObjectAllocationSample) on a Spring
Boot application, running an identical set of 14 integration tests against each build.

build	total allocation	allocated under LogMessage.toString
before upgrade (Spring Boot 3.x / Framework 6.2.19)	11.9 GB	0.00 GB
after upgrade (Spring Boot 4.1.0 / Framework 7.0.8)	16.1 GB	4.04 GB
after upgrade, with spring-jcl forced back onto the classpath	11.3 GB	0.00 GB

The regression is 4.2 GB, of which 4.04 GB (96%) is attributable to rendering log messages that
are never emitted. Restoring spring-jcl removes it entirely.

The dominant single contributor in our application is Spring Integration, which uses the idiom
heavily. GenericMessage.toString() alone accounted for 2.66 GB — 16.5% of all allocation — with
this call chain:

org.springframework.integration.handler.AbstractReplyProducingMessageHandler#handleMessageInternal
  -> LogAccessor#debug(CharSequence)                        // no guard
    -> Slf4jLogFactory$Slf4jLocationAwareLog#debug(Object)   // no guard
      -> String.valueOf(message)
        -> LogMessage$FormatMessage2#buildString
          -> GenericMessage#toString                         // renders the full payload
            -> LocationAwareLogger#log(...)                  // discarded, level is INFO

AbstractReplyProducingMessageHandler is written correctly against the documented contract:

if (!isAsync() && isLoggingEnabled()) {
    logger.debug(LogMessage.format("handler '%s' produced no reply for request Message: %s", this, message));
}

Not a single DEBUG line was emitted during the run. All of this work was thrown away.

Reproduction

1. Spring Boot 4.1.0 application, logging at INFO.
2. Any code path calling LogAccessor.debug(LogMessage.format(...)) with a non-trivial argument —
   Spring Integration's message handlers are an easy trigger.
3. Record allocations with JFR (-XX:StartFlightRecording=settings=profile,...).
4. Observe LogMessage$FormatMessage2#buildString and the argument's toString() in the
   allocation profile despite DEBUG being disabled.
5. Add org.springframework:spring-jcl and exclude commons-logging:commons-logging; the
   allocation disappears.

Suggested fixes

Any one of these would resolve it; they are listed in what we believe is decreasing preference.

1. Guard inside LogAccessor. Make debug(CharSequence), trace(CharSequence) and the other
   non-Supplier overloads check isDebugEnabled() / isTraceEnabled() before delegating. This
   makes LogAccessor independent of the Log implementation and matches the behaviour the
   Supplier overloads already have.
2. Depend on a bridge that short-circuits. Either keep spring-jcl, or document that a
   guarding commons-logging implementation is required.
3. Document the change. If the eager behaviour is intentional, it deserves a note in the
   migration guide, since LogMessage is advertised as a lazy formatter and a great deal of
   portfolio code passes it to the non-Supplier overloads.

Notes

• We did not find an existing issue for this, but we may have missed it.
• Our workaround is to exclude commons-logging and add org.springframework:spring-jcl:6.2.19
  explicitly. That combination works and all our tests pass, but it is clearly not a supported
  configuration and we would rather not keep it.
• Whether Apache commons-logging should perform the check itself is a separate question. We are
  reporting it here because the behavioural change was introduced by the spring-core dependency
  swap and because LogAccessor is the API that carries the laziness contract.

[sbrannen]

Hi @hendrikdonvil,

Thanks for bringing this to our attention.

This is indeed a regression that was introduced in Spring Framework 7.0.

• Related to: Current log level not checked by LogAccessor supplier-enabled logging methods #25741

[github-actions]

Fixed via b96592e