okhttp: Bug: HTTP/2 may send duplicate request on Android devices.
We have an app on both Android and iOS, and the Android using okhttp/3.6. We tried to start http/2 support on our api server which the apps connected to, Nginx.
Everything was ok, most requests have used http/2, but something wired happend:
in the nginx access_log, I found some requests with HUGE request_time, which could be more than 900s or 1000s, all these requests returned http_status_408.
And when I checked on these users(or devices), all these requests sent after users stopping using the app, and at most time these requests are duplicated.
I cannot reproduce this on my own devices, or any test devices in our company. But this should be a bug because at the same time, iOS client was working fine with http/2.
here is the wired access_log: we can find that the user stopped using app at 21:50:20, but sent more requests, after 950 seconds, the nginx log these requests at 22:01:27.
Time request_time response_time http2 status request
April 25th 2017, 22:23:25.000 0.021 0.021 h2 200 /messenger/v2/conversations/unread
April 25th 2017, 22:01:27.000 956.083 0.022 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 952.644 0.081 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 940.531 0.019 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 936.136 0.01 h2 408 /v1.1/upgrade/check
April 25th 2017, 22:01:27.000 942.604 0.019 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 945.977 0.023 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 952.787 0.001 h2 408 /search/v3/config/tabs
April 25th 2017, 22:01:27.000 942.729 0.024 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 960.572 0.021 h2 408 /training/v2/running/facade/config?type=3x
April 25th 2017, 22:01:27.000 936.136 0.017 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 950.519 0.033 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 946.369 0.017 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 22:01:27.000 956.083 0.023 h2 408 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 21:50:20.000 0.001 0.001 h2 200 /v1.1/log/client?format=json&priority=normal
April 25th 2017, 21:45:28.000 0.004 0.004 200 /config/v2/basic
April 25th 2017, 21:45:21.000 0.022 0.022 h2 200 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 21:45:21.000 0.012 0.012 h2 200 /messenger/v2/conversations/unread
April 25th 2017, 21:45:21.000 0.019 0.019 h2 200 /search/v3/global?keyword=%E5%A4%A7%E8%85%BF&trainer_gender=f&limit=20
April 25th 2017, 21:45:20.000 0.008 0.008 h2 200 /messenger/v2/conversations/unread
April 25th 2017, 21:45:20.000 0.071 0.071 h2 200 /account/v2/dashboard
April 25th 2017, 21:45:20.000 0.017 0.017 h2 200 /training/v2/event/outdoor
April 25th 2017, 21:45:20.000 0.003 0.003 204 /v1.1/ads/splash?type=android
April 25th 2017, 21:45:20.000 0.015 0.015 h2 200 /social/v2/rankinglist/brief?date=20170425
April 25th 2017, 21:45:20.000 0.009 0.009 h2 200 /v1.1/home/dashboard/statistics
About this issue
- Original URL
- State: closed
- Created 7 years ago
- Comments: 21 (8 by maintainers)
I am also having the same issue with my react-native Android app which uses okhttp 3.8.1 when talking to nginx + HTTP/2. In our case with probability less than 0.1% it sends multiple requests to server. When it happens, we see 128 multiple requests in our access log within a second. The number is always 128 because our nginx and HTTP/2 rejects concurrent requests more than 128.
However, at the same time, we see a gigantic number of logs like below in our nginx error log. In a worse case, it records a million of lines of this error line from the same IP within a few minutes. I’m afraid it means user sends a very large number of requests.
By disabling HTTP/2, the problem disappeared. The strange thing is it only happens with POST and DELETE, though our app sends more GET and OPTIONS requests than POST and DELETE. It seems more likely to happen with slow APIs (image uploading for example).
@pacuum oooh, that’s helpful for debugging this. Perhaps we’re timing out client side and retrying on the same HTTP/2 connection?