Cache Events (#6015)

Provide EventListener methods to understand the impact of caching.

okhttp-testing-support/src/main/kotlin/okhttp3/CallEvent.kt

@@ -204,4 +204,24 @@ sealed class CallEvent {
     override val call: Call,
     val ioe: IOException
   ) : CallEvent()
+
+  data class SatisfactionFailure(
+    override val timestampNs: Long,
+    override val call: Call
+  ) : CallEvent()
+
+  data class CacheHit(
+    override val timestampNs: Long,
+    override val call: Call
+  ) : CallEvent()
+
+  data class CacheMiss(
+    override val timestampNs: Long,
+    override val call: Call
+  ) : CallEvent()
+
+  data class CacheConditionalHit(
+    override val timestampNs: Long,
+    override val call: Call
+  ) : CallEvent()
 }

okhttp-testing-support/src/main/kotlin/okhttp3/ClientRuleEventListener.kt

@@ -241,6 +241,30 @@ class ClientRuleEventListener(
     delegate.canceled(call)
   }
 
+  override fun satisfactionFailure(call: Call, response: Response) {
+    logWithTime("satisfactionFailure")
+
+    delegate.satisfactionFailure(call, response)
+  }
+
+  override fun cacheMiss(call: Call) {
+    logWithTime("cacheMiss")
+
+    delegate.cacheMiss(call)
+  }
+
+  override fun cacheHit(call: Call, response: Response) {
+    logWithTime("cacheHit")
+
+    delegate.cacheHit(call, response)
+  }
+
+  override fun cacheConditionalHit(call: Call, cachedResponse: Response) {
+    logWithTime("cacheConditionalHit")
+
+    delegate.cacheConditionalHit(call, cachedResponse)
+  }
+
   private fun logWithTime(message: String) {
     val timeMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs)
     logger.invoke("[$timeMs ms] $message")

okhttp-testing-support/src/main/kotlin/okhttp3/RecordingEventListener.kt

@@ -22,6 +22,9 @@ import java.net.Proxy
 import java.util.Deque
 import java.util.concurrent.ConcurrentLinkedDeque
 import java.util.concurrent.TimeUnit
+import okhttp3.CallEvent.CacheConditionalHit
+import okhttp3.CallEvent.CacheHit
+import okhttp3.CallEvent.CacheMiss
 import okhttp3.CallEvent.CallEnd
 import okhttp3.CallEvent.CallFailed
 import okhttp3.CallEvent.CallStart
@@ -45,6 +48,7 @@ import okhttp3.CallEvent.ResponseBodyStart
 import okhttp3.CallEvent.ResponseFailed
 import okhttp3.CallEvent.ResponseHeadersEnd
 import okhttp3.CallEvent.ResponseHeadersStart
+import okhttp3.CallEvent.SatisfactionFailure
 import okhttp3.CallEvent.SecureConnectEnd
 import okhttp3.CallEvent.SecureConnectStart
 import org.assertj.core.api.Assertions.assertThat
@@ -260,4 +264,21 @@ open class RecordingEventListener : EventListener() {
   override fun canceled(
     call: Call
   ) = logEvent(Canceled(System.nanoTime(), call))
+
+  override fun satisfactionFailure(
+    call: Call,
+    response: Response
+  ) = logEvent(SatisfactionFailure(System.nanoTime(), call))
+
+  override fun cacheMiss(
+    call: Call
+  ) = logEvent(CacheMiss(System.nanoTime(), call))
+
+  override fun cacheHit(
+    call: Call,
+    response: Response
+  ) = logEvent(CacheHit(System.nanoTime(), call))
+
+  override fun cacheConditionalHit(call: Call, cachedResponse: Response) =
+    logEvent(CacheConditionalHit(System.nanoTime(), call))
 }

okhttp/src/main/kotlin/okhttp3/EventListener.kt

@@ -422,6 +422,41 @@ abstract class EventListener {
   ) {
   }
 
