okhttp: make AsyncFrameWriter log quietly when socket is already closed. also, default log level down to INFO(closed) which is same as NettyServerTransport. (#4927)

2 files changed, 49 insertions, 1 deletions

diff --git a/okhttp/src/main/java/io/grpc/okhttp/AsyncFrameWriter.java b/okhttp/src/main/java/io/grpc/okhttp/AsyncFrameWriter.java
index 3049c5bd6..210aaa1f0 100644
--- a/okhttp/src/main/java/io/grpc/okhttp/AsyncFrameWriter.java
+++ b/okhttp/src/main/java/io/grpc/okhttp/AsyncFrameWriter.java
@@ -16,6 +16,7 @@
 
 package io.grpc.okhttp;
 
+import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Preconditions;
 import io.grpc.internal.SerializingExecutor;
 import io.grpc.okhttp.internal.framed.ErrorCode;
@@ -24,7 +25,11 @@ import io.grpc.okhttp.internal.framed.Header;
 import io.grpc.okhttp.internal.framed.Settings;
 import java.io.IOException;
 import java.net.Socket;
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.HashSet;
 import java.util.List;
+import java.util.Set;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.logging.Level;
 import java.util.logging.Logger;
@@ -39,6 +44,9 @@ class AsyncFrameWriter implements FrameWriter {
   private final SerializingExecutor executor;
   private final TransportExceptionHandler transportExceptionHandler;
   private final AtomicLong flushCounter = new AtomicLong();
+  // Some exceptions are not very useful and add too much noise to the log
+  private static final Set<String> QUIET_ERRORS =
+      Collections.unmodifiableSet(new HashSet<>(Arrays.asList("Socket closed")));
 
   public AsyncFrameWriter(
       TransportExceptionHandler transportExceptionHandler, SerializingExecutor executor) {
@@ -213,13 +221,28 @@ class AsyncFrameWriter implements FrameWriter {
             frameWriter.close();
             socket.close();
           } catch (IOException e) {
-            log.log(Level.WARNING, "Failed closing connection", e);
+            log.log(getLogLevel(e), "Failed closing connection", e);
           }
         }
       }
     });
   }
 
+  /**
+   * Accepts a throwable and returns the appropriate logging level. Uninteresting exceptions
+   * should not clutter the log.
+   */
+  @VisibleForTesting
+  static Level getLogLevel(Throwable t) {
+    if (t instanceof IOException
+        && t.getMessage() != null
+        && QUIET_ERRORS.contains(t.getMessage())) {
+      return Level.FINE;
+
+    }
+    return Level.INFO;
+  }
+
   private abstract class WriteRunnable implements Runnable {
     @Override
     public final void run() {
diff --git a/okhttp/src/test/java/io/grpc/okhttp/AsyncFrameWriterTest.java b/okhttp/src/test/java/io/grpc/okhttp/AsyncFrameWriterTest.java
index 3c435da4d..45e80707c 100644
--- a/okhttp/src/test/java/io/grpc/okhttp/AsyncFrameWriterTest.java
+++ b/okhttp/src/test/java/io/grpc/okhttp/AsyncFrameWriterTest.java
@@ -16,6 +16,8 @@
 
 package io.grpc.okhttp;
 
+import static com.google.common.truth.Truth.assertThat;
+import static io.grpc.okhttp.AsyncFrameWriter.getLogLevel;
 import static org.mockito.Matchers.anyBoolean;
 import static org.mockito.Matchers.anyInt;
 import static org.mockito.Mockito.inOrder;
@@ -30,6 +32,7 @@ import java.net.Socket;
 import java.util.Queue;
 import java.util.concurrent.ConcurrentLinkedQueue;
 import java.util.concurrent.Executor;
+import java.util.logging.Level;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
@@ -92,6 +95,28 @@ public class AsyncFrameWriterTest {
     inOrder.verify(frameWriter).flush();
   }
 
+  @Test
+  public void unknownException() {
+    assertThat(getLogLevel(new Exception())).isEqualTo(Level.INFO);
+  }
+
+  @Test
+  public void quiet() {
+    assertThat(getLogLevel(new IOException("Socket closed"))).isEqualTo(Level.FINE);
+  }
+
+  @Test
+  public void nonquiet() {
+    assertThat(getLogLevel(new IOException("foo"))).isEqualTo(Level.INFO);
+  }
+
+  @Test
+  public void nullMessage() {
+    IOException e = new IOException();
+    assertThat(e.getMessage()).isNull();
+    assertThat(getLogLevel(e)).isEqualTo(Level.INFO);
+  }
+
   /**
    * Executor queues incoming runnables instead of running it. Runnables can be invoked via {@link
    * QueueingExecutor#runAll} in serial order.