JsonRPCHttpService can silently fail to start

[magooster]

Steps to Reproduce (Bug)

1. Configure node for TLS --rpc-http-tls-enabled, --rpc-http-tls-keystore-file=, --rpc-http-tls-keystore-password-file= make the password file path invalid
2. Start the node
3. Try to access JSON_RPC Http endpoint

Expected behavior:
Exception should be thrown and node fails to start

Actual behavior:
Node starts with no JSON-RPC Http service

Frequency:
All the time

Versions (Add all that apply)

• Software version: 1.4.2

Additional Information

As you can see from the logs, never get a log confirming that JsonRPC service has started...

2020-04-06 23:19:03.213+01:00 | main | INFO | JsonRpcHttpService | Starting JsonRPC service on 0.0.0.0:8545
2020-04-06 23:19:03.216+01:00 | main | INFO | WebSocketService | Starting Websocket service on 0.0.0.0:8546
2020-04-06 23:19:03.244+01:00 | vert.x-eventloop-thread-1 | INFO | WebSocketService | Websocket service started and listening on 0.0.0.0:8546
2020-04-06 23:19:03.244+01:00 | main | INFO | MetricsHttpService | Starting metrics http service on 0.0.0.0:9545
2020-04-06 23:19:03.255+01:00 | main | INFO | Runner | Ethereum main loop is up.
2020-04-06 23:19:03.256+01:00 | vert.x-eventloop-thread-2 | INFO | MetricsHttpService | Metrics service started and listening on 9545:9545

netstat -nltp shows nothing listening on 8545

Looking at waitForServiceToStart in org.hyperledger.besu.Runner.java, it would seem only checking the status of the future before it is completed, any future that completes immediately is not checked.

private void waitForServiceToStart(
final String serviceName, final CompletableFuture<?> startFuture) {
while (!startFuture.isDone()) {
try {
startFuture.get(60, TimeUnit.SECONDS);
} catch (final InterruptedException e) {
Thread.currentThread().interrupt();
throw new IllegalStateException("Interrupted while waiting for service to start", e);
} catch (final ExecutionException e) {
LOG.error("Service " + serviceName + " failed to start", e);
throw new IllegalStateException(e);
} catch (final TimeoutException e) {
LOG.warn("Service {} is taking an unusually long time to start", serviceName);
}
}
}

Why not just just call Future.get(60, TimeUnit.SECONDS) without the while loop?

[shemnon]

We in essence poll forever. Every 60 seconds we complain that it is taking too long. The log messages you have show that it isn't complete. What does the log look like after 60 seconds? Do we get an error at error level or a complaint about taking an unusually long time to start?

The logs will be at ERROR or WARN, which should show up in standard output unless you are doing something special to the log4j config.

[magooster]

IMHO: You'll never get an error (warning), as the future has already completed... Future.isDone Returns true if completed in any fashion: normally, exceptionally, or via cancellation.

I can wait forever... I never see the warning in the logs.

With no issues JSON-RPC service starts almost immediately...

2020-04-07 00:59:14.349+01:00 | main | INFO | JsonRpcHttpService | Starting JsonRPC service on 0.0.0.0:8545
2020-04-07 00:59:14.429+01:00 | vert.x-eventloop-thread-1 | INFO | JsonRpcHttpService | JsonRPC service started and listening on 0.0.0.0:8545 with TLS enabled.

[shemnon]

I think we need to go from a while to a do/while then, to give the exception a chance to throw.

[MadelineMurray]

@magooster - #714 will be included in 1.4.4 and should solve this issue. If not, let us know.