Error handling and logging improvements (Consensys#9)

ethfirewall/src/integration-test/java/tech/pegasys/ethfirewall/jsonrpcproxy/IntegrationTestBase.java

@@ -34,6 +34,7 @@
 import java.net.URL;
 import java.nio.file.Files;
 import java.nio.file.Path;
+import java.time.Duration;
 import java.util.List;
 import java.util.Map;
 
@@ -85,7 +86,8 @@ public static void setupEthFirewall() throws IOException, CipherException {
     httpServerOptions.setPort(serverSocket.getLocalPort());
     httpServerOptions.setHost("localhost");
 
-    runner = new Runner(transactionSigner, httpClientOptions, httpServerOptions);
+    runner =
+        new Runner(transactionSigner, httpClientOptions, httpServerOptions, Duration.ofSeconds(5));
     runner.start();
 
     LOG.info(

ethfirewall/src/main/java/tech/pegasys/ethfirewall/EthFirewall.java

@@ -53,20 +53,31 @@ public void run() {
       return;
     }
 
+    if (config.getDownstreamHttpRequestTimeout().toMillis() <= 0) {
+      LOG.error("Http request timeout must be greater than 0.");
+      return;
+    }
+
+    if (config.getHttpListenHost().equals(config.getDownstreamHttpHost())
+        && config.getHttpListenPort().equals(config.getDownstreamHttpPort())) {
+      LOG.error("Http host and port must be different to the downstream host and port.");
+      return;
+    }
+
     try {
       runnerBuilder.setTransactionSigner(
           transactionSigner(config.getKeyPath().toFile(), password.get(), config.getChainId()));
       runnerBuilder.setClientOptions(
           new WebClientOptions()
               .setDefaultPort(config.getDownstreamHttpPort())
-              .setDefaultHost(config.getDownstreamHttpHost()));
+              .setDefaultHost(config.getDownstreamHttpHost().getHostAddress()));
       runnerBuilder.setServerOptions(
           new HttpServerOptions()
               .setPort(config.getHttpListenPort())
-              .setHost(config.getHttpListenHost())
+              .setHost(config.getHttpListenHost().getHostAddress())
               .setReuseAddress(true)
               .setReusePort(true));
-
+      runnerBuilder.setHttpRequestTimeout(config.getDownstreamHttpRequestTimeout());
       runnerBuilder.build().start();
     } catch (IOException ex) {
       LOG.info(

ethfirewall/src/main/java/tech/pegasys/ethfirewall/EthFirewallCommandLineConfig.java

@@ -16,7 +16,9 @@
 import tech.pegasys.ethfirewall.signing.ConfigurationChainId;
 
 import java.io.PrintStream;
+import java.net.InetAddress;
 import java.nio.file.Path;
+import java.time.Duration;
 
 import org.apache.logging.log4j.Level;
 import org.slf4j.Logger;
@@ -71,7 +73,7 @@ public class EthFirewallCommandLineConfig implements EthFirewallConfig {
       names = "--downstream-http-host",
       description = "The endpoint to which received requests are forwarded",
       arity = "1")
-  private String downstreamHttpHost = "127.0.0.1";
+  private InetAddress downstreamHttpHost = InetAddress.getLoopbackAddress();
 
   @Option(
       names = "--downstream-http-port",
@@ -80,12 +82,19 @@ public class EthFirewallCommandLineConfig implements EthFirewallConfig {
       arity = "1")
   private Integer downstreamHttpPort;
 
+  @Option(
+      names = {"--downstream-http-request-timeout"},
+      description =
+          "Timeout (in milliseconds) to wait for downstream request to timeout (default: ${DEFAULT-VALUE})",
+      arity = "1")
+  private long downstreamHttpRequestTimeout = Duration.ofSeconds(5).toMillis();
+
   @SuppressWarnings("FieldMayBeFinal") // Because PicoCLI requires Strings to not be final.
   @Option(
       names = {"--http-listen-host"},
       description = "Host for JSON-RPC HTTP to listen on (default: ${DEFAULT-VALUE})",
       arity = "1")
-  private String httpListenHost = "127.0.0.1";
+  private InetAddress httpListenHost = InetAddress.getLoopbackAddress();
 
   @Option(
       names = {"--http-listen-port"},
@@ -159,7 +168,7 @@ public Path getKeyPath() {
   }
 
   @Override
-  public String getDownstreamHttpHost() {
+  public InetAddress getDownstreamHttpHost() {
     return downstreamHttpHost;
   }
 
@@ -169,7 +178,7 @@ public Integer getDownstreamHttpPort() {
   }
 
   @Override
-  public String getHttpListenHost() {
+  public InetAddress getHttpListenHost() {
     return httpListenHost;
   }
 
@@ -182,4 +191,9 @@ public Integer getHttpListenPort() {
   public ChainIdProvider getChainId() {
     return new ConfigurationChainId(chainId);
   }
+
+  @Override
+  public Duration getDownstreamHttpRequestTimeout() {
+    return Duration.ofMillis(downstreamHttpRequestTimeout);
+  }
 }

ethfirewall/src/main/java/tech/pegasys/ethfirewall/EthFirewallConfig.java

@@ -14,7 +14,9 @@
 
 import tech.pegasys.ethfirewall.signing.ChainIdProvider;
 
+import java.net.InetAddress;
 import java.nio.file.Path;
+import java.time.Duration;
 
 import org.apache.logging.log4j.Level;
 
@@ -26,11 +28,13 @@ public interface EthFirewallConfig {
 
   Path getKeyPath();
 
-  String getDownstreamHttpHost();
+  InetAddress getDownstreamHttpHost();
 
   Integer getDownstreamHttpPort();
 
-  String getHttpListenHost();
+  Duration getDownstreamHttpRequestTimeout();
+
+  InetAddress getHttpListenHost();
 
   Integer getHttpListenPort();
 

ethfirewall/src/main/java/tech/pegasys/ethfirewall/Runner.java

@@ -18,6 +18,8 @@
 import tech.pegasys.ethfirewall.jsonrpcproxy.TransactionBodyProvider;
 import tech.pegasys.ethfirewall.signing.TransactionSigner;
 
+import java.time.Duration;
+
 import io.vertx.core.AsyncResult;
 import io.vertx.core.Vertx;
 import io.vertx.core.http.HttpClient;
@@ -33,23 +35,27 @@ public class Runner {
   private TransactionSigner transactionSigner;
   private HttpClientOptions clientOptions;
   private HttpServerOptions serverOptions;
+  private Duration httpRequestTimeout;
   private Vertx vertx;
   private String deploymentId;
 
   public Runner(
       final TransactionSigner transactionSigner,
       final HttpClientOptions clientOptions,
-      final HttpServerOptions serverOptions) {
+      final HttpServerOptions serverOptions,
+      final Duration httpRequestTimeout) {
     this.transactionSigner = transactionSigner;
     this.clientOptions = clientOptions;
     this.serverOptions = serverOptions;
+    this.httpRequestTimeout = httpRequestTimeout;
   }
 
   public void start() {
     // NOTE: Starting vertx spawns daemon threads, meaning the app may complete, but not terminate.
     vertx = Vertx.vertx();
     final RequestMapper requestMapper = createRequestMapper(vertx, transactionSigner);
-    final JsonRpcHttpService httpService = new JsonRpcHttpService(serverOptions, requestMapper);
+    final JsonRpcHttpService httpService =
+        new JsonRpcHttpService(serverOptions, httpRequestTimeout, requestMapper);
     vertx.deployVerticle(httpService, this::handleDeployResult);
   }
 
@@ -79,9 +85,10 @@ private RequestMapper createRequestMapper(
   private void handleDeployResult(final AsyncResult<String> result) {
     if (result.succeeded()) {
       deploymentId = result.result();
-      LOG.info("Deployment id is: {}", deploymentId);
+      LOG.info("Vertx deployment id is: {}", deploymentId);
     } else {
-      LOG.warn("Deployment failed! ", result.cause());
+      LOG.error("Vertx deployment failed", result.cause());
+      System.exit(1);
     }
   }
 }

ethfirewall/src/main/java/tech/pegasys/ethfirewall/RunnerBuilder.java

@@ -14,6 +14,8 @@
 
 import tech.pegasys.ethfirewall.signing.TransactionSigner;
 
+import java.time.Duration;
+
 import io.vertx.core.http.HttpServerOptions;
 import io.vertx.ext.web.client.WebClientOptions;
 import org.slf4j.Logger;
@@ -26,6 +28,7 @@ public class RunnerBuilder {
   private TransactionSigner transactionSigner;
   private WebClientOptions clientOptions;
   private HttpServerOptions serverOptions;
+  private Duration requestTimeout;
 
   public RunnerBuilder() {}
 
@@ -41,6 +44,10 @@ public void setServerOptions(final HttpServerOptions serverOptions) {
     this.serverOptions = serverOptions;
   }
 
+  public void setHttpRequestTimeout(final Duration requestTimeout) {
+    this.requestTimeout = requestTimeout;
+  }
+
   public Runner build() {
     if (transactionSigner == null) {
       LOG.error("Unable to construct Runner, transactionSigner is unset.");
@@ -54,6 +61,10 @@ public Runner build() {
       LOG.error("Unable to construct Runner, serverOptions is unset.");
       return null;
     }
-    return new Runner(transactionSigner, clientOptions, serverOptions);
+    if (requestTimeout == null) {
+      LOG.error("Unable to construct Runner, requestTimeout is unset.");
+      return null;
+    }
+    return new Runner(transactionSigner, clientOptions, serverOptions, requestTimeout);
   }
 }

ethfirewall/src/main/java/tech/pegasys/ethfirewall/jsonrpcproxy/JsonRpcHttpService.java

@@ -12,6 +12,8 @@
  */
 package tech.pegasys.ethfirewall.jsonrpcproxy;
 
+import java.time.Duration;
+
 import io.netty.handler.codec.http.HttpHeaderValues;
 import io.vertx.core.AbstractVerticle;
 import io.vertx.core.Future;
@@ -23,6 +25,7 @@
 import io.vertx.ext.web.RoutingContext;
 import io.vertx.ext.web.handler.BodyHandler;
 import io.vertx.ext.web.handler.ResponseContentTypeHandler;
+import io.vertx.ext.web.handler.TimeoutHandler;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -33,11 +36,15 @@ public class JsonRpcHttpService extends AbstractVerticle {
 
   private final RequestMapper requestHandlerMapper;
   private final HttpServerOptions serverOptions;
+  private final Duration httpRequestTimeout;
   private HttpServer httpServer = null;
 
   public JsonRpcHttpService(
-      final HttpServerOptions serverOptions, final RequestMapper requestHandlerMapper) {
+      final HttpServerOptions serverOptions,
+      final Duration httpRequestTimeout,
+      final RequestMapper requestHandlerMapper) {
     this.serverOptions = serverOptions;
+    this.httpRequestTimeout = httpRequestTimeout;
     this.requestHandlerMapper = requestHandlerMapper;
   }
 
@@ -77,6 +84,7 @@ private Router router() {
         .produces(JSON)
         .handler(BodyHandler.create())
         .handler(ResponseContentTypeHandler.create())
+        .handler(TimeoutHandler.create(httpRequestTimeout.toMillis()))
         .failureHandler(new LogErrorHandler())
         .handler(this::handleJsonRpc);
     router.route().handler(context -> {});

ethfirewall/src/main/java/tech/pegasys/ethfirewall/jsonrpcproxy/LogErrorHandler.java

@@ -28,6 +28,8 @@ public void handle(final RoutingContext failureContext) {
       LOG.error(
           String.format("Failed sendRequest: %s", failureContext.request().absoluteURI()),
           failureContext.failure());
+      // Let the next matching route or error handler deal with the error, we only handle logging
+      failureContext.next();
     } else {
       LOG.warn("Error handler triggered without any propagated failure");
     }

ethfirewall/src/main/java/tech/pegasys/ethfirewall/jsonrpcproxy/PassThroughHandler.java

@@ -60,8 +60,9 @@ public void handle(final RoutingContext context) {
     proxyRequest.headers().remove("Content-Length"); // created during 'end'.
     proxyRequest.setChunked(false);
 
-    proxyRequest.end(bodyProvider.getBody(context));
-    logRequest(context, proxyRequest);
+    final Buffer proxyRequestBody = bodyProvider.getBody(context);
+    proxyRequest.end(proxyRequestBody);
+    logRequest(context, proxyRequest, proxyRequestBody);
   }
 
   private void logResponse(final HttpClientResponse response) {
@@ -72,13 +73,17 @@ private void logResponseBody(final Buffer body) {
     LOG.debug("Response body: {}", body);
   }
 
-  private void logRequest(final RoutingContext context, final HttpClientRequest proxyRequest) {
+  private void logRequest(
+      final RoutingContext context,
+      final HttpClientRequest proxyRequest,
+      final Buffer proxyRequestBody) {
     LOG.debug(
-        "Send Request downstream: method: {}, uri: {}, body: {}, ethNodeClient: method: {}, uri: {}",
+        "Proxying originalRequest: method: {}, uri: {}, body: {}, target: method: {}, uri: {}, body: {}",
         context.request().method(),
         context.request().absoluteURI(),
         context.getBody(),
         proxyRequest.method(),
-        proxyRequest.absoluteURI());
+        proxyRequest.absoluteURI(),
+        proxyRequestBody);
   }
 }

ethfirewall/src/test/java/tech/pegasys/ethfirewall/EthFirewallCommandLineConfigTest.java

@@ -16,6 +16,9 @@
 
 import java.io.ByteArrayOutputStream;
 import java.io.PrintStream;
+import java.net.InetAddress;
+import java.net.UnknownHostException;
+import java.time.Duration;
 import java.util.function.Supplier;
 
 import org.apache.logging.log4j.Level;
@@ -38,8 +41,9 @@ private boolean parseCommand(String cmdLine) {
   private String validCommandLine() {
     return "--key-file=./keyfile "
         + "--password-file=./passwordFile "
-        + "--downstream-http-host=127.0.0.1 "
+        + "--downstream-http-host=8.8.8.8 "
         + "--downstream-http-port=5000 "
+        + "--downstream-http-request-timeout=10000 "
         + "--http-listen-port=5001 "
         + "--http-listen-host=localhost "
         + "--chain-id=6 "
@@ -55,16 +59,17 @@ private String modifyField(final String input, final String fieldname, final Str
   }
 
   @Test
-  public void fullyPopulatedCommandLineParsesIntoVariables() {
+  public void fullyPopulatedCommandLineParsesIntoVariables() throws UnknownHostException {
     final boolean result = parseCommand(validCommandLine());
 
     assertThat(result).isTrue();
     assertThat(config.getLogLevel()).isEqualTo(Level.INFO);
     assertThat(config.getKeyPath().toString()).isEqualTo("./keyfile");
     assertThat(config.getPasswordFilePath().toString()).isEqualTo("./passwordFile");
-    assertThat(config.getDownstreamHttpHost()).isEqualTo("127.0.0.1");
+    assertThat(config.getDownstreamHttpHost()).isEqualTo(InetAddress.getByName("8.8.8.8"));
     assertThat(config.getDownstreamHttpPort()).isEqualTo(5000);
-    assertThat(config.getHttpListenHost()).isEqualTo("localhost");
+    assertThat(config.getDownstreamHttpRequestTimeout()).isEqualTo(Duration.ofSeconds(10));
+    assertThat(config.getHttpListenHost()).isEqualTo(InetAddress.getByName("localhost"));
     assertThat(config.getHttpListenPort()).isEqualTo(5001);
   }
 
@@ -98,15 +103,21 @@ public void missingOptionalParametersAreSetToDefault() {
 
     config = new EthFirewallCommandLineConfig(outPrintStream);
     missingOptionalParameterIsValidAndMeetsDefault(
-        "downstream-http-host", config::getDownstreamHttpHost, "127.0.0.1");
+        "downstream-http-host", config::getDownstreamHttpHost, InetAddress.getLoopbackAddress());
+
+    config = new EthFirewallCommandLineConfig(outPrintStream);
+    missingOptionalParameterIsValidAndMeetsDefault(
+        "downstream-http-request-timeout",
+        config::getDownstreamHttpRequestTimeout,
+        Duration.ofSeconds(5));
 
     config = new EthFirewallCommandLineConfig(outPrintStream);
     missingOptionalParameterIsValidAndMeetsDefault(
         "http-listen-port", config::getHttpListenPort, 8545);
 
     config = new EthFirewallCommandLineConfig(outPrintStream);
     missingOptionalParameterIsValidAndMeetsDefault(
-        "http-listen-host", config::getHttpListenHost, "127.0.0.1");
+        "http-listen-host", config::getHttpListenHost, InetAddress.getLoopbackAddress());
   }
 
   private void missingParameterShowsError(final String paramToRemove) {