Output client events after tagged @Flaky tests or failures (#5217)

Collect additional debugging info for know problem tests or after unplanned failures.

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<InetAddress>) {
+    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")
+  }
+}

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<String>()
   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()
+        prototype = prototypes.poll() ?: freshClient()
-            .dns(SINGLE_INET_ADDRESS_DNS) // Prevent unexpected fallback addresses.
-            .build()
       }
 
       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()
+    }
   }
 }

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<String> = [])

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;
 

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,8 +695,11 @@ public final class URLConnectionTest {
       getResponse(newRequest("/foo"));
       fail();
     } catch (SSLHandshakeException expected) {
+      // Allow conscrypt to fail in different ways
+      if (!platform.isConscrypt()) {
         assertThat(expected.getCause()).isInstanceOf(CertificateException.class);
       }
+    }
     assertThat(server.getRequestCount()).isEqualTo(0);
   }
 

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)

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();
@@ -579,8 +582,8 @@ public final class WebSocketHttpTest {
     }
 
     long elapsedUntilPong3 = System.nanoTime() - startNanos;
-    assertThat((double) TimeUnit.NANOSECONDS.toMillis(elapsedUntilPong3)).isCloseTo((double) 1500, offset(
+    assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilPong3))
-        250d));
+        .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(
+    assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure))
-        250d));
+        .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(
+    assertThat(TimeUnit.NANOSECONDS.toMillis(elapsedUntilFailure))
-        250d));
+        .isCloseTo(500L, offset(250L));
 
     // Close the server and confirm it saw what we expected.
     server.close(1000, null);