From a6c4ff6e44d2fbd4e44bd523c4ffd3529612a86b Mon Sep 17 00:00:00 2001 From: Yuri Schimke Date: Tue, 16 Jul 2019 22:34:32 +0100 Subject: [PATCH] Output client events after tagged @Flaky tests or failures (#5217) Collect additional debugging info for know problem tests or after unplanned failures. --- .../java/okhttp3/ClientRuleEventListener.kt | 135 ++++++++++++++++++ .../main/java/okhttp3/OkHttpClientTestRule.kt | 44 +++++- .../src/main/java/okhttp3/testing/Flaky.kt | 24 ++++ .../okhttp3/ConnectionCoalescingTest.java | 1 - .../test/java/okhttp3/URLConnectionTest.java | 11 +- .../internal/http2/HttpOverHttp2Test.java | 5 + .../internal/ws/WebSocketHttpTest.java | 19 +-- 7 files changed, 221 insertions(+), 18 deletions(-) create mode 100644 okhttp-testing-support/src/main/java/okhttp3/ClientRuleEventListener.kt create mode 100644 okhttp-testing-support/src/main/java/okhttp3/testing/Flaky.kt diff --git a/okhttp-testing-support/src/main/java/okhttp3/ClientRuleEventListener.kt b/okhttp-testing-support/src/main/java/okhttp3/ClientRuleEventListener.kt new file mode 100644 index 000000000..26fe43c16 --- /dev/null +++ b/okhttp-testing-support/src/main/java/okhttp3/ClientRuleEventListener.kt @@ -0,0 +1,135 @@ +/* + * Copyright (C) 2018 Square, Inc. + * + * 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 okhttp3 + +import java.io.IOException +import java.net.InetAddress +import java.net.InetSocketAddress +import java.net.Proxy +import java.util.concurrent.TimeUnit + +class ClientRuleEventListener(var logger: (String) -> Unit) : EventListener(), + EventListener.Factory { + private var startNs: Long = 0 + + override fun create(call: Call): EventListener = this + + override fun callStart(call: Call) { + startNs = System.nanoTime() + + logWithTime("callStart: ${call.request()}") + } + + override fun dnsStart(call: Call, domainName: String) { + logWithTime("dnsStart: $domainName") + } + + override fun dnsEnd(call: Call, domainName: String, inetAddressList: List) { + logWithTime("dnsEnd: $inetAddressList") + } + + override fun connectStart(call: Call, inetSocketAddress: InetSocketAddress, proxy: Proxy) { + logWithTime("connectStart: $inetSocketAddress $proxy") + } + + override fun secureConnectStart(call: Call) { + logWithTime("secureConnectStart") + } + + override fun secureConnectEnd(call: Call, handshake: Handshake?) { + logWithTime("secureConnectEnd: $handshake") + } + + override fun connectEnd( + call: Call, + inetSocketAddress: InetSocketAddress, + proxy: Proxy, + protocol: Protocol? + ) { + logWithTime("connectEnd: $protocol") + } + + override fun connectFailed( + call: Call, + inetSocketAddress: InetSocketAddress, + proxy: Proxy, + protocol: Protocol?, + ioe: IOException + ) { + logWithTime("connectFailed: $protocol $ioe") + } + + override fun connectionAcquired(call: Call, connection: Connection) { + logWithTime("connectionAcquired: $connection") + } + + override fun connectionReleased(call: Call, connection: Connection) { + logWithTime("connectionReleased") + } + + override fun requestHeadersStart(call: Call) { + logWithTime("requestHeadersStart") + } + + override fun requestHeadersEnd(call: Call, request: Request) { + logWithTime("requestHeadersEnd") + } + + override fun requestBodyStart(call: Call) { + logWithTime("requestBodyStart") + } + + override fun requestBodyEnd(call: Call, byteCount: Long) { + logWithTime("requestBodyEnd: byteCount=$byteCount") + } + + override fun requestFailed(call: Call, ioe: IOException) { + logWithTime("requestFailed: $ioe") + } + + override fun responseHeadersStart(call: Call) { + logWithTime("responseHeadersStart") + } + + override fun responseHeadersEnd(call: Call, response: Response) { + logWithTime("responseHeadersEnd: $response") + } + + override fun responseBodyStart(call: Call) { + logWithTime("responseBodyStart") + } + + override fun responseBodyEnd(call: Call, byteCount: Long) { + logWithTime("responseBodyEnd: byteCount=$byteCount") + } + + override fun responseFailed(call: Call, ioe: IOException) { + logWithTime("responseFailed: $ioe") + } + + override fun callEnd(call: Call) { + logWithTime("callEnd") + } + + override fun callFailed(call: Call, ioe: IOException) { + logWithTime("callFailed: $ioe") + } + + private fun logWithTime(message: String) { + val timeMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs) + logger.invoke("[$timeMs ms] $message") + } +} diff --git a/okhttp-testing-support/src/main/java/okhttp3/OkHttpClientTestRule.kt b/okhttp-testing-support/src/main/java/okhttp3/OkHttpClientTestRule.kt index d94f9f5c1..6d3484807 100644 --- a/okhttp-testing-support/src/main/java/okhttp3/OkHttpClientTestRule.kt +++ b/okhttp-testing-support/src/main/java/okhttp3/OkHttpClientTestRule.kt @@ -15,6 +15,7 @@ */ package okhttp3 +import okhttp3.testing.Flaky import org.assertj.core.api.Assertions.assertThat import org.junit.rules.TestRule import org.junit.runner.Description @@ -24,6 +25,7 @@ import java.util.concurrent.ConcurrentLinkedDeque /** Apply this rule to tests that need an OkHttpClient instance. */ class OkHttpClientTestRule : TestRule { + private val clientEventsList = mutableListOf() private var prototype: OkHttpClient? = null /** @@ -40,7 +42,13 @@ class OkHttpClientTestRule : TestRule { } fun newClientBuilder(): OkHttpClient.Builder { - return checkNotNull(prototype) { "don't create clients in test initialization!" }.newBuilder() + return checkNotNull(prototype) { "don't create clients in test initialization!" } + .newBuilder() + .eventListener(ClientRuleEventListener { addEvent(it) }) + } + + @Synchronized private fun addEvent(it: String) { + clientEventsList.add(it) } fun ensureAllConnectionsReleased() { @@ -57,6 +65,10 @@ class OkHttpClientTestRule : TestRule { acquireClient() try { base.evaluate() + logEventsIfFlaky(description) + } catch (t: Throwable) { + logEvents() + throw t } finally { ensureAllConnectionsReleased() releaseClient() @@ -64,9 +76,7 @@ class OkHttpClientTestRule : TestRule { } private fun acquireClient() { - prototype = prototypes.poll() ?: OkHttpClient.Builder() - .dns(SINGLE_INET_ADDRESS_DNS) // Prevent unexpected fallback addresses. - .build() + prototype = prototypes.poll() ?: freshClient() } private fun releaseClient() { @@ -78,6 +88,26 @@ class OkHttpClientTestRule : TestRule { } } + private fun logEventsIfFlaky(description: Description) { + if (isTestFlaky(description)) { + logEvents() + } + } + + private fun isTestFlaky(description: Description): Boolean { + return description.annotations.any { it.annotationClass == Flaky::class } || + description.testClass.annotations.any { it.annotationClass == Flaky::class } + } + + @Synchronized private fun logEvents() { + // Will be ineffective if test overrides the listener + println("Events (${clientEventsList.size})") + + for (e in clientEventsList) { + println(e) + } + } + /** * Called if a test is known to be leaky. */ @@ -107,5 +137,11 @@ class OkHttpClientTestRule : TestRule { return listOf(addresses[0]) } } + + private fun freshClient(): OkHttpClient { + return OkHttpClient.Builder() + .dns(SINGLE_INET_ADDRESS_DNS) // Prevent unexpected fallback addresses. + .build() + } } } diff --git a/okhttp-testing-support/src/main/java/okhttp3/testing/Flaky.kt b/okhttp-testing-support/src/main/java/okhttp3/testing/Flaky.kt new file mode 100644 index 000000000..026eeb3b1 --- /dev/null +++ b/okhttp-testing-support/src/main/java/okhttp3/testing/Flaky.kt @@ -0,0 +1,24 @@ +/* + * Copyright (C) 2019 Square, Inc. + * + * 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 okhttp3.testing + +@Target(AnnotationTarget.CLASS, AnnotationTarget.FUNCTION) +@Retention(AnnotationRetention.RUNTIME) +/** + * Annotation marking a test as flaky, and requires extra logging and linking against + * a known github issue. This does not ignore the failure. + */ +annotation class Flaky(val issues: Array = []) diff --git a/okhttp/src/test/java/okhttp3/ConnectionCoalescingTest.java b/okhttp/src/test/java/okhttp3/ConnectionCoalescingTest.java index 0752e9175..daaec3191 100644 --- a/okhttp/src/test/java/okhttp3/ConnectionCoalescingTest.java +++ b/okhttp/src/test/java/okhttp3/ConnectionCoalescingTest.java @@ -30,7 +30,6 @@ import okhttp3.testing.PlatformRule; import okhttp3.tls.HandshakeCertificates; import okhttp3.tls.HeldCertificate; import org.junit.Before; -import org.junit.Ignore; import org.junit.Rule; import org.junit.Test; diff --git a/okhttp/src/test/java/okhttp3/URLConnectionTest.java b/okhttp/src/test/java/okhttp3/URLConnectionTest.java index 0d0923676..4643e8ab3 100644 --- a/okhttp/src/test/java/okhttp3/URLConnectionTest.java +++ b/okhttp/src/test/java/okhttp3/URLConnectionTest.java @@ -68,6 +68,7 @@ import okhttp3.mockwebserver.MockResponse; import okhttp3.mockwebserver.MockWebServer; import okhttp3.mockwebserver.RecordedRequest; import okhttp3.mockwebserver.SocketPolicy; +import okhttp3.testing.Flaky; import okhttp3.testing.PlatformRule; import okhttp3.tls.HandshakeCertificates; import okio.Buffer; @@ -100,10 +101,8 @@ import static okhttp3.mockwebserver.SocketPolicy.FAIL_HANDSHAKE; import static okhttp3.mockwebserver.SocketPolicy.SHUTDOWN_INPUT_AT_END; import static okhttp3.mockwebserver.SocketPolicy.SHUTDOWN_OUTPUT_AT_END; import static okhttp3.mockwebserver.SocketPolicy.UPGRADE_TO_SSL_AT_END; -import static okhttp3.testing.PlatformRule.CONSCRYPT_PROPERTY; import static okhttp3.tls.internal.TlsUtil.localhost; import static org.assertj.core.api.Assertions.assertThat; -import static org.hamcrest.CoreMatchers.anything; import static org.junit.Assert.fail; /** Android's URLConnectionTest, ported to exercise OkHttp's Call API. */ @@ -687,9 +686,8 @@ public final class URLConnectionTest { * * http://code.google.com/p/android/issues/detail?id=13178 */ + @Flaky(issues = "https://github.com/square/okhttp/issues/5222") @Test public void connectViaHttpsToUntrustedServer() throws Exception { - // https://github.com/square/okhttp/issues/5222 - server.useHttps(handshakeCertificates.sslSocketFactory(), false); server.enqueue(new MockResponse()); // unused @@ -697,7 +695,10 @@ public final class URLConnectionTest { getResponse(newRequest("/foo")); fail(); } catch (SSLHandshakeException expected) { - assertThat(expected.getCause()).isInstanceOf(CertificateException.class); + // Allow conscrypt to fail in different ways + if (!platform.isConscrypt()) { + assertThat(expected.getCause()).isInstanceOf(CertificateException.class); + } } assertThat(server.getRequestCount()).isEqualTo(0); } diff --git a/okhttp/src/test/java/okhttp3/internal/http2/HttpOverHttp2Test.java b/okhttp/src/test/java/okhttp3/internal/http2/HttpOverHttp2Test.java index b830ff73c..c35d2603b 100644 --- a/okhttp/src/test/java/okhttp3/internal/http2/HttpOverHttp2Test.java +++ b/okhttp/src/test/java/okhttp3/internal/http2/HttpOverHttp2Test.java @@ -63,6 +63,7 @@ import okhttp3.mockwebserver.PushPromise; import okhttp3.mockwebserver.QueueDispatcher; import okhttp3.mockwebserver.RecordedRequest; import okhttp3.mockwebserver.SocketPolicy; +import okhttp3.testing.Flaky; import okhttp3.testing.PlatformRule; import okhttp3.tls.HandshakeCertificates; import okio.Buffer; @@ -97,6 +98,8 @@ import static org.junit.Assume.assumeTrue; /** Test how HTTP/2 interacts with HTTP features. */ @RunWith(Parameterized.class) +@Flaky(issues = {"https://github.com/square/okhttp/issues/4632", + "https://github.com/square/okhttp/issues/4633"}) public final class HttpOverHttp2Test { private static final Logger http2Logger = Logger.getLogger(Http2.class.getName()); private static final HandshakeCertificates handshakeCertificates = localhost(); @@ -1227,6 +1230,7 @@ public final class HttpOverHttp2Test { (long) 1); } + @Flaky(issues = "https://github.com/square/okhttp/issues/5221") @Test public void missingPongsFailsConnection() throws Exception { if (protocol == Protocol.HTTP_2) { // https://github.com/square/okhttp/issues/5221 @@ -1405,6 +1409,7 @@ public final class HttpOverHttp2Test { assertThat(server.takeRequest().getSequenceNumber()).isEqualTo(0); } + @Flaky(issues = "https://github.com/square/okhttp/issues/4836") @Test public void responseHeadersAfterGoaway() throws Exception { server.enqueue(new MockResponse() .setHeadersDelay(1, SECONDS) diff --git a/okhttp/src/test/java/okhttp3/internal/ws/WebSocketHttpTest.java b/okhttp/src/test/java/okhttp3/internal/ws/WebSocketHttpTest.java index 4806f923d..2dd8bb226 100644 --- a/okhttp/src/test/java/okhttp3/internal/ws/WebSocketHttpTest.java +++ b/okhttp/src/test/java/okhttp3/internal/ws/WebSocketHttpTest.java @@ -41,6 +41,7 @@ import okhttp3.mockwebserver.MockResponse; import okhttp3.mockwebserver.MockWebServer; import okhttp3.mockwebserver.RecordedRequest; import okhttp3.mockwebserver.SocketPolicy; +import okhttp3.testing.Flaky; import okhttp3.tls.HandshakeCertificates; import okio.Buffer; import okio.ByteString; @@ -57,6 +58,8 @@ import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.data.Offset.offset; import static org.junit.Assert.fail; +@Flaky(issues = {"https://github.com/square/okhttp/issues/4515", + "https://github.com/square/okhttp/issues/4953"}) public final class WebSocketHttpTest { @Rule public final MockWebServer webServer = new MockWebServer(); @Rule public final OkHttpClientTestRule clientTestRule = new OkHttpClientTestRule(); @@ -249,8 +252,8 @@ public final class WebSocketHttpTest { server.close(1001, "bye"); clientListener.assertClosed(1001, "bye"); clientListener.assertExhausted(); - serverListener.assertClosing(1000, ""); - serverListener.assertClosed(1000, ""); + serverListener.assertClosing(1000, ""); + serverListener.assertClosed(1000, ""); serverListener.assertExhausted(); } @@ -579,8 +582,8 @@ public final class WebSocketHttpTest { } long elapsedUntilPong3 = System.nanoTime() - startNanos; - assertThat((double) TimeUnit.NANOSECONDS.toMillis(elapsedUntilPong3)).isCloseTo((double) 1500, offset( - 250d)); + assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilPong3)) + .isCloseTo(1500L, offset(250L)); // The client pinged the server 3 times, and it has ponged back 3 times. assertThat(webSocket.sentPingCount()).isEqualTo(3); @@ -644,8 +647,8 @@ public final class WebSocketHttpTest { latch.countDown(); long elapsedUntilFailure = System.nanoTime() - openAtNanos; - assertThat((double) TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure)).isCloseTo((double) 1000, offset( - 250d)); + assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure)) + .isCloseTo(1000L, offset(250L)); } /** https://github.com/square/okhttp/issues/2788 */ @@ -664,8 +667,8 @@ public final class WebSocketHttpTest { // Confirm that the hard cancel occurred after 500 ms. clientListener.assertFailure(); long elapsedUntilFailure = System.nanoTime() - closeAtNanos; - assertThat((double) TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure)).isCloseTo((double) 500, offset( - 250d)); + assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure)) + .isCloseTo(500L, offset(250L)); // Close the server and confirm it saw what we expected. server.close(1000, null);