SpringBoot 'logback_events_total' not increasing when using SLF4Js Fluent Logging API

Hey there 👋

Not sure if this is the right place to report, but I noticed that logback_events_total is not increasing when using SLF4Js Fluent Logging API.

So for a minimal example app like this

@SpringBootApplication
public class DemoApplication implements ApplicationRunner {

    private static final Logger logger = LoggerFactory.getLogger(DemoApplication.class);

    public static void main(String[] args) {
        SpringApplication.run(DemoApplication.class, args);
    }

    @Override
    public void run(ApplicationArguments args) {
        for (int i = 1; i <= 100; i++) {
            logger.atWarn().log("This is INFO message #{}", i);
            logger.error("This is ERROR message #{}", i);
        }
    }
}

I get

# HELP logback_events_total Number of log events that were enabled by the effective log level
# TYPE logback_events_total counter
logback_events_total{level="debug"} 0.0
logback_events_total{level="error"} 100.0
logback_events_total{level="info"} 5.0
logback_events_total{level="trace"} 0.0
logback_events_total{level="warn"} 0.0

(where warn should be 100.0 as well actually).

The actual logging works fine, it's just the metrics that are off.

Minimal Spring Boot 3.4.2 app with only spring-boot-starter-actuator, spring-boot-starter-web and micrometer-registry-prometheus. Can happily share a repo containing the minimal example app if required.

Comment From: izeye

This seems to be a duplicate of https://github.com/micrometer-metrics/micrometer/issues/4404.

Comment From: wilkinsona

Thanks for the report but I don't think this is a Spring Boot problem. Here's a minimal app using only SLF4J, Logback, and Micrometer:

package example;

import io.micrometer.core.instrument.binder.logging.LogbackMetrics;
import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LogbackMetricsProblem {

    private static final Logger log = LoggerFactory.getLogger(LogbackMetricsProblem.class);

    public static void main(String[] args) {
        LogbackMetrics metrics = new LogbackMetrics();
        SimpleMeterRegistry meterRegistry = new SimpleMeterRegistry();
        metrics.bindTo(meterRegistry);

        for (int i = 1; i <= 100; i++) {
            log.atWarn().log("This is INFO message #{}", i);
            log.error("This is ERROR message #{}", i);
        }

        meterRegistry.forEachMeter((meter) -> System.out.println(meter.getId() + " " + meter.measure()));
    }

}

The meters output at the end are the following:

MeterId{name='logback.events', tags=[tag(level=warn)]} [Measurement{statistic='COUNT', value=0.0}]
MeterId{name='logback.events', tags=[tag(level=trace)]} [Measurement{statistic='COUNT', value=0.0}]
MeterId{name='logback.events', tags=[tag(level=info)]} [Measurement{statistic='COUNT', value=0.0}]
MeterId{name='logback.events', tags=[tag(level=error)]} [Measurement{statistic='COUNT', value=100.0}]
MeterId{name='logback.events', tags=[tag(level=debug)]} [Measurement{statistic='COUNT', value=0.0}]

Using the fluent API, MetricsTurboFilter is called within an isWarnEnabled() check. At this time format is null and the filter returns immediately and no metrics are recorded. There's no subsequent call to the filter so the event's missed.

It looks like a performance optimisation for using the standard API is causing a problem when using the fluent API. ~Please report this to the Micrometer team so that they can investigate further.~ As @izeye says above, an improvement in this area is being tracked by https://github.com/micrometer-metrics/micrometer/issues/4404.

Comment From: wilkinsona

Thanks, @izeye. I didn't see your reply until after I'd written the above.