Unrecoverable SocketTimeoutExceptions when playing live streams

[baiqindotfubotv]

This probably should be a bug report. But that template is too hard to edit.

All testing are based on media3 1.1.1 and okhttp 4.11.0.

Our live streams are based short DASH or HLS manifests of about two minutes long. So when users perform seeks on our programs, we need to create new stream urls and send them to exoPlayer. That means every time user seeks, we need to create a new MediaItem instance and call exoPlayer.setMediaItem() and exoPlayer.prepare().

Users have been reporting random network connection issues (not real network issues of course) and the only way to recover is to force kill and restart the app. I am also able to reproduce this issue randomly. It turns out exoPlayer randomly throws some SocketTimeoutExceptions if we perform exoPlayer.setMediaItem() and exoPlayer.prepare() repeatedly on the same exoPlayer instance.

media3 had this commit to workaround some issues in okhttp regarding thread interruption: 80928e7. But looks like media3 is still using thread interruptions here and there. For example:

https://github.com/androidx/media/blob/1.1.1/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/upstream/Loader.java#L386

https://github.com/androidx/media/blob/1.1.1/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/upstream/Loader.java#L293

The stack trace is:

Playback error
   androidx.media3.exoplayer.ExoPlaybackException: Source error
       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleIoException(ExoPlayerImplInternal.java:684)
       at androidx.media3.exoplayer.ExoPlayerImplInternal.handleMessage(ExoPlayerImplInternal.java:656)
       at android.os.Handler.dispatchMessage(Handler.java:102)
       at android.os.Looper.loopOnce(Looper.java:205)
       at android.os.Looper.loop(Looper.java:294)
       at android.os.HandlerThread.run(HandlerThread.java:67)
   Caused by: androidx.media3.datasource.HttpDataSource$HttpDataSourceException: java.net.SocketTimeoutException: timeout
       at androidx.media3.datasource.okhttp.OkHttpDataSource.read(OkHttpDataSource.java:413)
       at androidx.media3.datasource.StatsDataSource.read(StatsDataSource.java:94)
       at androidx.media3.exoplayer.source.chunk.DataChunk.load(DataChunk.java:98)
       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:415)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644)
       at java.lang.Thread.run(Thread.java:1012)
   Caused by: java.net.SocketTimeoutException: timeout
       at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.kt:675)
       at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.kt:684)
       at okhttp3.internal.http2.Http2Stream$FramingSource.read(Http2Stream.kt:379)
       at okhttp3.internal.connection.Exchange$ResponseBodySource.read(Exchange.kt:281)
       at okio.RealBufferedSource$inputStream$1.read(RealBufferedSource.kt:158)
       at androidx.media3.datasource.okhttp.OkHttpDataSource.readInternal(OkHttpDataSource.java:579)
       at androidx.media3.datasource.okhttp.OkHttpDataSource.read(OkHttpDataSource.java:406)
       at androidx.media3.datasource.StatsDataSource.read(StatsDataSource.java:94) 
       at androidx.media3.exoplayer.source.chunk.DataChunk.load(DataChunk.java:98) 
       at androidx.media3.exoplayer.upstream.Loader$LoadTask.run(Loader.java:415) 
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644) 
       at java.lang.Thread.run(Thread.java:1012)

I added some logging code in media3 1.1.1 so the line number doesn't match original 1.1.1 tag. The Loader.txt and OkhttpDataSource.txt are the modified source files.

Loader.txt
OkhttpDataSource.txt

The logcats.txt is the corresponding logcat printed when this issue is reproduced.

logcats.txt

I also added a break pointer at Thread.interrupt() method with stack trace dump and evaluation of expression at the start of Thread.interrupt method:
"At: " + System.currentTimeMillis() + " Thread " + Thread.currentThread().getId() + " " + Thread.currentThread().getName() + " try to interrupt " + this.getId() + " " + this.getName()
ThreadInterrupts.txt

When these SocketTimeoutExceptions happen, the data probably reaches the device correctly (since the 200 code and correct ResponseBody length). The method OkhttpDataSource.open parses out the 200 response code and correct body length. But when OkhttpDataSource.read is called, the method throws IOExceptions due to thread interruptions. I think when you call exoPlayer.prepare with new MediaItems frequently, there are some thread contentions.

For example, in the logcat file at 15:51:33.318, the call to OkhttpDataSource.open is successful with correct body length 16, but the following OkhttpDataSource.read is blocked and eventually causes a time out after 10 seconds.

What's the suggested way to work around these SocketTimeoutExceptions?

[icbaker]

Does this issue only reproduce with OkhttpDataSource or also DefaultHttpDataSource and/or CronetDataSource?

Please can you provide a complete way for us to reproduce the problem (i.e. media links, and ideally a fork of the demo app that performs the problematic series of setMediaItem and prepare calls that you're describing)?

[baiqindotfubotv]

The exception is in okhttp3.internal.http2.Http2Stream as you can see in the stacktrace, it is only reproducible with okhttp http2.

I am not able to reproduce it if I do

okhttpClientBuilder.protocols(listOf(Protocol.HTTP_1_1))

or

okhttpClientBuilder.connectionPool(ConnectionPool(0, 1, TimeUnit.MILLISECONDS)) as described here: square/okhttp#3146 (comment)

[baiqindotfubotv]

Does this issue only reproduce with OkhttpDataSource or also DefaultHttpDataSource and/or CronetDataSource?

Please can you provide a complete way for us to reproduce the problem (i.e. media links, and ideally a fork of the demo app that performs the problematic series of setMediaItem and prepare calls that you're describing)?

In media3 1.1.1, change USE_CRONET_FOR_NETWORKING to false and

change
httpDataSourceFactory = new DefaultHttpDataSource.Factory();

to

OkHttpClient okHttpClient = new OkHttpClient.Builder().build();
httpDataSourceFactory = new OkHttpDataSource.Factory(okHttpClient);

change minSdkVersion to 21. Connect to charles proxy, play "UHD (MP4, H265)". Do some seeks, same crash happen.
Since this comment doesn't support charles log type. I will send an email.

[icbaker]

I'm not able to reproduce this in the demo app using the provided instructions. I seeked around a lot in 'UHD (MP4, H265)' and didn't generate any playback errors.

[icbaker]

Please can you try reproducing with okhttp 4.12? It mentions some possibly-related changes in the release notes. (I'm still unable to repro with 4.11)

[baiqindotfubotv]

Ok I can try okhttp 4.12. Can you try to connect to charles proxy and may add some throttling? On my side some times I cannot reproduce once for several hours. Sometimes it just happens 10 seconds after playback. I think that's the nature of thread contention issues.

[baiqindotfubotv]

Yes it is still reproducible with 4.12.0 in media3 demo.