okhttp: add verbose logging for OkHttp HTTP/2 frame content (#5488)

* okhttp: add verbose logging for OkHttp HTTP/2 frames to include brief frame content.

* fix small details and typo issues

* fix branch condition (it's a typo) for logging the whole buffer

* remove redudent log level checking, always not log entire buffer

* convert ByteString to String to avoid printing 'hex=' prefix

* add test for OkHttpFrameLogger for inbound http frames

* refactor OkHttpFrameLogger's help method

* add Constructor for testing and missing logHeaders

* add http/2 framelogger test for outbound side

* use ArgumentMatchers instead of Matchers

* replace assertTrue with Truth.assertThat

* assert buffer log with exact length match instead of <=

okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java

@@ -33,10 +33,12 @@ import java.util.Set;
 import java.util.logging.Level;
 import java.util.logging.Logger;
 import okio.Buffer;
+import okio.ByteString;
 
 final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   private static final Logger log = Logger.getLogger(OkHttpClientTransport.class.getName());
+
   // 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")));
@@ -45,11 +47,23 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   private final FrameWriter frameWriter;
 
+  private final OkHttpFrameLogger frameLogger;
+
   ExceptionHandlingFrameWriter(
       TransportExceptionHandler transportExceptionHandler, FrameWriter frameWriter) {
+    this(transportExceptionHandler, frameWriter,
+        new OkHttpFrameLogger(Level.FINE, OkHttpClientTransport.class));
+  }
+
+  @VisibleForTesting
+  ExceptionHandlingFrameWriter(
+      TransportExceptionHandler transportExceptionHandler,
+      FrameWriter frameWriter,
+      OkHttpFrameLogger frameLogger) {
     this.transportExceptionHandler =
         checkNotNull(transportExceptionHandler, "transportExceptionHandler");
     this.frameWriter = Preconditions.checkNotNull(frameWriter, "frameWriter");
+    this.frameLogger = Preconditions.checkNotNull(frameLogger, "frameLogger");
   }
 
   @Override
@@ -63,6 +77,7 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void ackSettings(Settings peerSettings) {
+    frameLogger.logSettingsAck(OkHttpFrameLogger.Direction.OUTBOUND);
     try {
       frameWriter.ackSettings(peerSettings);
     } catch (IOException e) {
@@ -72,6 +87,8 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void pushPromise(int streamId, int promisedStreamId, List<Header> requestHeaders) {
+    frameLogger.logPushPromise(OkHttpFrameLogger.Direction.OUTBOUND,
+        streamId, promisedStreamId, requestHeaders);
     try {
       frameWriter.pushPromise(streamId, promisedStreamId, requestHeaders);
     } catch (IOException e) {
@@ -114,6 +131,7 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void headers(int streamId, List<Header> headerBlock) {
+    frameLogger.logHeaders(OkHttpFrameLogger.Direction.OUTBOUND, streamId, headerBlock, false);
     try {
       frameWriter.headers(streamId, headerBlock);
     } catch (IOException e) {
@@ -123,6 +141,7 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void rstStream(int streamId, ErrorCode errorCode) {
+    frameLogger.logRstStream(OkHttpFrameLogger.Direction.OUTBOUND, streamId, errorCode);
     try {
       frameWriter.rstStream(streamId, errorCode);
     } catch (IOException e) {
@@ -137,6 +156,8 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void data(boolean outFinished, int streamId, Buffer source, int byteCount) {
+    frameLogger.logData(OkHttpFrameLogger.Direction.OUTBOUND,
+        streamId, source.buffer(), byteCount, outFinished);
     try {
       frameWriter.data(outFinished, streamId, source, byteCount);
     } catch (IOException e) {
@@ -146,6 +167,7 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void settings(Settings okHttpSettings) {
+    frameLogger.logSettings(OkHttpFrameLogger.Direction.OUTBOUND, okHttpSettings);
     try {
       frameWriter.settings(okHttpSettings);
     } catch (IOException e) {
@@ -155,6 +177,8 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void ping(boolean ack, int payload1, int payload2) {
+    frameLogger.logPing(OkHttpFrameLogger.Direction.OUTBOUND,
+        ((long)payload1 << 32) | (payload2 & 0xFFFFFFFFL));
     try {
       frameWriter.ping(ack, payload1, payload2);
     } catch (IOException e) {
@@ -165,6 +189,8 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
   @Override
   public void goAway(int lastGoodStreamId, ErrorCode errorCode,
       byte[] debugData) {
+    frameLogger.logGoAway(OkHttpFrameLogger.Direction.OUTBOUND,
+        lastGoodStreamId, errorCode, ByteString.of(debugData));
     try {
       frameWriter.goAway(lastGoodStreamId, errorCode, debugData);
       // Flush it since after goAway, we are likely to close this writer.
@@ -176,6 +202,8 @@ final class ExceptionHandlingFrameWriter implements FrameWriter {
 
   @Override
   public void windowUpdate(int streamId, long windowSizeIncrement) {
+    frameLogger.logWindowsUpdate(OkHttpFrameLogger.Direction.OUTBOUND,
+        streamId, windowSizeIncrement);
     try {
       frameWriter.windowUpdate(streamId, windowSizeIncrement);
     } catch (IOException e) {

okhttp/src/main/java/io/grpc/okhttp/OkHttpClientTransport.java

@@ -145,6 +145,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
   private final int initialWindowSize;
   private Listener listener;
   private FrameReader testFrameReader;
+  private OkHttpFrameLogger testFrameLogger;
   @GuardedBy("lock")
   private ExceptionHandlingFrameWriter frameWriter;
   private OutboundFlowController outboundFlow;
@@ -272,6 +273,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
       Executor executor,
       FrameReader frameReader,
       FrameWriter testFrameWriter,
+      OkHttpFrameLogger testFrameLogger,
       int nextStreamId,
       Socket socket,
       Supplier<Stopwatch> stopwatchFactory,
@@ -291,6 +293,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
     this.socketFactory = SocketFactory.getDefault();
     this.testFrameReader = Preconditions.checkNotNull(frameReader, "frameReader");
     this.testFrameWriter = Preconditions.checkNotNull(testFrameWriter, "testFrameWriter");
+    this.testFrameLogger = Preconditions.checkNotNull(testFrameLogger, "testFrameLogger");
     this.socket = Preconditions.checkNotNull(socket, "socket");
     this.nextStreamId = nextStreamId;
     this.stopwatchFactory = stopwatchFactory;
@@ -468,7 +471,8 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
     }
     if (isForTest()) {
       synchronized (lock) {
-        frameWriter = new ExceptionHandlingFrameWriter(OkHttpClientTransport.this, testFrameWriter);
+        frameWriter = new ExceptionHandlingFrameWriter(OkHttpClientTransport.this, testFrameWriter,
+            testFrameLogger);
         outboundFlow =
             new OutboundFlowController(OkHttpClientTransport.this, frameWriter, initialWindowSize);
       }
@@ -478,7 +482,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
           if (connectingCallback != null) {
             connectingCallback.run();
           }
-          clientFrameHandler = new ClientFrameHandler(testFrameReader);
+          clientFrameHandler = new ClientFrameHandler(testFrameReader, testFrameLogger);
           executor.execute(clientFrameHandler);
           synchronized (lock) {
             maxConcurrentStreams = Integer.MAX_VALUE;
@@ -1028,11 +1032,19 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
    */
   @VisibleForTesting
   class ClientFrameHandler implements FrameReader.Handler, Runnable {
+
+    private final OkHttpFrameLogger logger;
     FrameReader frameReader;
     boolean firstSettings = true;
 
     ClientFrameHandler(FrameReader frameReader) {
+      this(frameReader, new OkHttpFrameLogger(Level.FINE, OkHttpClientTransport.class));
+    }
+
+    @VisibleForTesting
+    ClientFrameHandler(FrameReader frameReader, OkHttpFrameLogger frameLogger) {
       this.frameReader = frameReader;
+      logger = frameLogger;
     }
 
     @Override
@@ -1079,6 +1091,8 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
     @Override
     public void data(boolean inFinished, int streamId, BufferedSource in, int length)
         throws IOException {
+      logger.logData(OkHttpFrameLogger.Direction.INBOUND,
+          streamId, in.buffer(), length, inFinished);
       OkHttpClientStream stream = getStream(streamId);
       if (stream == null) {
         if (mayHaveCreatedStream(streamId)) {
@@ -1121,6 +1135,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
         int associatedStreamId,
         List<Header> headerBlock,
         HeadersMode headersMode) {
+      logger.logHeaders(OkHttpFrameLogger.Direction.INBOUND, streamId, headerBlock, inFinished);
       boolean unknownStream = false;
       Status failedStatus = null;
       if (maxInboundMetadataSize != Integer.MAX_VALUE) {
@@ -1172,6 +1187,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
 
     @Override
     public void rstStream(int streamId, ErrorCode errorCode) {
+      logger.logRstStream(OkHttpFrameLogger.Direction.INBOUND, streamId, errorCode);
       Status status = toGrpcStatus(errorCode).augmentDescription("Rst Stream");
       boolean stopDelivery =
           (status.getCode() == Code.CANCELLED || status.getCode() == Code.DEADLINE_EXCEEDED);
@@ -1183,6 +1199,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
 
     @Override
     public void settings(boolean clearPrevious, Settings settings) {
+      logger.logSettings(OkHttpFrameLogger.Direction.INBOUND, settings);
       boolean outboundWindowSizeIncreased = false;
       synchronized (lock) {
         if (OkHttpSettingsUtil.isSet(settings, OkHttpSettingsUtil.MAX_CONCURRENT_STREAMS)) {
@@ -1216,13 +1233,14 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
 
     @Override
     public void ping(boolean ack, int payload1, int payload2) {
+      long ackPayload = (((long) payload1) << 32) | (payload2 & 0xffffffffL);
+      logger.logPing(OkHttpFrameLogger.Direction.INBOUND, ackPayload);
       if (!ack) {
         synchronized (lock) {
           frameWriter.ping(true, payload1, payload2);
         }
       } else {
         Http2Ping p = null;
-        long ackPayload = (((long) payload1) << 32) | (payload2 & 0xffffffffL);
         synchronized (lock) {
           if (ping != null) {
             if (ping.payload() == ackPayload) {
@@ -1250,6 +1268,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
 
     @Override
     public void goAway(int lastGoodStreamId, ErrorCode errorCode, ByteString debugData) {
+      logger.logGoAway(OkHttpFrameLogger.Direction.INBOUND, lastGoodStreamId, errorCode, debugData);
       if (errorCode == ErrorCode.ENHANCE_YOUR_CALM) {
         String data = debugData.utf8();
         log.log(Level.WARNING, String.format(
@@ -1270,6 +1289,8 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
     @Override
     public void pushPromise(int streamId, int promisedStreamId, List<Header> requestHeaders)
         throws IOException {
+      logger.logPushPromise(OkHttpFrameLogger.Direction.INBOUND,
+          streamId, promisedStreamId, requestHeaders);
       // We don't accept server initiated stream.
       synchronized (lock) {
         frameWriter.rstStream(streamId, ErrorCode.PROTOCOL_ERROR);
@@ -1278,6 +1299,7 @@ class OkHttpClientTransport implements ConnectionClientTransport, TransportExcep
 
     @Override
     public void windowUpdate(int streamId, long delta) {
+      logger.logWindowsUpdate(OkHttpFrameLogger.Direction.INBOUND, streamId, delta);
       if (delta == 0) {
         String errorMsg = "Received 0 flow control window increment.";
         if (streamId == 0) {

okhttp/src/main/java/io/grpc/okhttp/OkHttpFrameLogger.java

@@ -0,0 +1,218 @@
+/*
+ * Copyright 2019 The gRPC Authors
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package io.grpc.okhttp;
+
+import static com.google.common.base.Preconditions.checkNotNull;
+
+import com.google.common.annotations.VisibleForTesting;
+import io.grpc.okhttp.internal.framed.ErrorCode;
+import io.grpc.okhttp.internal.framed.Header;
+import io.grpc.okhttp.internal.framed.Settings;
+import java.util.EnumMap;
+import java.util.List;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+import okio.Buffer;
+import okio.ByteString;
+
+class OkHttpFrameLogger {
+  private static final int BUFFER_LENGTH_THRESHOLD = 64;
+  private final Logger logger;
+  private final Level level;
+
+  OkHttpFrameLogger(Level level, Class<?> clazz) {
+    this(level, Logger.getLogger(clazz.getName()));
+  }
+
+  @VisibleForTesting
+  OkHttpFrameLogger(Level level, Logger logger) {
+    this.level = checkNotNull(level, "level");
+    this.logger = checkNotNull(logger, "logger");
+  }
+
+  private static String toString(Settings settings) {
+    EnumMap<SettingParams, Integer> map = new EnumMap<>(SettingParams.class);
+    for (SettingParams p : SettingParams.values()) {
+      // Only log set parameters.
+      if (settings.isSet(p.getBit())) {
+        map.put(p, settings.get(p.getBit()));
+      }
+    }
+    return map.toString();
+  }
+
+  private static String toString(Buffer buf) {
+    if (buf.size() <= BUFFER_LENGTH_THRESHOLD) {
+      // Log the entire buffer.
+      return buf.snapshot().hex();
+    }
+
+    // Otherwise just log the first 64 bytes.
+    int length = (int) Math.min(buf.size(), BUFFER_LENGTH_THRESHOLD);
+    return buf.snapshot(length).hex() + "...";
+  }
+
+  private boolean isEnabled() {
+    return logger.isLoggable(level);
+  }
+
+  void logData(Direction direction, int streamId, Buffer data, int length, boolean endStream) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " DATA: streamId="
+              + streamId
+              + " endStream="
+              + endStream
+              + " length="
+              + length
+              + " bytes="
+              + toString(data));
+    }
+  }
+
+  void logHeaders(Direction direction, int streamId, List<Header> headers, boolean endStream) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " HEADERS: streamId="
+              + streamId
+              + " headers="
+              + headers
+              + " endStream="
+              + endStream);
+    }
+  }
+
+  public void logPriority(
+      Direction direction, int streamId, int streamDependency, int weight, boolean exclusive) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " PRIORITY: streamId="
+              + streamId
+              + " streamDependency="
+              + streamDependency
+              + " weight="
+              + weight
+              + " exclusive="
+              + exclusive);
+    }
+  }
+
+  void logRstStream(Direction direction, int streamId, ErrorCode errorCode) {
+    if (isEnabled()) {
+      logger.log(
+          level, direction + " RST_STREAM: streamId=" + streamId + " errorCode=" + errorCode);
+    }
+  }
+
+  void logSettingsAck(Direction direction) {
+    if (isEnabled()) {
+      logger.log(level, direction + " SETTINGS: ack=true");
+    }
+  }
+
+  void logSettings(Direction direction, Settings settings) {
+    if (isEnabled()) {
+      logger.log(level, direction + " SETTINGS: ack=false settings=" + toString(settings));
+    }
+  }
+
+  void logPing(Direction direction, long data) {
+    if (isEnabled()) {
+      logger.log(level, direction + " PING: ack=false bytes=" + data);
+    }
+  }
+
+  void logPingAck(Direction direction, long data) {
+    if (isEnabled()) {
+      logger.log(level, direction + " PING: ack=true bytes=" + data);
+    }
+  }
+
+  void logPushPromise(
+      Direction direction, int streamId, int promisedStreamId, List<Header> headers) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " PUSH_PROMISE: streamId="
+              + streamId
+              + " promisedStreamId="
+              + promisedStreamId
+              + " headers="
+              + headers);
+    }
+  }
+
+  void logGoAway(Direction direction, int lastStreamId, ErrorCode errorCode, ByteString debugData) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " GO_AWAY: lastStreamId="
+              + lastStreamId
+              + " errorCode="
+              + errorCode
+              + " length="
+              + debugData.size()
+              + " bytes="
+              + toString(new Buffer().write(debugData)));
+    }
+  }
+
+  void logWindowsUpdate(Direction direction, int streamId, long windowSizeIncrement) {
+    if (isEnabled()) {
+      logger.log(
+          level,
+          direction
+              + " WINDOW_UPDATE: streamId="
+              + streamId
+              + " windowSizeIncrement="
+              + windowSizeIncrement);
+    }
+  }
+
+  enum Direction {
+    INBOUND,
+    OUTBOUND
+  }
+
+  // Note the set bits in OkHttp's Settings are different from HTTP2 Specifications.
+  private enum SettingParams {
+    HEADER_TABLE_SIZE(1),
+    ENABLE_PUSH(2),
+    MAX_CONCURRENT_STREAMS(4),
+    MAX_FRAME_SIZE(5),
+    MAX_HEADER_LIST_SIZE(6),
+    INITIAL_WINDOW_SIZE(7);
+
+    private final int bit;
+
+    SettingParams(int bit) {
+      this.bit = bit;
+    }
+
+    public int getBit() {
+      return this.bit;
+    }
+  }
+}

okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java

@@ -16,21 +16,33 @@
 
 package io.grpc.okhttp;
 
+import static com.google.common.base.Charsets.UTF_8;
 import static com.google.common.truth.Truth.assertThat;
 import static io.grpc.okhttp.ExceptionHandlingFrameWriter.getLogLevel;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.ArgumentMatchers.startsWith;
+import static org.mockito.Mockito.atLeastOnce;
 import static org.mockito.Mockito.doThrow;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.when;
 
 import io.grpc.okhttp.ExceptionHandlingFrameWriter.TransportExceptionHandler;
+import io.grpc.okhttp.OkHttpFrameLogger.Direction;
+import io.grpc.okhttp.internal.framed.ErrorCode;
 import io.grpc.okhttp.internal.framed.FrameWriter;
 import io.grpc.okhttp.internal.framed.Header;
+import io.grpc.okhttp.internal.framed.Settings;
 import java.io.IOException;
 import java.util.ArrayList;
 import java.util.logging.Level;
+import java.util.logging.Logger;
+import okio.Buffer;
+import okio.ByteString;
 import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.junit.runners.JUnit4;
+import org.mockito.ArgumentCaptor;
 
 @RunWith(JUnit4.class)
 public class ExceptionHandlingFrameWriterTest {
@@ -38,8 +50,10 @@ public class ExceptionHandlingFrameWriterTest {
   private final FrameWriter mockedFrameWriter = mock(FrameWriter.class);
   private final TransportExceptionHandler transportExceptionHandler =
       mock(TransportExceptionHandler.class);
+  private final Logger log = mock(Logger.class);
   private final ExceptionHandlingFrameWriter exceptionHandlingFrameWriter =
-      new ExceptionHandlingFrameWriter(transportExceptionHandler, mockedFrameWriter);
+      new ExceptionHandlingFrameWriter(transportExceptionHandler, mockedFrameWriter,
+          new OkHttpFrameLogger(Level.FINE, log));
 
   @Test
   public void exception() throws IOException {
@@ -74,4 +88,64 @@ public class ExceptionHandlingFrameWriterTest {
     assertThat(e.getMessage()).isNull();
     assertThat(getLogLevel(e)).isEqualTo(Level.INFO);
   }
+
+  private static Buffer createMessageFrame(String message) {
+    return createMessageFrame(message.getBytes(UTF_8));
+  }
+
+  private static Buffer createMessageFrame(byte[] message) {
+    Buffer buffer = new Buffer();
+    buffer.writeByte(0 /* UNCOMPRESSED */);
+    buffer.writeInt(message.length);
+    buffer.write(message);
+    return buffer;
+  }
+
+  /**
+   * Test logging is functioning correctly for client sent Http/2 frames. Not intended to test
+   * actual frame content being logged.
+   */
+  @Test
+  public void testFrameLogger() {
+    when(log.isLoggable(any(Level.class))).thenReturn(true);
+
+    exceptionHandlingFrameWriter.headers(100, new ArrayList<Header>());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " HEADERS: streamId=" + 100));
+
+    final String message = "Hello Server";
+    Buffer buffer = createMessageFrame(message);
+    exceptionHandlingFrameWriter.data(false, 100, buffer, (int) buffer.size());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " DATA: streamId=" + 100));
+
+    // At most 64 bytes of data frame will be logged.
+    exceptionHandlingFrameWriter
+        .data(false, 3, createMessageFrame(new String(new char[1000])), 1000);
+    ArgumentCaptor<String> logCaptor = ArgumentCaptor.forClass(String.class);
+    verify(log, atLeastOnce()).log(any(Level.class), logCaptor.capture());
+    String data = logCaptor.getValue();
+    assertThat(data).endsWith("...");
+    assertThat(data.substring(data.indexOf("bytes="), data.indexOf("..."))).hasLength(64 * 2 + 6);
+
+    exceptionHandlingFrameWriter.ackSettings(new Settings());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " SETTINGS: ack=true"));
+
+    exceptionHandlingFrameWriter.settings(new Settings());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " SETTINGS: ack=false"));
+
+    exceptionHandlingFrameWriter.ping(false, 0, 0);
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " PING: ack=false"));
+
+    exceptionHandlingFrameWriter.pushPromise(100, 100, new ArrayList<Header>());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " PUSH_PROMISE"));
+
+    exceptionHandlingFrameWriter.rstStream(100, ErrorCode.CANCEL);
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " RST_STREAM"));
+
+    exceptionHandlingFrameWriter.goAway(100, ErrorCode.CANCEL, ByteString.EMPTY.toByteArray());
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " GO_AWAY"));
+
+    exceptionHandlingFrameWriter.windowUpdate(100, 32);
+    verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " WINDOW_UPDATE"));
+
+  }
 }

okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java

@@ -38,6 +38,8 @@ import static org.mockito.ArgumentMatchers.anyInt;
 import static org.mockito.ArgumentMatchers.eq;
 import static org.mockito.ArgumentMatchers.isA;
 import static org.mockito.ArgumentMatchers.same;
+import static org.mockito.ArgumentMatchers.startsWith;
+import static org.mockito.Mockito.atLeastOnce;
 import static org.mockito.Mockito.inOrder;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.never;
@@ -46,6 +48,7 @@ import static org.mockito.Mockito.timeout;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
 import static org.mockito.Mockito.verifyZeroInteractions;
+import static org.mockito.Mockito.when;
 
 import com.google.common.base.Stopwatch;
 import com.google.common.base.Supplier;
@@ -74,6 +77,7 @@ import io.grpc.internal.GrpcUtil;
 import io.grpc.internal.ManagedClientTransport;
 import io.grpc.internal.TransportTracer;
 import io.grpc.okhttp.OkHttpClientTransport.ClientFrameHandler;
+import io.grpc.okhttp.OkHttpFrameLogger.Direction;
 import io.grpc.okhttp.internal.ConnectionSpec;
 import io.grpc.okhttp.internal.framed.ErrorCode;
 import io.grpc.okhttp.internal.framed.FrameReader;
@@ -104,6 +108,8 @@ import java.util.concurrent.Executors;
 import java.util.concurrent.LinkedBlockingQueue;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.logging.Level;
+import java.util.logging.Logger;
 import javax.annotation.Nullable;
 import javax.net.SocketFactory;
 import javax.net.ssl.HostnameVerifier;
@@ -149,6 +155,8 @@ public class OkHttpClientTransportTest {
 
   @Mock
   private ManagedClientTransport.Listener transportListener;
+  @Mock
+  private Logger log;
 
   private final SocketFactory socketFactory = null;
   private final SSLSocketFactory sslSocketFactory = null;
@@ -224,6 +232,7 @@ public class OkHttpClientTransportTest {
         executor,
         frameReader,
         frameWriter,
+        new OkHttpFrameLogger(Level.FINE, log),
         startId,
         socket,
         stopwatchSupplier,
@@ -263,6 +272,50 @@ public class OkHttpClientTransportTest {
     assertTrue("Unexpected: " + s, s.contains(address.toString()));
   }
 
+  /**
+   * Test logging is functioning correctly for client received Http/2 frames. Not intended to test
+   * actual frame content being logged.
+   */
+  @Test
+  public void testClientHandlerFrameLogger() throws Exception {
+    initTransport();
+
+    when(log.isLoggable(any(Level.class))).thenReturn(true);
+    frameHandler().headers(false, false, 3, 0, grpcResponseHeaders(), HeadersMode.HTTP_20_HEADERS);
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " HEADERS: streamId=" + 3));
+
+    final String message = "Hello Client";
+    Buffer buffer = createMessageFrame(message);
+    frameHandler().data(false, 3, buffer, (int) buffer.size());
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " DATA: streamId=" + 3));
+
+    // At most 64 bytes of data frame will be logged.
+    frameHandler().data(false, 3, createMessageFrame(new String(new char[1000])), 1000);
+    ArgumentCaptor<String> logCaptor = ArgumentCaptor.forClass(String.class);
+    verify(log, atLeastOnce()).log(any(Level.class), logCaptor.capture());
+    String data = logCaptor.getValue();
+    assertThat(data).endsWith("...");
+    assertThat(data.substring(data.indexOf("bytes="), data.indexOf("..."))).hasLength(64 * 2 + 6);
+
+    frameHandler().settings(false, new Settings());
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " SETTINGS: ack=false"));
+
+    frameHandler().ping(false, 0, 0);
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " PING: ack=false"));
+
+    frameHandler().pushPromise(3, 3, grpcResponseHeaders());
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " PUSH_PROMISE"));
+
+    frameHandler().rstStream(3, ErrorCode.CANCEL);
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " RST_STREAM"));
+
+    frameHandler().goAway(3, ErrorCode.CANCEL, ByteString.EMPTY);
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " GO_AWAY"));
+
+    frameHandler().windowUpdate(3, 32);
+    verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " WINDOW_UPDATE"));
+  }
+
   @Test
   public void maxMessageSizeShouldBeEnforced() throws Exception {
     // Allow the response payloads of up to 1 byte.