+  /**
+   * Invoked when a call fails due to cache rules.
+   * For example, we're forbidden from using the network and the cache is insufficient
+   */
+  open fun satisfactionFailure(call: Call, response: Response) {
+  }
+
+  /**
+   * Invoked when a result is served from the cache. The Response provided is the top level
+   * Response and normal event sequences will not be received.
+   *
+   * This event will only be received when a Cache is configured for the client.
+   */
+  open fun cacheHit(call: Call, response: Response) {
+  }
+
+  /**
+   * Invoked when a response will be served from the network. The Response will be
+   * available from normal event sequences.
+   *
+   * This event will only be received when a Cache is configured for the client.
+   */
+  open fun cacheMiss(call: Call) {
+  }
+
+  /**
+   * Invoked when a response will be served from the cache or network based on validating the
+   * cached Response freshness. Will be followed by cacheHit or cacheMiss after the network
+   * Response is available.
+   *
+   * This event will only be received when a Cache is configured for the client.
+   */
+  open fun cacheConditionalHit(call: Call, cachedResponse: Response) {
+  }
+
   interface Factory {
     /**
      * Creates an instance of the [EventListener] for a particular [Call]. The returned

okhttp/src/main/kotlin/okhttp3/internal/cache/CacheInterceptor.kt

@@ -21,12 +21,14 @@ import java.net.HttpURLConnection.HTTP_GATEWAY_TIMEOUT
 import java.net.HttpURLConnection.HTTP_NOT_MODIFIED
 import java.util.concurrent.TimeUnit.MILLISECONDS
 import okhttp3.Cache
+import okhttp3.EventListener
 import okhttp3.Headers
 import okhttp3.Interceptor
 import okhttp3.Protocol
 import okhttp3.Response
 import okhttp3.internal.EMPTY_RESPONSE
 import okhttp3.internal.closeQuietly
+import okhttp3.internal.connection.RealCall
 import okhttp3.internal.discard
 import okhttp3.internal.http.ExchangeCodec
 import okhttp3.internal.http.HttpMethod
@@ -42,6 +44,7 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor {
 
   @Throws(IOException::class)
   override fun intercept(chain: Interceptor.Chain): Response {
+    val call = chain.call()
     val cacheCandidate = cache?.get(chain.request())
 
     val now = System.currentTimeMillis()
@@ -51,6 +54,7 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor {
     val cacheResponse = strategy.cacheResponse
 
     cache?.trackResponse(strategy)
+    val listener = (call as? RealCall)?.eventListener ?: EventListener.NONE
 
     if (cacheCandidate != null && cacheResponse == null) {
       // The cache candidate wasn't applicable. Close it.
@@ -67,14 +71,24 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor {
           .body(EMPTY_RESPONSE)
           .sentRequestAtMillis(-1L)
           .receivedResponseAtMillis(System.currentTimeMillis())
-          .build()
+          .build().also {
+            listener.satisfactionFailure(call, it)
+          }
     }
 
     // If we don't need the network, we're done.
     if (networkRequest == null) {
       return cacheResponse!!.newBuilder()
           .cacheResponse(stripBody(cacheResponse))
-          .build()
+          .build().also {
+            listener.cacheHit(call, it)
+          }
+    }
+
+    if (cacheResponse != null) {
+      listener.cacheConditionalHit(call, cacheResponse)
+    } else if (cache != null) {
+      listener.cacheMiss(call)
     }
 
     var networkResponse: Response? = null
@@ -104,7 +118,9 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor {
         // Content-Encoding header (as performed by initContentStream()).
         cache!!.trackConditionalCacheHit()
         cache.update(cacheResponse, response)
-        return response
+        return response.also {
+          listener.cacheHit(call, it)
+        }
       } else {
         cacheResponse.body?.closeQuietly()
       }
@@ -119,7 +135,12 @@ class CacheInterceptor(internal val cache: Cache?) : Interceptor {
       if (response.promisesBody() && CacheStrategy.isCacheable(response, networkRequest)) {
         // Offer this request to the cache.
         val cacheRequest = cache.put(response)
-        return cacheWritingResponse(cacheRequest, response)
+        return cacheWritingResponse(cacheRequest, response).also {
+          if (cacheResponse != null) {
+            // This will log a conditional cache miss only.
+            listener.cacheMiss(call)
+          }
+        }
       }
 
       if (HttpMethod.invalidatesCache(networkRequest.method)) {

okhttp/src/main/kotlin/okhttp3/internal/connection/RealCall.kt

@@ -65,7 +65,7 @@ class RealCall(
 ) : Call {
   private val connectionPool: RealConnectionPool = client.connectionPool.delegate
 
-  private val eventListener: EventListener = client.eventListenerFactory.create(this)
+  internal val eventListener: EventListener = client.eventListenerFactory.create(this)
 
   private val timeout = object : AsyncTimeout() {
     override fun timedOut() {

okhttp/src/test/java/okhttp3/EventListenerTest.java

@@ -15,6 +15,7 @@
  */
 package okhttp3;
 
+import java.io.File;
 import java.io.IOException;
 import java.io.InterruptedIOException;
 import java.net.HttpURLConnection;
@@ -77,6 +78,7 @@ import static okhttp3.tls.internal.TlsUtil.localhost;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.hamcrest.CoreMatchers.any;
 import static org.hamcrest.CoreMatchers.equalTo;
+import static org.junit.Assert.assertNotNull;
 import static org.junit.Assert.fail;
 import static org.junit.Assume.assumeThat;
 
@@ -96,6 +98,7 @@ public final class EventListenerTest {
       .eventListenerFactory(clientTestRule.wrap(listener))
       .build();
   private SocksProxy socksProxy;
+  private Cache cache = null;
 
   @Before public void setUp() {
     platform.assumeNotOpenJSSE();
@@ -109,6 +112,9 @@ public final class EventListenerTest {
     if (socksProxy != null) {
       socksProxy.shutdown();
     }
+    if (cache != null) {
+      cache.delete();
+    }
   }
 
   @Test public void successfulCallEventSequence() throws IOException {
@@ -1443,4 +1449,141 @@ public final class EventListenerTest {
     listener.takeEvent(RequestBodyEnd.class, 0L);
     listener.takeEvent(ResponseHeadersEnd.class, responseHeadersStartDelay);
   }
+
+  @Test public void cacheMiss() throws IOException {
+    enableCache();
+
+    server.enqueue(new MockResponse()
+        .setBody("abc"));
+
+    Call call = client.newCall(new Request.Builder()
+        .url(server.url("/"))
+        .build());
+    Response response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    assertThat(response.body().string()).isEqualTo("abc");
+    response.close();
+
+    assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheMiss",
+        "ProxySelectStart", "ProxySelectEnd", "DnsStart", "DnsEnd",
+        "ConnectStart", "ConnectEnd", "ConnectionAcquired", "RequestHeadersStart",
+        "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd",
+        "ResponseBodyStart", "ResponseBodyEnd", "ConnectionReleased", "CallEnd");
+  }
+
+  @Test public void conditionalCache() throws IOException {
+    enableCache();
+
+    server.enqueue(new MockResponse()
+        .addHeader("ETag: v1")
+        .setBody("abc"));
+    server.enqueue(new MockResponse()
+        .setResponseCode(HttpURLConnection.HTTP_NOT_MODIFIED));
+
+    Call call = client.newCall(new Request.Builder()
+        .url(server.url("/"))
+        .build());
+
+    Response response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    response.close();
+
+    listener.clearAllEvents();
+
+    call = call.clone();
+
+    response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    assertThat(response.body().string()).isEqualTo("abc");
+    response.close();
+
+    assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheConditionalHit",
+        "ConnectionAcquired", "RequestHeadersStart",
+        "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd",
+        "ResponseBodyStart", "ResponseBodyEnd", "CacheHit", "ConnectionReleased", "CallEnd");
+  }
+
+  @Test public void conditionalCacheMiss() throws IOException {
+    enableCache();
+
+    server.enqueue(new MockResponse()
+        .addHeader("ETag: v1")
+        .setBody("abc"));
+    server.enqueue(new MockResponse()
+        .setResponseCode(HttpURLConnection.HTTP_OK)
+        .addHeader("ETag: v2")
+        .setBody("abd"));
+
+    Call call = client.newCall(new Request.Builder()
+        .url(server.url("/"))
+        .build());
+
+    Response response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    response.close();
+
+    listener.clearAllEvents();
+
+    call = call.clone();
+
+    response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    assertThat(response.body().string()).isEqualTo("abd");
+    response.close();
+
+    assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheConditionalHit",
+        "ConnectionAcquired", "RequestHeadersStart",
+        "RequestHeadersEnd", "ResponseHeadersStart", "ResponseHeadersEnd", "CacheMiss",
+        "ResponseBodyStart", "ResponseBodyEnd", "ConnectionReleased", "CallEnd");
+  }
+
+  @Test public void satisfactionFailure() throws IOException {
+    enableCache();
+
+    Call call = client.newCall(new Request.Builder()
+        .url(server.url("/"))
+        .cacheControl(CacheControl.FORCE_CACHE)
+        .build());
+    Response response = call.execute();
+    assertThat(response.code()).isEqualTo(504);
+    response.close();
+
+    assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "SatisfactionFailure", "CallEnd");
+  }
+
+  @Test public void cacheHit() throws IOException {
+    enableCache();
+
+    server.enqueue(new MockResponse().setBody("abc").addHeader("cache-control: public, max-age=300"));
+
+    Call call = client.newCall(new Request.Builder()
+        .url(server.url("/"))
+        .build());
+    Response response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    assertThat(response.body().string()).isEqualTo("abc");
+    response.close();
+
+    listener.clearAllEvents();
+
+    call = call.clone();
+    response = call.execute();
+    assertThat(response.code()).isEqualTo(200);
+    assertThat(response.body().string()).isEqualTo("abc");
+    response.close();
+
+    assertThat(listener.recordedEventTypes()).containsExactly("CallStart", "CacheHit", "CallEnd");
+  }
+
+  private Cache enableCache() throws IOException {
+    cache = makeCache();
+    client = client.newBuilder().cache(cache).build();
+    return cache;
+  }
+
+  private Cache makeCache() throws IOException {
+    File cacheDir = File.createTempFile("cache-", ".dir");
+    cacheDir.delete();
+    return new Cache(cacheDir, 1024 * 1024);
+  }
 }