Final set of changes for presto-gateway to reduce 502s for clients

gateway-ha/src/main/java/com/lyft/data/gateway/ha/handler/QueryIdCachingProxyHandler.java

@@ -1,6 +1,10 @@
 package com.lyft.data.gateway.ha.handler;
 
+import static com.codahale.metrics.MetricRegistry.name;
+
+import com.codahale.metrics.Counter;
 import com.codahale.metrics.Meter;
+import com.codahale.metrics.MetricRegistry;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import com.google.common.base.Strings;
 import com.google.common.io.CharStreams;
@@ -28,6 +32,7 @@
 import org.eclipse.jetty.http.HttpStatus;
 import org.eclipse.jetty.util.Callback;
 
+
 @Slf4j
 public class QueryIdCachingProxyHandler extends ProxyHandler {
   public static final String PROXY_TARGET_HEADER = "proxytarget";
@@ -57,13 +62,19 @@ public class QueryIdCachingProxyHandler extends ProxyHandler {
   private final Meter requestMeter;
   private final int serverApplicationPort;
 
+  private final Counter errorCounter4xx;
+  private final Counter errorCounter5xx;
+
   public QueryIdCachingProxyHandler(
       QueryHistoryManager queryHistoryManager,
       RoutingManager routingManager,
       RoutingGroupSelector routingGroupSelector,
       int serverApplicationPort,
-      Meter requestMeter) {
+      Meter requestMeter,
+      MetricRegistry metrics) {
     this.requestMeter = requestMeter;
+    this.errorCounter4xx = metrics.counter(name(QueryIdCachingProxyHandler.class, "4xx"));
+    this.errorCounter5xx = metrics.counter(name(QueryIdCachingProxyHandler.class, "5xx"));
     this.routingManager = routingManager;
     this.routingGroupSelector = routingGroupSelector;
     this.queryHistoryManager = queryHistoryManager;
@@ -270,6 +281,11 @@ protected void postConnectionHook(
     } catch (Exception e) {
       log.error("Error in proxying falling back to super call", e);
     }
+    if (response.getStatus() >= 500) {
+      errorCounter5xx.inc();
+    } else if (response.getStatus() >= 400) {
+      errorCounter4xx.inc();
+    }
     super.postConnectionHook(request, response, buffer, offset, length, callback);
   }
 

gateway-ha/src/main/java/com/lyft/data/gateway/ha/module/HaGatewayProviderModule.java

@@ -1,6 +1,7 @@
 package com.lyft.data.gateway.ha.module;
 
 import com.codahale.metrics.Meter;
+import com.codahale.metrics.MetricRegistry;
 import com.google.inject.Provides;
 import com.google.inject.Singleton;
 import com.lyft.data.baseapp.AppModule;
@@ -23,6 +24,7 @@
 import com.lyft.data.proxyserver.ProxyServerConfiguration;
 import io.dropwizard.setup.Environment;
 
+
 public class HaGatewayProviderModule extends AppModule<HaGatewayConfiguration, Environment> {
 
   private final ResourceGroupsManager resourceGroupsManager;
@@ -42,9 +44,9 @@ public HaGatewayProviderModule(HaGatewayConfiguration configuration, Environment
   }
 
   protected ProxyHandler getProxyHandler() {
+    MetricRegistry metrics = getEnvironment().metrics();
     Meter requestMeter =
-        getEnvironment()
-            .metrics()
+        metrics
             .meter(getConfiguration().getRequestRouter().getName() + ".requests");
 
     // By default, use routing group header to route
@@ -61,7 +63,8 @@ protected ProxyHandler getProxyHandler() {
         getRoutingManager(),
         routingGroupSelector,
         getApplicationPort(),
-        requestMeter);
+        requestMeter,
+        metrics);
   }
 
   @Provides
@@ -81,6 +84,7 @@ public ProxyServer provideGateway() {
       routerProxyConfig.setKeystorePass(routerConfiguration.getKeystorePass());
       routerProxyConfig.setForwardKeystore(routerConfiguration.isForwardKeystore());
       routerProxyConfig.setPreserveHost("false");
+
       ProxyHandler proxyHandler = getProxyHandler();
       gateway = new ProxyServer(routerProxyConfig, proxyHandler);
     }

pom.xml

@@ -7,7 +7,7 @@
     <artifactId>prestogateway-parent</artifactId>
     <name>prestogateway-parent</name>
     <packaging>pom</packaging>
-    <version>1.9.6-SNAPSHOT</version>
+    <version>1.9.7</version>
 
     <properties>
         <maven.compiler.source>1.8</maven.compiler.source>
@@ -118,4 +118,16 @@
             </plugin>
         </plugins>
     </build>
+    <distributionManagement>
+        <repository>
+            <id>lyft-releases</id>
+            <name>release</name>
+            <url>https://artifactory.lyft.net/artifactory/virtual-maven-libs-release</url>
+        </repository>
+        <snapshotRepository>
+            <id>lyft-snapshots</id>
+            <name>libs-snapshot</name>
+            <url>https://artifactory.lyft.net/artifactory/virtual-maven-libs-snapshot</url>
+        </snapshotRepository>
+    </distributionManagement>
 </project>

proxyserver/pom.xml

@@ -62,6 +62,12 @@
             <artifactId>mockwebserver</artifactId>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>com.fasterxml.jackson.core</groupId>
+            <artifactId>jackson-databind</artifactId>
+            <version>2.14.2</version>
+            <scope>compile</scope>
+        </dependency>
     </dependencies>
     <build>
         <plugins>

proxyserver/src/main/java/com/lyft/data/proxyserver/ProxyHandler.java

@@ -8,7 +8,6 @@
 import java.util.Collection;
 import java.util.Enumeration;
 import java.util.zip.GZIPInputStream;
-
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
@@ -60,12 +59,8 @@ protected void postConnectionHook(
                 request.getRequestURL());
       }
       response.getOutputStream().write(buffer, offset, length);
-
       callback.succeeded();
     } catch (Throwable var9) {
-      log.error("Exception occurred while processing request URL: {} , request URI {} ,"
-                      + " servlet path {} , toString {}", request.getRequestURL(),
-              request.getRequestURI(), request.getServletPath(), request.toString(), var9);
       callback.failed(var9);
     }
   }

