tests: flaky HLS segment queue timing threshold test

[bastimeyer]

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

	def test_segment_queue_timing_threshold_reached_min(self) -> None:
	thread, segments = self.subject(
	start=False,
	playlists=[
	# no EXT-X-ENDLIST, last mocked playlist response will be repreated forever
	Playlist(0, targetduration=1, segments=[Segment(0)]),
	],
	)
	worker: EventedHLSStreamWorker = thread.reader.worker
	targetduration = ONE_SECOND
	with freezegun.freeze_time(EPOCH) as frozen_time, \
	patch("streamlink.stream.hls.hls.log") as mock_log:
	self.start()
	assert worker.handshake_reload.wait_ready(1), "Loads playlist for the first time"
	assert worker.playlist_sequence == -1, "Initial sequence number"
	assert worker.playlist_sequence_last == EPOCH, "Sets the initial last queue time"
	# first playlist reload has taken one second
	frozen_time.tick(ONE_SECOND)
	self.await_playlist_reload(1)
	assert worker.handshake_wait.wait_ready(1), "Arrives at wait() call #1"
	assert worker.playlist_sequence == 1, "Updates the sequence number"
	assert worker.playlist_sequence_last == EPOCH + ONE_SECOND, "Updates the last queue time"
	assert worker.playlist_targetduration == 1.0
	for num in range(2, 7):
	# trigger next reload when the target duration has passed
	frozen_time.tick(targetduration)
	self.await_playlist_wait(1)
	self.await_playlist_reload(1)
	assert worker.handshake_wait.wait_ready(1), f"Arrives at wait() call #{num}"
	assert worker.playlist_sequence == 1, "Sequence number is unchanged"
	assert worker.playlist_sequence_last == EPOCH + ONE_SECOND, "Last queue time is unchanged"
	assert worker.playlist_targetduration == 1.0
	assert mock_log.warning.call_args_list == []
	# trigger next reload when the target duration has passed
	frozen_time.tick(targetduration)
	self.await_playlist_wait(1)
	self.await_playlist_reload(1)
	assert mock_log.warning.call_args_list == [call("No new segments in playlist for more than 5.00s. Stopping...")]

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...')]