diff --git a/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java b/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java index 0ee4c42367..faba4a2604 100644 --- a/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java +++ b/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 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
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
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) { diff --git a/okhttp/src/main/java/io/grpc/okhttp/OkHttpClientTransport.java b/okhttp/src/main/java/io/grpc/okhttp/OkHttpClientTransport.java index deabff9f73..64d24ee70a 100644 --- a/okhttp/src/main/java/io/grpc/okhttp/OkHttpClientTransport.java +++ b/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 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
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
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) { diff --git a/okhttp/src/main/java/io/grpc/okhttp/OkHttpFrameLogger.java b/okhttp/src/main/java/io/grpc/okhttp/OkHttpFrameLogger.java new file mode 100644 index 0000000000..e54c101811 --- /dev/null +++ b/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 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
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
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; + } + } +} diff --git a/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java b/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java index 44d03bdacf..38d435fc61 100644 --- a/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java +++ b/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
()); + 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 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
()); + 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")); + + } } \ No newline at end of file diff --git a/okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java b/okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java index 082c544c82..654a2e0126 100644 --- a/okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java +++ b/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 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.