Okhttp: HTTP2 not working with different mixes of library and OS versions

[niltsiar]

In my application I'm still using branch 3.12.x because I still need to support older versions than Android 5.0. Today I've realized that HTTP2 connections were not working on Android 10.

Here you can find the log from a Caddy server with different requests made by my app. The only differences between executions were the modification of OkHttp version. I've tried from an old 3.12.x version where HTTP2 were working fine to the latest version of that branch, 3.14.x and 4.x

[19/Mar/2020:20:16:34 +0100] "POST /redacted HTTP/2.0" 200 8143 "-" "okhttp/3.12.6"
[19/Mar/2020:20:16:34 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/3.12.6"
[19/Mar/2020:20:16:34 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/3.12.6"

[19/Mar/2020:20:19:43 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/3.12.7"
[19/Mar/2020:20:19:43 +0100] "POST /redacted HTTP/2.0" 200 8142 "-" "okhttp/3.12.7"
[19/Mar/2020:20:19:43 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/3.12.7"

[19/Mar/2020:20:22:03 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/3.12.8"
[19/Mar/2020:20:22:03 +0100] "POST /redacted HTTP/2.0" 200 8142 "-" "okhttp/3.12.8"
[19/Mar/2020:20:22:04 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/3.12.8"

[19/Mar/2020:20:23:16 +0100] "POST /redacted HTTP/1.1" 200 8143 "-" "okhttp/3.12.9"
[19/Mar/2020:20:23:17 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.12.9"
[19/Mar/2020:20:23:17 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.12.9"

[19/Mar/2020:20:13:40 +0100] "POST /redacted HTTP/1.1" 200 8142 "-" "okhttp/3.12.10"
[19/Mar/2020:20:14:10 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.12.10"
[19/Mar/2020:20:14:11 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.12.10"

[19/Mar/2020:20:25:17 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.7"
[19/Mar/2020:20:25:17 +0100] "POST /redacted HTTP/1.1" 200 8142 "-" "okhttp/3.14.7"
[19/Mar/2020:20:25:17 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.14.7"

[19/Mar/2020:20:27:44 +0100] "POST /redacted HTTP/1.1" 200 8143 "-" "okhttp/3.14.6"
[19/Mar/2020:20:27:44 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.6"
[19/Mar/2020:20:27:44 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.14.6"

[19/Mar/2020:20:30:28 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/3.14.5"
[19/Mar/2020:20:30:28 +0100] "POST /redacted HTTP/1.1" 401 120 "-" "okhttp/3.14.5"
[19/Mar/2020:20:30:28 +0100] "POST /redacted HTTP/1.1" 401 120 "-" "okhttp/3.14.5"

[19/Mar/2020:20:32:16 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/3.14.4"
[19/Mar/2020:20:32:16 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.14.4"
[19/Mar/2020:20:32:16 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.4"

[19/Mar/2020:20:35:19 +0100] "POST /redacted HTTP/1.1" 200 8143 "-" "okhttp/3.14.3"
[19/Mar/2020:20:35:19 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.3"
[19/Mar/2020:20:35:19 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.14.3"

[19/Mar/2020:20:38:46 +0100] "POST /redacted HTTP/1.1" 200 8142 "-" "okhttp/3.14.2"
[19/Mar/2020:20:38:46 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.2"
[19/Mar/2020:20:38:46 +0100] "POST /redacted HTTP/1.1" 200 369 "-" "okhttp/3.14.2"

[19/Mar/2020:20:41:46 +0100] "POST /redacted HTTP/1.1" 200 8143 "-" "okhttp/3.14.1"
[19/Mar/2020:20:41:46 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.1"
[19/Mar/2020:20:41:46 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.14.1"

[19/Mar/2020:20:44:39 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/3.14.0"
[19/Mar/2020:20:44:39 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.0"
[19/Mar/2020:20:44:40 +0100] "POST /redacted HTTP/1.1" 200 369 "-" "okhttp/3.14.0"

[19/Mar/2020:20:47:51 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/3.13.1"
[19/Mar/2020:20:47:51 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.13.1"
[19/Mar/2020:20:47:51 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/3.13.1"

[19/Mar/2020:20:58:07 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/4.0.0"
[19/Mar/2020:20:58:07 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/4.0.0"
[19/Mar/2020:20:58:07 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/4.0.0"

[19/Mar/2020:21:44:37 +0100] "POST /redacted HTTP/1.1" 200 8143 "-" "okhttp/4.0.1"
[19/Mar/2020:21:44:37 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/4.0.1"
[19/Mar/2020:21:44:37 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/4.0.1"

[19/Mar/2020:21:49:17 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/4.1.0"
[19/Mar/2020:21:49:17 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/4.1.0"
[19/Mar/2020:21:49:17 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/4.1.0"

[19/Mar/2020:21:52:52 +0100] "POST /redacted HTTP/1.1" 200 8144 "-" "okhttp/4.1.1"
[19/Mar/2020:21:52:52 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/4.1.1"
[19/Mar/2020:21:52:52 +0100] "POST /redacted HTTP/1.1" 200 370 "-" "okhttp/4.1.1"

[19/Mar/2020:21:57:05 +0100] "POST /redacted HTTP/2.0" 200 369 "-" "okhttp/4.2.0"
[19/Mar/2020:21:57:05 +0100] "POST /redacted HTTP/2.0" 200 8143 "-" "okhttp/4.2.0"
[19/Mar/2020:21:57:05 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.2.0"

[19/Mar/2020:22:01:34 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.2.1"
[19/Mar/2020:22:01:34 +0100] "POST /redacted HTTP/2.0" 200 8143 "-" "okhttp/4.2.1"
[19/Mar/2020:22:01:34 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.2.1"

[19/Mar/2020:22:05:54 +0100] "POST /redacted HTTP/2.0" 401 118 "-" "okhttp/4.2.2"
[19/Mar/2020:22:05:56 +0100] "POST /redacted HTTP/2.0" 200 159 "-" "okhttp/4.2.2"
[19/Mar/2020:22:05:58 +0100] "POST /redacted HTTP/2.0" 200 8142 "-" "okhttp/4.2.2"

[19/Mar/2020:21:39:33 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.3.0"
[19/Mar/2020:21:39:33 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.3.0"
[19/Mar/2020:21:39:37 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.3.0"

[19/Mar/2020:21:34:57 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.3.1"
[19/Mar/2020:21:34:57 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.3.1"
[19/Mar/2020:21:34:59 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.3.1"

[19/Mar/2020:21:00:41 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.4.0"
[19/Mar/2020:21:01:07 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.4.0"
[19/Mar/2020:21:10:26 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.4.0"

[19/Mar/2020:22:44:57 +0100] "POST /redacted HTTP/2.0" 200 159 "-" "okhttp/4.4.1"
[19/Mar/2020:22:44:57 +0100] "POST /redacted HTTP/2.0" 200 370 "-" "okhttp/4.4.1"
[19/Mar/2020:22:44:59 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.4.1"

In summary for Android 10:

• In 3.12.x it was working fine until 3.12.9 were it does not work anymore.
• In 3.14.x it seems not to work at all.
• In 4.x it seems to work properly from 4.2.0 till the latest one.

I've also tried the same test with an Android 9 device. These are the relevant log parts.

[19/Mar/2020:22:12:18 +0100] "POST /redacted HTTP/2.0" 200 446 "-" "okhttp/3.12.10"
[19/Mar/2020:22:12:18 +0100] "POST /redacted HTTP/2.0" 200 88 "-" "okhttp/3.12.10"
[19/Mar/2020:22:12:18 +0100] "POST /redacted HTTP/2.0" 200 80 "-" "okhttp/3.12.10"

[19/Mar/2020:22:16:47 +0100] "POST /redacted HTTP/1.1" 200 80 "-" "okhttp/3.14.7"
[19/Mar/2020:22:16:47 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/3.14.7"
[19/Mar/2020:22:16:47 +0100] "POST /redacted HTTP/1.1" 200 399 "-" "okhttp/3.14.7"

[19/Mar/2020:22:21:20 +0100] "POST /redacted HTTP/1.1" 200 80 "-" "okhttp/4.1.1"
[19/Mar/2020:22:21:20 +0100] "POST /redacted HTTP/1.1" 200 99 "-" "okhttp/4.1.1"
[19/Mar/2020:22:21:21 +0100] "POST /redacted HTTP/1.1" 200 399 "-" "okhttp/4.1.1"

[19/Mar/2020:22:41:26 +0100] "POST /redacted HTTP/2.0" 200 80 "-" "okhttp/4.2.0"
[19/Mar/2020:22:41:26 +0100] "POST /redacted HTTP/2.0" 401 119 "-" "okhttp/4.2.0"
[19/Mar/2020:22:41:27 +0100] "POST /redacted HTTP/2.0" 401 117 "-" "okhttp/4.2.0"

[19/Mar/2020:22:43:41 +0100] "POST /redacted HTTP/2.0" 200 80 "-" "okhttp/4.4.1"
[19/Mar/2020:22:43:42 +0100] "POST /redacted HTTP/2.0" 200 399 "-" "okhttp/4.4.1"
[19/Mar/2020:22:43:42 +0100] "POST /redacted HTTP/2.0" 200 99 "-" "okhttp/4.4.1"

In summary for Android 9:

• 3.12.x is working fine
• 3.14.x is not working
• In 4.x the behavior is the same as in Android 10. HTTP2 is not woking until 4.2.0 and it's working fine from that.

[swankjesse]

Nice analysis.

[yschimke]

I'm trying to get the Android tests from 4 running on a branch against these versions. Thanks for the amazing analysis.

I'm glad Android 10 is working on 4.x.

3.12.9 added Android10Platform which IIRC we did to avoid issues with graylisted (and eventually blacklisted in 11) APIs via Reflection. So we backported it from 4.x.

https://github.com/square/okhttp/commit/c2e9ee23d9cc9cb48573a071ea32e4ec0640813f#diff-55fc33d7feaf12483a0809e1db851f58

I'll look at how to fix and test to confirm.

[yschimke]

How I feel about testing all the version combinations :(

https://twitter.com/yschimke/status/1231152563086557185

[yschimke]

This is the branch I'm testing on, backporting to 3.x branch at the moment.

https://github.com/square/okhttp/tree/android_3_14_tests

[niltsiar]

I've run the same tests on an Android 7 device and the results of the tests are the same as the ones from the Android 9. It was expected but just to be absolutely sure 😊

[yschimke]

OK, thankfully it's not as big an issue as I feared, assuming something about your test client (conscrypt or GMS is used). Can you confirm if you are using Conscrypt or the GMS Play Provider.

It's working for me on Android 10 with vanilla Android JSSE. But I'm seeing the behaviour you describe for Conscrypt and Play providers.

So bad news is that it is going to actively break for you in Android 11. To mitigate that and avoid spammy logging for graylists, I backported the Android10Platform to 3.x branches. But it doesn't negotiate HTTP/2 for those providers on those branches. And we don't have a way to anymore, hence why it broke, I was trying to get ahead of the problem.

[yschimke]

Anyway, I can't look at it at the moment (paying work to do), but the branch is there to test with.

$ ANDROID_SDK_ROOT=XXX/sdk ./gradlew :android-test:connectedCheck

[yschimke]

The simplest fix for Android 10, but not 11 :( is to accept the spammy messages and only use Android10Platform on Android 11+. I should have listened to Jake...

The bigger fix is backporting all the SocketAdapter code to 3.12.x. But I'm not super keen. It's making these really live maintenance branches.

[niltsiar]

Yes, I'm using ProviderInstaller.installIfNeeded as the first thing the app does. If I don't do that, 3.12, 3.14 and 4.4 work great in both Android 10 and Android 9.

[yschimke]

OK, so apart from Android 11 (fatal) Android 10 (Spammy) issue with reflection, the other unknown is why it stopped working in 3.14.x for Android 9.

So here it relates to the move away from OptionalMethod to standard reflection in 3.14.x

sslSocketClass = Class.forName("com.android.org.conscrypt.OpenSSLSocketImpl");

    if (!sslSocketClass.isInstance(sslSocket)) {
      return; // No TLS extensions if the socket class is custom.
    }

That was done on this commit https://github.com/square/okhttp/commit/4fb5e71fe7da8b2c42986dc941567b93aef5f2e5#diff-04efb1e303b1ac9bc9cc37b04df89ca0

[yschimke]

@niltsiar I don't intend to fix either issue. There are potential code fixes we could do, but unless someone else wants to agree the path forward and implement one of them, it's not something I have motivation to do given work, family in lockdown and given the risk/reward of doing fixes like this on maintenance branches.

Closing this umbrella issue, follow up on the specific issues.

BTW you are an Awesome OSS collaborator, really appreciate the time you put into investigating this!