Actuator 'loggers' endpoint does not return all loggers for log4j

[alawrenc]

Replicated on SB 1.5.15 through SB 2.2.4

Calling /actuator/loggers returns 9 entries instead of the 412 returned by the default logback implementation. It appears that anything with "configuredLevel": null, is excluded from the log4j output.
Basic log4j project with the loggers endpoint exposed attached. Run with ./gradle bootRun
lo4j-test.zip

[alawrenc]

On further investigation it appears to be the difference between 1)getLoggerContext().getConfiguration().getLoggers() and 2)getLoggerContext().getLoggers().
In Log4j2 the first one returns loggers that have explicit configuration only.
The endpoint delegates to here.
The naive fix would be to merge the results of getLoggerContext().getLoggers() into the current method in some fashion.

[alawrenc]

As a workaround, I extended Log4J2LoggingSystem and added overrides for the get operations that use getLoggerContext().getLoggers() only. This appears to be working as expected/desired. Overriding and changing the set operation in the same fashion was not necessary, and an attempt to do so broke functionality.

  @Override
  // TODO: this is a *hopefully* temporary workaround for a SB bug.
  // tracking at https://github.com/spring-projects/spring-boot/issues/20037
  public List<LoggerConfiguration> getLoggerConfigurations() {
    List<LoggerConfiguration> result = new ArrayList<>();
    final Collection<Logger> loggers = getLoggerContext().getLoggers();
    for (Logger logger : loggers) {
      result.add(convertLoggerToLoggerConfiguration(logger));
    }
    result.sort(CONFIGURATION_COMPARATOR);
    return result;
  }

  @Override
  public LoggerConfiguration getLoggerConfiguration(String loggerName) {
    return convertLoggerToLoggerConfiguration(getLogger(loggerName));
  }

  private LoggerConfiguration convertLoggerToLoggerConfiguration(Logger logger) {
    if (logger == null) {
      return null;
    }
    LogLevel level = LEVELS.convertNativeToSystem(logger.getLevel());
    String name = logger.getName();
    if (!StringUtils.hasLength(name) || LogManager.ROOT_LOGGER_NAME.equals(name)) {
      name = ROOT_LOGGER_NAME;
    }
    return new LoggerConfiguration(name, level, level);
  }

  private Logger getLogger(String name) {
    if (!StringUtils.hasLength(name) || ROOT_LOGGER_NAME.equals(name)) {
      name = LogManager.ROOT_LOGGER_NAME;
    }
    return getLoggerContext().getLogger(name);
  }

[snicoll]

It appears that anything with "configuredLevel": null, is excluded from the log4j output.

@alawrenc what would be the added value of including those? The purpose of the endpoint is to show loggers that have been configured. If they have not, then the default log level applies for them. What have I missed?

[alawrenc]

It makes the Spring Boot Admin functionality for modifying loggers at runtime essentially useless since it only supports modifying loggers returned from that endpoint. Similarly, it makes discovery of available loggers difficult when using the endpoints directly, so you have to know in advance the exact loggers to configure and can't search for related loggers.
Finally! It's just plain surprising. The default logback implementation appears to consider all loggers as configured even when configuredLevel == null (possibly eagerly loading them even?) and makes them available. So purely from a consistency perspective, I'd find it ideal for one of the implementations to change.

[wilkinsona]

It makes the Spring Boot Admin functionality for modifying loggers at runtime essentially useless since it only supports modifying loggers returned from that endpoint.

Regardless of the decision that we make here, I think this should be addressed in Spring Boot Admin. When setting a logger's level using the Actuator endpoint there's no requirement for that logger to already exist.

[alawrenc]

Spring Boot Admin apparently implemented this in October, since another user was having the same issue with log4j

[wilkinsona]

That's good to know. Thank you.

[wilkinsona]

Similarly, it makes discovery of available loggers difficult when using the endpoints directly, so you have to know in advance the exact loggers to configure and can't search for related loggers.

You'll always have to know this to some degree. Even with Logback, a logger will only appear if the class that declares it has been loaded or an instance created (dependency on whether or not the logger declaration is static).

The above said, I think we should align with the behaviour of the Log4j2 logging system with that of the Logback logging system. As things stand, the distinction between configuredLevel and effectiveLevel is pointless for Log4j2 as they're always both the same. Here's an example taken from the provided sample:

"loggers": {
    "ROOT": {
        "configuredLevel": "INFO",
        "effectiveLevel": "INFO"
    },
    "org.apache.catalina.startup.DigesterFactory": {
        "configuredLevel": "ERROR",
        "effectiveLevel": "ERROR"
    },
    "org.apache.catalina.util.LifecycleBase": {
        "configuredLevel": "ERROR",
        "effectiveLevel": "ERROR"
    },
    "org.apache.coyote.http11.Http11NioProtocol": {
        "configuredLevel": "WARN",
        "effectiveLevel": "WARN"
    },
    "org.apache.sshd.common.util.SecurityUtils": {
        "configuredLevel": "WARN",
        "effectiveLevel": "WARN"
    },
    "org.apache.tomcat.util.net.NioSelectorPool": {
        "configuredLevel": "WARN",
        "effectiveLevel": "WARN"
    },
    "org.eclipse.jetty.util.component.AbstractLifeCycle": {
        "configuredLevel": "ERROR",
        "effectiveLevel": "ERROR"
    },
    "org.hibernate.validator.internal.util.Version": {
        "configuredLevel": "WARN",
        "effectiveLevel": "WARN"
    },
    "org.springframework.boot.actuate.endpoint.jmx": {
        "configuredLevel": "WARN",
        "effectiveLevel": "WARN"
    }
}

By comparison, here is some of what you get for the same app using Logback:

"loggers": {
    "ROOT": {
        "configuredLevel": "INFO",
        "effectiveLevel": "INFO"
    },
    "com": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "com.example": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "com.example.lo4jtest": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "com.example.lo4jtest.Lo4jTestApplication": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "io": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "io.micrometer": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "io.micrometer.core": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    },
    "io.micrometer.core.instrument": {
        "configuredLevel": null,
        "effectiveLevel": "INFO"
    }

It's apparent that there are numerous loggers that are logging at info level and they are doing so not because they've specifically been configured with that level but because it's been inherited. The additional information improves logger discoverability and also makes it easier to answer questions about which level a logger is using and why.