From 6810e959f9d1e15b197e65c6b7d4a8cc7d09d0a1 Mon Sep 17 00:00:00 2001
From: jianglai <jianglai@google.com>
Date: Mon, 6 Aug 2018 10:02:41 -0700
Subject: [PATCH] Refine logs in the proxy

[1] All logs should contain a reference to the channel so that it is easy to search for logs about a specific channel.

[2] EPP ssl handshake failure should be logged at warning. It is mostly the client that failed to complete the handshake, for example by sending bad cert, or not sending cert, or not using the correct SSL version. We should not lot it at error and spam the log.

[3] When the EPP response is not 200, we should not log at error because it means that the GAE app responded successfully. For example when datastore contention occurs, app engine responds with a non-200 status and logs at warning. The proxy should not at a higher level than app engine itself.

[4] Timeout is a non-fatal error that should be logged at warning.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=207562299
---
 .../proxy/handler/EppServiceHandler.java        |  2 +-
 .../proxy/handler/HttpsRelayServiceHandler.java | 17 ++++++++++++++---
 .../proxy/handler/ProxyProtocolHandler.java     | 14 +++++++++-----
 3 files changed, 24 insertions(+), 9 deletions(-)

diff --git a/java/google/registry/proxy/handler/EppServiceHandler.java b/java/google/registry/proxy/handler/EppServiceHandler.java
index 15b6f9a06..7c57f5251 100644
--- a/java/google/registry/proxy/handler/EppServiceHandler.java
+++ b/java/google/registry/proxy/handler/EppServiceHandler.java
@@ -118,7 +118,7 @@ public class EppServiceHandler extends HttpsRelayServiceHandler {
                         "epp", sslClientCertificateHash, ctx.channel());
                     channelRead(ctx, Unpooled.wrappedBuffer(helloBytes));
                   } else {
-                    logger.atSevere().withCause(promise.cause()).log(
+                    logger.atWarning().withCause(promise.cause()).log(
                         "Cannot finish handshake for channel %s", ctx.channel());
                     ChannelFuture unusedFuture = ctx.close();
                   }
diff --git a/java/google/registry/proxy/handler/HttpsRelayServiceHandler.java b/java/google/registry/proxy/handler/HttpsRelayServiceHandler.java
index 4e6974aff..6de1e8670 100644
--- a/java/google/registry/proxy/handler/HttpsRelayServiceHandler.java
+++ b/java/google/registry/proxy/handler/HttpsRelayServiceHandler.java
@@ -34,6 +34,7 @@ import io.netty.handler.codec.http.HttpVersion;
 import io.netty.handler.codec.http.cookie.ClientCookieDecoder;
 import io.netty.handler.codec.http.cookie.ClientCookieEncoder;
 import io.netty.handler.codec.http.cookie.Cookie;
+import io.netty.handler.timeout.ReadTimeoutException;
 import java.util.LinkedHashMap;
 import java.util.List;
 import java.util.Map;
@@ -152,8 +153,9 @@ abstract class HttpsRelayServiceHandler extends ByteToMessageCodec<FullHttpRespo
       throws Exception {
     checkArgument(
         response.status().equals(HttpResponseStatus.OK),
-        "Cannot relay HTTP response status \"%s\"\n%s",
+        "Cannot relay HTTP response status \"%s\"in channel %s:\n%s",
         response.status(),
+        ctx.channel(),
         response.content().toString(UTF_8));
     saveCookies(response);
     byteBuf.writeBytes(encodeFullHttpResponse(response));
@@ -162,8 +164,17 @@ abstract class HttpsRelayServiceHandler extends ByteToMessageCodec<FullHttpRespo
   /** Terminates connection upon inbound exception. */
   @Override
   public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception {
-    logger.atSevere().withCause(cause).log(
-        "Inbound exception caught for channel %s", ctx.channel());
+    // ReadTimeoutException is non fatal as the client times out due to inactivity.
+    // IllegalArgumentException is thrown by the checkArgument in the #encode command, it just means
+    // that GAE returns a non-200 response and the connection should be killed. The request is still
+    // processed by GAE, so this is not an unexpected behavior.
+    if (cause instanceof ReadTimeoutException || cause instanceof IllegalArgumentException) {
+      logger.atWarning().withCause(cause).log(
+          "Inbound exception caught for channel %s", ctx.channel());
+    } else {
+      logger.atSevere().withCause(cause).log(
+          "Inbound exception caught for channel %s", ctx.channel());
+    }
     ChannelFuture unusedFuture = ctx.close();
   }
 
diff --git a/java/google/registry/proxy/handler/ProxyProtocolHandler.java b/java/google/registry/proxy/handler/ProxyProtocolHandler.java
index 0433eb6ef..f86760658 100644
--- a/java/google/registry/proxy/handler/ProxyProtocolHandler.java
+++ b/java/google/registry/proxy/handler/ProxyProtocolHandler.java
@@ -75,23 +75,27 @@ public class ProxyProtocolHandler extends ByteToMessageDecoder {
       String remoteIP;
       if (proxyHeader != null) {
         logger.atFine().log("PROXIED CONNECTION: %s", ctx.channel());
-        logger.atFine().log("PROXY HEADER: %s", proxyHeader);
+        logger.atFine().log("PROXY HEADER for channel %s: %s", ctx.channel(), proxyHeader);
         String[] headerArray = proxyHeader.split(" ", -1);
         if (headerArray.length == 6) {
           remoteIP = headerArray[2];
-          logger.atFine().log("Header parsed, using %s as remote IP.", remoteIP);
+          logger.atFine().log(
+              "Header parsed, using %s as remote IP for channel %s", remoteIP, ctx.channel());
         } else {
-          logger.atFine().log("Cannot parse the header, using source IP as a last resort.");
+          logger.atFine().log(
+              "Cannot parse the header, using source IP as remote IP for channel %s",
+              ctx.channel());
           remoteIP = getSourceIP(ctx);
         }
       } else {
-        logger.atFine().log("No header present, using source IP directly.");
+        logger.atFine().log(
+            "No header present, using source IP directly for channel %s", ctx.channel());
         remoteIP = getSourceIP(ctx);
       }
       if (remoteIP != null) {
         ctx.channel().attr(REMOTE_ADDRESS_KEY).set(remoteIP);
       } else {
-        logger.atWarning().log("Not able to obtain remote IP for %s", ctx.channel());
+        logger.atWarning().log("Not able to obtain remote IP for channel %s", ctx.channel());
       }
       // ByteToMessageDecoder automatically flushes unread bytes in the ByteBuf to the next handler
       // when itself is being removed.