proxyserver/src/main/java/com/lyft/data/proxyserver/ProxyServer.java

@@ -1,25 +1,31 @@
 package com.lyft.data.proxyserver;
 
+import com.fasterxml.jackson.databind.ObjectMapper;
+import com.fasterxml.jackson.databind.node.ObjectNode;
 import java.io.Closeable;
 import java.io.File;
 import java.util.EnumSet;
+import java.util.Enumeration;
 import java.util.concurrent.TimeUnit;
-
 import javax.servlet.DispatcherType;
 import javax.servlet.Filter;
-
 import lombok.extern.slf4j.Slf4j;
-
 import org.apache.http.util.TextUtils;
 import org.eclipse.jetty.http.HttpScheme;
 import org.eclipse.jetty.http.HttpVersion;
 import org.eclipse.jetty.proxy.ConnectHandler;
+import org.eclipse.jetty.server.CustomRequestLog;
+import org.eclipse.jetty.server.Handler;
 import org.eclipse.jetty.server.HttpConfiguration;
 import org.eclipse.jetty.server.HttpConnectionFactory;
+import org.eclipse.jetty.server.Request;
+import org.eclipse.jetty.server.Response;
 import org.eclipse.jetty.server.SecureRequestCustomizer;
 import org.eclipse.jetty.server.Server;
 import org.eclipse.jetty.server.ServerConnector;
+import org.eclipse.jetty.server.Slf4jRequestLogWriter;
 import org.eclipse.jetty.server.SslConnectionFactory;
+import org.eclipse.jetty.server.handler.HandlerCollection;
 import org.eclipse.jetty.servlet.ServletContextHandler;
 import org.eclipse.jetty.servlet.ServletHolder;
 import org.eclipse.jetty.util.ssl.SslContextFactory;
