SLF4J 2 fluent logging metrics support

[MatthiasDrews]

Describe the bug The metric logback.events in general contains a counter of log events per log level. However, when creating log events via the Slf4j LoggingEventBuilder, these events are ignored by the underlying MetricsTurboFilter. The reason is, that the MetricsTurboFilter seems to be designed to ignore invocations of something like logger.isInfoEnabled(), and only instrument invocations like logger.info(...). However, using the Slf4j LoggingEventBuilder, there will be an invocation like like logger.log(loggingEvent), which is not covered by TurboFilters in general.

Is there a workaround to solve this or does the application need any special configuration for micrometer when using Slf4j this way?

Environment

• Micrometer version: 1.11.5
• Micrometer registry: prometheus
• OS: macOS
• Java version: openjdk 17.0.1 2021-10-19
• Logback version: 1.4.11
• Slf4j version: 2.0.9

To Reproduce How to reproduce the bug:

log.atInfo()
    .setMessage(message)
    .log();

Expected behavior The counter for logback.events.total should count log events produced via the Slf4j fluent API.

[shakuzen]

Is there a workaround to solve this or does the application need any special configuration for micrometer when using Slf4j this way?

I'm not able to find a way to make this work. ~~In the case you showed, the TurboFilter is being called with everything null except the Logger and the Level. I don't see any way to distinguish this case from the isInfoEnabled etc calls that we don't want to count.~~ I'm not sure why the filter isn't called ~with the message~, and I wonder if it is by design or a bug.

[shakuzen]

I've marked this as an enhancement to support SLF4J 2's fluent logging API in some way instead of a bug. The way things are implemented, there's no opportunity for a Logback TurboFilter to be called when using the SLF4J fluent logging. I'm not sure there's anything we can do in Micrometer alone but it would be nice to support metrics on logs made through the new API.

[ArtyomGabeev]

Hiello

I want to share some thoughts about this enhancement. TurboFilter is called when used with fluent builder api. Let's consider next 3 examples:

logger.atInfo() // filter is called
      .log("Hello, world!");

logger.info("Hello, world!"); // filter is called cause internally logger checks isInfoEnabled
    
 if (logger.isInfoEnabled()) { // filter is called here first time
   logger.info("Hello, world!"); // filter is called here second time
}

In order to not increment the log event counter when the is$LEVEL$Enabled method is called, we have introduced a check: if (format != null && ... in the MetricsTurboFilter class.

Unfortunately, it's not possible to distinguish between level enable check VS fluent builder event creation in current implementation based on Turbofilter.

If we want to support this feature, we may try to replace TurboFilter with a custom appender, which should be attached programmatically to Logback loggers.

[wilkinsona]

@izeye kindly pointed me here from #44024. Just in case it's useful, here's the stack when the fluent API calls the turbo filter:

MetricsTurboFilter.decide(Marker, Logger, Level, String, Object[], Throwable) line: 211	
TurboFilterList.getTurboFilterChainDecision(Marker, Logger, Level, String, Object[], Throwable) line: 49	
LoggerContext.getTurboFilterChainDecision_0_3OrMore(Marker, Logger, Level, String, Object[], Throwable) line: 271	
Logger.callTurboFilters(Marker, Level) line: 756	
Logger.isWarnEnabled(Marker) line: 662	
Logger.isWarnEnabled() line: 658	
Logger(Logger).atWarn() line: 732	
LogbackMetricsProblem.main(String[]) line: 34	

This is with SLF4J 2.0.16 and Logback 1.5.16.

As @ArtyomGabeev describes, the problem is that format is null when this call to the filter is made so no metrics are recorded. No further filtering is performed so the event's missed from a metrics perspective.

[shakuzen]

The problem comes down to:

Unfortunately, it's not possible to distinguish between level enable check VS fluent builder event creation in current implementation based on Turbofilter.

Maybe an appender is the only way to do it now, but we haven't thought through the ramifications of doing that and it's a shame the thing that worked until this new API was introduced now no longer works. Maybe there's room for improvement on the SLF4J/Logback side to support use cases like ours.

[ceki]

This issue has a proposed fix in commit https://github.com/qos-ch/logback/commit/1cd2df4be866ba48ec410ecd

see also https://github.com/qos-ch/logback/issues/871

[shakuzen]

@ceki thank you for commenting, and thank you for implementing the fix in logback for this. I've locally built logback and tested this issue. It looks to be fixed with the latest logback code. I used a test like the following, which fails with Logback 1.5.20 and passes with the latest 1.5.21 snapshots.

@Test
void slf4j2FluentApiIncrementsCounter() {
    logger.atWarn().setMessage("test warn log with fluent builder").log();

    assertThat(registry.get("logback.events").tags("level", "warn").counter().count()).isEqualTo(1.0);
}

Once Logback 1.5.21 is released, I think the only thing for us to do is add a test that runs with that version and verifies our LogbackMetrics work as expected (e.g. the above test) with SLF4J 2's fluent logging API. It looks like there isn't anything to change in Micrometer and users will be able to get this working by upgrading to the eventually released next version of Logback. Thanks again for your work on this and letting us know it's fixed @ceki.

[shakuzen]

We've upgraded to building with Logback 1.15.21, and I've added a test for this issue that passes - see https://github.com/micrometer-metrics/micrometer/commit/c18e7034c5f27a248f196b537602984671bbbed4