Add more context when failing to read from the cache

[ian-ellis]

I am currently trying to debug the following crash reported through firebase crashalytics for our Android application. Unfortunately but we cannot actually reproduce the issue, ourselves so the below stacktrace is all we have to go on.

okhttp3.Cache$Entry.readCertificateList (Cache.java:609)
okhttp3.Cache$Entry.<init> (Cache.java:529)
okhttp3.Cache.get$okhttp (Cache.java:177)
okhttp3.internal.cache.CacheInterceptor.intercept (CacheInterceptor.java:47)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:109)
okhttp3.internal.http.BridgeInterceptor.intercept (BridgeInterceptor.java:83)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:109)
okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept (RetryAndFollowUpInterceptor.java:76)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.java:109)
okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp (RealCall.java:201)
okhttp3.internal.connection.RealCall$AsyncCall.run (RealCall.java:517)
java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1167)
java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:641)
java.lang.Thread.run (Thread.java:764)

It stems from the null coalescing found here:

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

Line 609 in fc6c29c

bytes.write(line.decodeBase64()!!)

What is making this incredibly hard to debug is the lack of information about the request itself. Firstly we are not setting a cache on our own OKhttp instance, which leads me to suspect a third party lib. However, without knowing any details about the request that we are failing to read from the cache it is almost impossible to tell.

My suggestion is to instead of using !! on the decoded certificate, we null check and then throw a CertificateReadException that provides more info about the response - mainly the URL but any other information that would be considered safe to end up in crash logs.s

[yschimke]

What version of OkHttp and Okio are you including in your app?

Look similar-ish to #2281

What would your suggested change be? Care to submit a PR? We don't expect this bug or similar to happen, so we don't throw full context about urls for every logic bug. By the time we land a fix, or add in enough context for you to faithfully debug this, you probably will get an answer more directly by either

1. Building a local dev build of okhttp, with your suggested fix instead of waiting for a 4.10 release.
   or
2. Work out which client is making this call and configuring them to use an EventListener to capture some debugging information.

[yschimke]

Seems like a reasonable request if cache is corruptible (e.g. external file system changes) such that it doesn't always show a logic bug. If this type of runtime exception is possible because of external factors, we should probably also cleanup the cache instead of failing.

[yschimke]

For discussion, tests to confirm the fix after agreing on direction.

[swankjesse]

Looks like the response metadata file is truncated, despite our atomic rename.

Or we’re trying to use an HTTP cache entry to serve an HTTPS request?!

[yschimke]

So separating the cause from our handling of errors? Are you ok with the approach of preferring a mechanism to repair after failure? Otherwise we pretty much corrupt until you reinstall the App.

[swankjesse]

I'd like to understand what's happening here. Is it a logic bug or is this file changing spontaneously?

[dave-r12]

@ian-ellis this might be redundant but can you include the exception that you're seeing along with the stack trace?

[yschimke]

Another instance of this with 3.12.x

#2281 (comment)

Maybe best case here is to cleanly fail on corrupted base64 content instead of NPE? But will hide the bug.

[yschimke]

Also relevant #6453

[Reoger]

I also encountered this problem, and found that basically it happened in the background (accounting for 98%). I guess the string resource was recycled by the system in the background, resulting in the scheme leaving only empty strings.

[yschimke]

Thanks for the context, much appreciated. We have changed the code to fail earlier, and we are working on better IO abstractions that should allow us to make it easier to debug this type of problem. If you are able to reliably reproduce this, please let me know and I'll give you a build to test with. Thanks!

[rajbopched11]

@swankjesse @yschimke any possible suggestions/workarounds to overcome this ?? Was it gracefully handled in any up-versions ?
Our Firebase crashlytics still reports this issue infrequently

Fatal Exception: java.lang.NullPointerException
       at okhttp3.Cache$Entry.readCertificateList(SourceFile:608)
       at okhttp3.Cache$Entry.<init>(SourceFile:528)
       at okhttp3.Cache.get$okhttp(SourceFile:177)
       at okhttp3.internal.cache.CacheInterceptor.intercept(SourceFile:47)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at okhttp3.internal.http.BridgeInterceptor.intercept(SourceFile:83)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(SourceFile:76)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at o.ɷ.intercept(SourceFile:81)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at o.aMM.intercept(SourceFile:16)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at o.aMX.intercept(SourceFile:15)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at okhttp3.logging.HttpLoggingInterceptor.intercept(SourceFile:221)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at o.aMT$if.intercept(SourceFile:172)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at o.aMT$ı.intercept(SourceFile:149)
       at okhttp3.internal.http.RealInterceptorChain.proceed(SourceFile:109)
       at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(SourceFile:201)
       at okhttp3.internal.connection.RealCall$AsyncCall.run(SourceFile:517)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
       at java.lang.Thread.run(Thread.java:764)

[yschimke]

Cache now takes a FileSystem, so I think there are options now for adding additional debugging if you can repro.

Is anyone hitting this on 4.11 or 5.0.0-alpha11?