tests: flaky HLS segment queue timing threshold test #5660
Description
The tests/stream/hls/test_hls.py::TestHLSStreamWorker::test_segment_queue_timing_threshold_reached_min test has failed a couple of times over the past few weeks now. Only fails on the Windows test runners (of course), despite this test not being relevant to Windows at all.
Added in: #5478
streamlink/tests/stream/hls/test_hls.py
Lines 374 to 420 in ed400e4
Recent CI failure:
https://github.com/streamlink/streamlink/actions/runs/6815777721/job/18535642382
Copying the log here since the log will expire in 90 days:
2023-11-09T18:16:05.1345245Z ================================== FAILURES ===================================
2023-11-09T18:16:05.1346435Z _____ TestHLSStreamWorker.test_segment_queue_timing_threshold_reached_min _____
2023-11-09T18:16:05.1347115Z
2023-11-09T18:16:05.1347965Z self = <tests.stream.hls.test_hls.TestHLSStreamWorker testMethod=test_segment_queue_timing_threshold_reached_min>
2023-11-09T18:16:05.1348944Z
2023-11-09T18:16:05.1349929Z def test_segment_queue_timing_threshold_reached_min(self) -> None:
2023-11-09T18:16:05.1350748Z thread, segments = self.subject(
2023-11-09T18:16:05.1351338Z start=False,
2023-11-09T18:16:05.1351818Z playlists=[
2023-11-09T18:16:05.1352887Z # no EXT-X-ENDLIST, last mocked playlist response will be repreated forever
2023-11-09T18:16:05.1354118Z Playlist(0, targetduration=1, segments=[Segment(0)]),
2023-11-09T18:16:05.1354883Z ],
2023-11-09T18:16:05.1355675Z )
2023-11-09T18:16:05.1356406Z worker: EventedHLSStreamWorker = thread.reader.worker
2023-11-09T18:16:05.1357154Z targetduration = ONE_SECOND
2023-11-09T18:16:05.1357701Z
2023-11-09T18:16:05.1358222Z with freezegun.freeze_time(EPOCH) as frozen_time, \
2023-11-09T18:16:05.1359448Z patch("streamlink.stream.hls.hls.log") as mock_log:
2023-11-09T18:16:05.1360185Z self.start()
2023-11-09T18:16:05.1361587Z
2023-11-09T18:16:05.1362443Z assert worker.handshake_reload.wait_ready(1), "Loads playlist for the first time"
2023-11-09T18:16:05.1363858Z assert worker.playlist_sequence == -1, "Initial sequence number"
2023-11-09T18:16:05.1365188Z assert worker.playlist_sequence_last == EPOCH, "Sets the initial last queue time"
2023-11-09T18:16:05.1366198Z
2023-11-09T18:16:05.1366728Z # first playlist reload has taken one second
2023-11-09T18:16:05.1367820Z frozen_time.tick(ONE_SECOND)
2023-11-09T18:16:05.1368472Z self.await_playlist_reload(1)
2023-11-09T18:16:05.1369040Z
2023-11-09T18:16:05.1369714Z assert worker.handshake_wait.wait_ready(1), "Arrives at wait() call #1"
2023-11-09T18:16:05.1370802Z assert worker.playlist_sequence == 1, "Updates the sequence number"
2023-11-09T18:16:05.1371999Z assert worker.playlist_sequence_last == EPOCH + ONE_SECOND, "Updates the last queue time"
2023-11-09T18:16:05.1373429Z assert worker.playlist_targetduration == 1.0
2023-11-09T18:16:05.1374170Z
2023-11-09T18:16:05.1374606Z for num in range(2, 7):
2023-11-09T18:16:05.1375902Z # trigger next reload when the target duration has passed
2023-11-09T18:16:05.1376688Z frozen_time.tick(targetduration)
2023-11-09T18:16:05.1377370Z self.await_playlist_wait(1)
2023-11-09T18:16:05.1378036Z self.await_playlist_reload(1)
2023-11-09T18:16:05.1378603Z
2023-11-09T18:16:05.1379295Z assert worker.handshake_wait.wait_ready(1), f"Arrives at wait() call #{num}"
2023-11-09T18:16:05.1380398Z assert worker.playlist_sequence == 1, "Sequence number is unchanged"
2023-11-09T18:16:05.1381575Z assert worker.playlist_sequence_last == EPOCH + ONE_SECOND, "Last queue time is unchanged"
2023-11-09T18:16:05.1382870Z assert worker.playlist_targetduration == 1.0
2023-11-09T18:16:05.1383687Z
2023-11-09T18:16:05.1384190Z assert mock_log.warning.call_args_list == []
2023-11-09T18:16:05.1384826Z
2023-11-09T18:16:05.1385350Z # trigger next reload when the target duration has passed
2023-11-09T18:16:05.1386116Z frozen_time.tick(targetduration)
2023-11-09T18:16:05.1386751Z self.await_playlist_wait(1)
2023-11-09T18:16:05.1387339Z self.await_playlist_reload(1)
2023-11-09T18:16:05.1387896Z
2023-11-09T18:16:05.1388771Z > assert mock_log.warning.call_args_list == [call("No new segments in playlist for more than 5.00s. Stopping...")]
2023-11-09T18:16:05.1390340Z E AssertionError: assert [call('No new...Stopping...')] == [call('No new...Stopping...')]
2023-11-09T18:16:05.1391229Z E Full diff:
2023-11-09T18:16:05.1392105Z E [call('No new segments in playlist for more than 5.00s. Stopping...')]
2023-11-09T18:16:05.1393296Z
2023-11-09T18:16:05.1393666Z tests\stream\hls\test_hls.py:420: AssertionError
2023-11-09T18:16:05.1394531Z ============================== warnings summary ===============================
2023-11-09T18:16:05.1395859Z C:\hostedtoolcache\windows\Python\3.12.0\x64\Lib\site-packages\dateutil\tz\tz.py:37
2023-11-09T18:16:05.1399864Z C:\hostedtoolcache\windows\Python\3.12.0\x64\Lib\site-packages\dateutil\tz\tz.py:37: DeprecationWarning: datetime.datetime.utcfromtimestamp() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.fromtimestamp(timestamp, datetime.UTC).
2023-11-09T18:16:05.1403323Z EPOCH = datetime.datetime.utcfromtimestamp(0)
2023-11-09T18:16:05.1403916Z
2023-11-09T18:16:05.1404294Z tests/webbrowser/test_chromium.py: 4 warnings
2023-11-09T18:16:05.1405087Z tests/webbrowser/test_webbrowser.py: 4 warnings
2023-11-09T18:16:05.1405868Z tests/webbrowser/cdp/test_client.py: 26 warnings
2023-11-09T18:16:05.1406690Z tests/webbrowser/cdp/test_connection.py: 26 warnings
2023-11-09T18:16:05.1410850Z C:\hostedtoolcache\windows\Python\3.12.0\x64\Lib\site-packages\trio\_core\_wakeup_socketpair.py:55: RuntimeWarning: It looks like Trio's signal handling code might have collided with another library you're using. If you're running Trio in guest mode, then this might mean you should set host_uses_signal_set_wakeup_fd=True. Otherwise, file a bug on Trio and we'll help you figure out what's going on.
2023-11-09T18:16:05.1414232Z warnings.warn(
2023-11-09T18:16:05.1414631Z
2023-11-09T18:16:05.1415334Z -- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
2023-11-09T18:16:05.1416254Z
2023-11-09T18:16:05.1416794Z ---------- coverage: platform win32, python 3.12.0-final-0 -----------
2023-11-09T18:16:05.1417843Z Coverage XML written to file coverage.xml
2023-11-09T18:16:05.1418357Z
2023-11-09T18:16:05.1419160Z ============================ slowest 10 durations =============================
2023-11-09T18:16:05.1421962Z 0.92s call tests/plugins/test_twitch.py::TestTwitchHLSStream::test_hls_low_latency_has_prefetch_disable_ads_has_preroll
2023-11-09T18:16:05.1424426Z 0.87s call tests/plugins/test_twitch.py::TestTwitchHLSStream::test_hls_low_latency_has_prefetch_disable_ads_no_preroll_with_prefetch_ads
2023-11-09T18:16:05.1426229Z 0.87s call tests/plugins/test_twitch.py::TestTwitchHLSStream::test_hls_low_latency_has_prefetch_has_preroll
2023-11-09T18:16:05.1427995Z 0.79s call tests/cli/test_main.py::TestCLIMainLoggingInfos::test_log_current_versions
2023-11-09T18:16:05.1429525Z 0.70s call tests/stream/hls/test_hls_filtered.py::TestFilteredHLSStream::test_filtered_logging
2023-11-09T18:16:05.1431035Z 0.69s call tests/cli/test_main.py::TestCLIMainLoggingInfos::test_log_current_arguments
2023-11-09T18:16:05.1432330Z 0.68s call tests/plugins/test_twitch.py::TestTwitchHLSStream::test_hls_low_latency_has_prefetch
2023-11-09T18:16:05.1434842Z 0.64s call tests/stream/hls/test_hls.py::TestHLSStreamByterange::test_offsets
2023-11-09T18:16:05.1436296Z 0.63s call tests/stream/hls/test_hls.py::TestHLSStreamEncrypted::test_hls_encrypted_aes128_incorrect_padding_content
2023-11-09T18:16:05.1437782Z 0.62s call tests/stream/hls/test_hls.py::TestHlsPlaylistParseErrors::test_reload
2023-11-09T18:16:05.1447071Z =========================== short test summary info ===========================
2023-11-09T18:16:05.9570617Z SKIPPED [32] tests\conftest.py:61: only applicable on a POSIX OS
2023-11-09T18:16:05.9573754Z FAILED tests/stream/hls/test_hls.py::TestHLSStreamWorker::test_segment_queue_timing_threshold_reached_min - AssertionError: assert [call('No new...Stopping...')] == [call('No new...Stopping...')]
2023-11-09T18:16:05.9581994Z Full diff:
2023-11-09T18:16:05.9583130Z [call('No new segments in playlist for more than 5.00s. Stopping...')]
2023-11-09T18:16:05.9584146Z ===== 1 failed, 6222 passed, 32 skipped, 61 warnings in 89.37s (0:01:29) ======
No idea why the assertion fails. The diff doesn't show any differences.
2023-11-09T18:16:05.1390340Z E AssertionError: assert [call('No new...Stopping...')] == [call('No new...Stopping...')] 2023-11-09T18:16:05.1391229Z E Full diff: 2023-11-09T18:16:05.1392105Z E [call('No new segments in playlist for more than 5.00s. Stopping...')]