spring-boot: Log warning on slow host resolution

This came up again recently: https://twitter.com/CRivasGomez/status/1084395737683775488

I’m still not in favour of trying to work around the problem as it will almost certainly occur elsewhere in the app in a place that’s out of our control. Perhaps, in a place that is in our control, we could log a warning when the resolution is too slow:

diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java
index a8b69cb091..82dcc3293b 100644
--- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java
+++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java
@@ -47,7 +47,7 @@ class StartupInfoLogger {
        public void logStarting(Log log) {
                Assert.notNull(log, "Log must not be null");
                if (log.isInfoEnabled()) {
-                       log.info(getStartupMessage());
+                       log.info(getStartupMessage(log));
                }
                if (log.isDebugEnabled()) {
                        log.debug(getRunningMessage());
@@ -60,12 +60,12 @@ class StartupInfoLogger {
                }
        }
 
-       private String getStartupMessage() {
+       private String getStartupMessage(Log log) {
                StringBuilder message = new StringBuilder();
                message.append("Starting ");
                message.append(getApplicationName());
                message.append(getVersion(this.sourceClass));
-               message.append(getOn());
+               message.append(getOn(log));
                message.append(getPid());
                message.append(getContext());
                return message.toString();
@@ -105,8 +105,17 @@ class StartupInfoLogger {
                return getValue(" v", () -> source.getPackage().getImplementationVersion(), "");
        }
 
-       private String getOn() {
-               return getValue(" on ", () -> InetAddress.getLocalHost().getHostName());
+       private String getOn(Log log) {
+               return getValue(" on ", () -> {
+                       InetAddress localHost = InetAddress.getLocalHost();
+                       long start = System.currentTimeMillis();
+                       String hostName = localHost.getHostName();
+                       if (System.currentTimeMillis() - start > 200) {
+                               log.warn("Resolution of the local host's name took in excess of 200ms."
+                                               + " Please verify your network configuration");
+                       }
+                       return hostName;
+               });

200ms is a rather arbitrary value. Resolution takes 0.2ms on my machine so hopefully 1000x that should be sufficient to avoid false positives.

FWIW I’ve also changed my mind about using a thread since I wrote https://github.com/spring-projects/spring-boot/issues/7087#issuecomment-252056754. The timeout warning seems like the best option to me because it will tell users that they have a problem and allow them to fix it for every getHostName call (not just the one that Boot makes).

The conclusion in the JDK issue is that “the times in the report are likely a local configuration issue”. That matches what we have seen too. Using a separate thread and timing out is going to add overhead that slows things down for everyone just to benefit the few that have a local configuration issue. I don’t think it makes sense to do that. We’ve discussed this problem this week and the Boot team are in agreement that we should time how long the call takes and log when it takes too long. The timing will still introduce overhead, but it’s tiny in comparison to using a separate thread.

I don’t think we should be trying to work around this. The underlying cause has been in Java for some time. I believe it’s appearing more frequently now due to the (mis)configuration of macOS after an upgrade to Sierra. It’s also happened in the past with other macOS upgrades.

When you request a hostname, the JDK resolves it to IP addresses. It then tries a reverse lookup of those addresses and checks that at least one of the results maps back to the input host name. It’s this reverse lookup that’s slow. The slowness isn’t limited to the JVM. Anything on the OS that tries to perform such a reverse lookup will be slow without appropriate configuration in /etc/hosts.