logging-log4j2

logging-log4j2 copied to clipboard

Description

When starting an application with:

Logger logger = LogManager.getLogger("test");

It takes 5 seconds consistently for the first logger to initiate. Afterwards, this command can be repeated and there is no slowdown.

This makes it extremely troublesome to run tests, debug as program start time is increased by 5 seconds.

Configuration

Version: [Log4j version] 2.21.1

Operating system: [OS and version] macOS Montery (m1 processor)

JDK: [JDK distribution and version] openjdk-21.0.1

Reproduction

public static void main(String[] args) { long ts = System.currentTimeMillis(); LogManager.getLogger("test"); System.out.println(System.currentTimeMillis() - ts); // eg. 5432 }

I have tested the same with zulu-21 and openjdk-21 with an Apple M2 max. My times are around 250-300ms. I created the attached project to test it. Can you check with this project as well?

simpletest.zip

This is a long-known issue specific to macOS because by default, macOS does not include an entry in /etc/hosts for localhost, so the default behavior of its network stack (or at least in Java) involves DNS lookups to try to determine the hostname of the local interface. Once Java has cached the initial DNS lookup here, it doesn't resolve it again.

Simplest fix is documented in https://github.com/apache/logging-log4j2/blob/2.x/BUILDING.adoc where you can run:

printf '127.0.0.1 %s\n::1 %s\n' `hostname` `hostname` | sudo tee -a /etc/hosts

Edit: the more general issue here is that Log4j caches the local hostname in the configuration properties, but I think that should be deferred unless and until a user references the hostname property in a config file.

I think that we should just log a warning (which will not show up due to the default being ERROR ;-( ) if the lookup takes more than 100 ms. By comparison Tomcat logs a warning if Random() takes more than 100 ms to initialize.

This is a fairly well-known JDK characteristic (see e.g. JDK8143378) that implements InetAddress#getLocalHost() on UNIX-es as:

• a super-fast gethostname call,
• a slow getaddrinfo call with a AI_CANONNAME hint to retrieve the fully qualified host name (2 DNS calls) and discard the result of the reverse lookup.

On the other hand it is pretty common for server software to retrieve the FQDN of the machine, so users experiencing delays with Log4j will also experience delays in e.g. Apache HTTPD. I think it is better to inform the user of the misconfiguration, rather than work around it.

Back when I first tried to debug this, I had fun due to the fact that Java calls into those exact C functions, and you can't exactly debug those through the Java debugger (at least not with older Java versions; the new FFI stuff should make it debuggable). Anyways, I think it's a good idea to warn (and also to set warn as the default level).

OK so why would there be a DNS lookup like this anyway? I don't see any configuration requiring this

@grobmeier, good question!

The naive answer is "if you want to use ${hostName} in a configuration, InetAddress#getLocalHost is one of the few ways to do it in Java", but in fact I don't remember the last time I saw ${hostName} in a configuration file. We should probably move it to a lookup in 3.x.