@@ -30,6 +36,7 @@ public class ProxyServer implements Closeable {
   private final ProxyServletImpl proxy;
   private final ProxyHandler proxyHandler;
   private ServletContextHandler context;
+  private boolean accessLogEnabled;
 
   public ProxyServer(ProxyServerConfiguration config, ProxyHandler proxyHandler) {
     this(config, proxyHandler, new ProxyServletImpl());
@@ -44,6 +51,8 @@ public ProxyServer(ProxyServerConfiguration config, ProxyHandler proxyHandler,
 
     this.proxy.setServerConfig(config);
     this.setupContext(config);
+    //cheap flag to turn on Jetty access logging
+    this.accessLogEnabled = false;
   }
 
   private void setupContext(ProxyServerConfiguration config) {
@@ -59,6 +68,7 @@ private void setupContext(ProxyServerConfiguration config) {
       sslContextFactory.setStopTimeout(TimeUnit.SECONDS.toMillis(15));
       sslContextFactory.setSslSessionTimeout((int) TimeUnit.SECONDS.toMillis(15));
 
+
       if (!TextUtils.isBlank(keystorePath)) {
         sslContextFactory.setKeyStorePath(keystoreFile.getAbsolutePath());
         sslContextFactory.setKeyStorePassword(keystorePass);
@@ -69,6 +79,8 @@ private void setupContext(ProxyServerConfiguration config) {
       httpsConfig.setSecureScheme(HttpScheme.HTTPS.asString());
       httpsConfig.setSecurePort(config.getLocalPort());
       httpsConfig.setOutputBufferSize(32768);
+      httpsConfig.setRequestHeaderSize(2048000);
+      httpsConfig.setResponseHeaderSize(2048000);
 
       SecureRequestCustomizer src = new SecureRequestCustomizer();
       src.setStsMaxAge(TimeUnit.SECONDS.toSeconds(2000));
@@ -86,27 +98,99 @@ private void setupContext(ProxyServerConfiguration config) {
     connector.setPort(config.getLocalPort());
     connector.setName(config.getName());
     connector.setAccepting(true);
+    connector.setIdleTimeout(150000L);
+    connector.setAcceptQueueSize(1024);
     this.server.addConnector(connector);
 
     // Setup proxy handler to handle CONNECT methods
     ConnectHandler proxyConnectHandler = new ConnectHandler();
-    this.server.setHandler(proxyConnectHandler);
+
+    HandlerCollection handlers = new HandlerCollection();
+
+    if (this.accessLogEnabled) {
+      Slf4jRequestLogWriter slfjRequestLogWriter = new Slf4jRequestLogWriter();
+      slfjRequestLogWriter.setLoggerName("request.log");
+      String myFormat =
+          "ACCESS LOG %{client}a - %u %t \"%r\" %s %O \"%{Referer}i\" \"%{User-Agent}i\" **%T/%D**";
+
+
+      CustomRequestLog requestLog = new CustomRequestLog(slfjRequestLogWriter,myFormat) {
+        @Override
+        public void log(Request request, Response response) {
+          String clientAddress = request.getRemoteAddr();
+          String username = request.getRemoteUser();
+          String requestTime = String.valueOf(request.getTimeStamp());
+          String requestMethod = request.getMethod();
+          String requestUri = request.getRequestURI();
+          int responseStatus = response.getStatus();
+          long responseSize = response.getContentCount();
+          String referer = request.getHeader("Referer");
+          String userAgent = request.getHeader("User-Agent");
+          long requestDurationMs = System.currentTimeMillis() - request.getTimeStamp();
+
+          String logMessageString = "ACCESS LOG == " + clientAddress + " - "
+                  + (username != null ? username : "-") + " " + requestTime
+                  + " \"" + requestMethod + " " + requestUri + " " + request.getProtocol()
+                  + "\" " + responseStatus + " " + responseSize + " \""
+                  + (referer != null ? referer : "-") + "\" \""
+                  + (userAgent != null ? userAgent : "-")
+                  + "\" **" + (requestDurationMs / 1000) + "/" + requestDurationMs + "**";
+
+          ObjectMapper mapper = new ObjectMapper();
+          ObjectNode logMessage = mapper.createObjectNode();
+          logMessage.put("clientAddress", clientAddress);
+          logMessage.put("username", username != null ? username : "-");
+          logMessage.put("requestTime", requestTime);
+          logMessage.put("requestMethod", requestMethod);
+          logMessage.put("requestURI", requestUri);
+          logMessage.put("protocol", request.getProtocol());
+          logMessage.put("responseStatus", responseStatus);
+          logMessage.put("responseSize", responseSize);
+          logMessage.put("referer", referer != null ? referer : "-");
+          logMessage.put("userAgent", userAgent != null ? userAgent : "-");
+          logMessage.put("requestDurationMs", requestDurationMs);
+          try {
+            Enumeration<String> headerNames = request.getHeaderNames();
+            while (headerNames.hasMoreElements()) {
+              String header = headerNames.nextElement();
+              logMessage.put("request_header_" + header, request.getHeader(header));
+            }
+
+            for (String i: response.getHeaderNames()) {
+              logMessage.put("request_header_" + i, response.getHeader(i));
+            }
+
+            log.info("ACCESS LOG: {} : {}", logMessage.toString(),
+                      request.getHeader("proxytarget"), request.getHeaderNames());
+
+          } catch (Exception e) {
+            log.error("Error logging access log message", e);
+          }
+
+        }
+      };
+
+      this.server.setRequestLog(requestLog);
+    }
+
+    handlers.setHandlers(new Handler[] { proxyConnectHandler });
+    this.server.setHandler(handlers);
 
     if (proxyHandler != null) {
       proxy.setProxyHandler(proxyHandler);
     }
 
     ServletHolder proxyServlet = new ServletHolder(config.getName(), proxy);
-
     proxyServlet.setInitParameter("proxyTo", config.getProxyTo());
     proxyServlet.setInitParameter("prefix", config.getPrefix());
     proxyServlet.setInitParameter("trustAll", config.getTrustAll());
     proxyServlet.setInitParameter("preserveHost", config.getPreserveHost());
 
     // Setup proxy servlet
     this.context =
-        new ServletContextHandler(proxyConnectHandler, "/", ServletContextHandler.SESSIONS);
+        new ServletContextHandler(handlers, "/", ServletContextHandler.SESSIONS);
     this.context.addServlet(proxyServlet, "/*");
+
     this.context.addFilter(RequestFilter.class, "/*", EnumSet.allOf(DispatcherType.class));
   }
 

proxyserver/src/main/java/com/lyft/data/proxyserver/ProxyServletImpl.java

@@ -46,6 +46,7 @@ protected HttpClient newHttpClient() {
     HttpClient httpClient = new HttpClient(sslFactory);
     httpClient.setMaxConnectionsPerDestination(10000);
     httpClient.setConnectTimeout(TimeUnit.SECONDS.toMillis(60));
+
     return httpClient;
   }