From 74527dcee9bf037d76f635de24dbe0553bf76217 Mon Sep 17 00:00:00 2001 From: Chengyuan Zhang Date: Mon, 8 Apr 2019 18:06:25 -0700 Subject: [PATCH] okhttp: fix OkhttpFrameLogger mocking tests failure (#5565) * use LogRecord to verify OkHttpFrameLogger in OkHttpClientTransportTest * use LogRecord to test OkHttpFrameLogger in ExceptionHandlingFrameWriterTest --- .../okhttp/ExceptionHandlingFrameWriter.java | 9 +- .../ExceptionHandlingFrameWriterTest.java | 82 +++++++++++---- .../okhttp/OkHttpClientTransportTest.java | 99 +++++++++++++++---- 3 files changed, 150 insertions(+), 40 deletions(-) diff --git a/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java b/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java index faba4a2604..93a4c740e8 100644 --- a/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java +++ b/okhttp/src/main/java/io/grpc/okhttp/ExceptionHandlingFrameWriter.java @@ -177,8 +177,13 @@ 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)); + if (ack) { + frameLogger.logPingAck(OkHttpFrameLogger.Direction.OUTBOUND, + ((long) payload1 << 32) | (payload2 & 0xFFFFFFFFL)); + } else { + frameLogger.logPing(OkHttpFrameLogger.Direction.OUTBOUND, + ((long) payload1 << 32) | (payload2 & 0xFFFFFFFFL)); + } try { frameWriter.ping(ack, payload1, payload2); } catch (IOException e) { diff --git a/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java b/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java index 38d435fc61..27e3c0fc3f 100644 --- a/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java +++ b/okhttp/src/test/java/io/grpc/okhttp/ExceptionHandlingFrameWriterTest.java @@ -19,13 +19,9 @@ 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; @@ -35,25 +31,27 @@ 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.List; +import java.util.logging.Handler; import java.util.logging.Level; +import java.util.logging.LogRecord; 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 { + private static final Logger logger = Logger.getLogger(OkHttpClientTransport.class.getName()); 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 OkHttpFrameLogger(Level.FINE, log)); + new OkHttpFrameLogger(Level.FINE, logger)); @Test public void exception() throws IOException { @@ -107,45 +105,89 @@ public class ExceptionHandlingFrameWriterTest { */ @Test public void testFrameLogger() { - when(log.isLoggable(any(Level.class))).thenReturn(true); + final List logs = new ArrayList<>(); + Handler handler = new Handler() { + @Override + public void publish(LogRecord record) { + logs.add(record); + } + + @Override + public void flush() { + } + + @Override + public void close() throws SecurityException { + } + }; + logger.addHandler(handler); + logger.setLevel(Level.ALL); exceptionHandlingFrameWriter.headers(100, new ArrayList
()); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " HEADERS: streamId=" + 100)); + assertThat(logs).hasSize(1); + LogRecord log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " HEADERS: streamId=" + 100); + assertThat(log.getLevel()).isEqualTo(Level.FINE); 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)); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " DATA: streamId=" + 100); + assertThat(log.getLevel()).isEqualTo(Level.FINE); // 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(logs).hasSize(1); + log = logs.remove(0); + String data = log.getMessage(); 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")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " SETTINGS: ack=true"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.settings(new Settings()); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " SETTINGS: ack=false")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " SETTINGS: ack=false"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.ping(false, 0, 0); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " PING: ack=false")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " PING: ack=false"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.pushPromise(100, 100, new ArrayList
()); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " PUSH_PROMISE")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " PUSH_PROMISE"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.rstStream(100, ErrorCode.CANCEL); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " RST_STREAM")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " RST_STREAM"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.goAway(100, ErrorCode.CANCEL, ByteString.EMPTY.toByteArray()); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " GO_AWAY")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " GO_AWAY"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); exceptionHandlingFrameWriter.windowUpdate(100, 32); - verify(log).log(any(Level.class), startsWith(Direction.OUTBOUND + " WINDOW_UPDATE")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " WINDOW_UPDATE"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + logger.removeHandler(handler); } } \ 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 654a2e0126..4c5fb21ff7 100644 --- a/okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java +++ b/okhttp/src/test/java/io/grpc/okhttp/OkHttpClientTransportTest.java @@ -38,8 +38,6 @@ 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; @@ -48,7 +46,6 @@ 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; @@ -108,7 +105,9 @@ 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.Handler; import java.util.logging.Level; +import java.util.logging.LogRecord; import java.util.logging.Logger; import javax.annotation.Nullable; import javax.net.SocketFactory; @@ -146,6 +145,7 @@ public class OkHttpClientTransportTest { private static final int DEFAULT_START_STREAM_ID = 3; private static final int DEFAULT_MAX_INBOUND_METADATA_SIZE = Integer.MAX_VALUE; private static final Attributes EAG_ATTRS = Attributes.EMPTY; + private static final Logger logger = Logger.getLogger(OkHttpClientTransport.class.getName()); @Rule public final Timeout globalTimeout = Timeout.seconds(10); @@ -155,8 +155,6 @@ public class OkHttpClientTransportTest { @Mock private ManagedClientTransport.Listener transportListener; - @Mock - private Logger log; private final SocketFactory socketFactory = null; private final SSLSocketFactory sslSocketFactory = null; @@ -232,7 +230,7 @@ public class OkHttpClientTransportTest { executor, frameReader, frameWriter, - new OkHttpFrameLogger(Level.FINE, log), + new OkHttpFrameLogger(Level.FINE, logger), startId, socket, stopwatchSupplier, @@ -278,42 +276,107 @@ public class OkHttpClientTransportTest { */ @Test public void testClientHandlerFrameLogger() throws Exception { + final List logs = new ArrayList<>(); + Handler handler = new Handler() { + @Override + public void publish(LogRecord record) { + logs.add(record); + } + + @Override + public void flush() { + } + + @Override + public void close() throws SecurityException { + } + }; + logger.addHandler(handler); + logger.setLevel(Level.ALL); + initTransport(); - when(log.isLoggable(any(Level.class))).thenReturn(true); + MockStreamListener listener = new MockStreamListener(); + OkHttpClientStream stream = + clientTransport.newStream(method, new Metadata(), CallOptions.DEFAULT); + stream.start(listener); + stream.request(1); + frameHandler().headers(false, false, 3, 0, grpcResponseHeaders(), HeadersMode.HTTP_20_HEADERS); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " HEADERS: streamId=" + 3)); + assertThat(logs).hasSize(1); + LogRecord log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " HEADERS: streamId=" + 3); + assertThat(log.getLevel()).isEqualTo(Level.FINE); 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)); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " DATA: streamId=" + 3); + assertThat(log.getLevel()).isEqualTo(Level.FINE); // 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(logs).hasSize(1); + log = logs.remove(0); + String data = log.getMessage(); assertThat(data).endsWith("..."); assertThat(data.substring(data.indexOf("bytes="), data.indexOf("..."))).hasLength(64 * 2 + 6); + // A SETTINGS ACK frame is sent out after receiving SETTINGS frame. frameHandler().settings(false, new Settings()); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " SETTINGS: ack=false")); + assertThat(logs).hasSize(2); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " SETTINGS: ack=false"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " SETTINGS: ack=true"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + // A PING ACK frame is sent out after receiving PING frame. frameHandler().ping(false, 0, 0); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " PING: ack=false")); + assertThat(logs).hasSize(2); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " PING: ack=false"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " PING: ack=true"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + // As server push is not supported, a RST_STREAM is sent out after receiving PUSH_PROMISE frame. frameHandler().pushPromise(3, 3, grpcResponseHeaders()); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " PUSH_PROMISE")); + assertThat(logs).hasSize(2); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " PUSH_PROMISE"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " RST_STREAM"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); frameHandler().rstStream(3, ErrorCode.CANCEL); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " RST_STREAM")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " RST_STREAM"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + // Outbound GO_AWAY is responded after receiving inbound GO_AWAY frame. frameHandler().goAway(3, ErrorCode.CANCEL, ByteString.EMPTY); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " GO_AWAY")); + assertThat(logs).hasSize(2); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " GO_AWAY"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.OUTBOUND + " GO_AWAY"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); frameHandler().windowUpdate(3, 32); - verify(log).log(any(Level.class), startsWith(Direction.INBOUND + " WINDOW_UPDATE")); + assertThat(logs).hasSize(1); + log = logs.remove(0); + assertThat(log.getMessage()).startsWith(Direction.INBOUND + " WINDOW_UPDATE"); + assertThat(log.getLevel()).isEqualTo(Level.FINE); + + logger.removeHandler(handler); } @Test