Preloading is not happening early enough
When scheduling streams or files the preloading functionality is happening too late i.e. when the actually playout should be happening:
2021-07-05 12:24:16,731:AuraEngine:INFO - Finished fetching current programme from API (3 timeslots) - [programme.py:80-refresh()]
2021-07-05 12:24:16,735:AuraEngine:INFO - For now, skipped 2 future timeslot(s) which are out of the scheduling window (T¹-60s to T²-60s) - [scheduler.py:383-filter_scheduling_window()]
2021-07-05 12:24:16,736:AuraEngine:INFO - Fading out timeslot in 1625480998.5 seconds at 2021-07-05 12:30:00 | Timeslot: ID#406 [Show: Musikprogramm, ShowID: 1 | 12:25:00 - 12:30:00 ] - [scheduler.py:426-__init__()]
2021-07-05 12:25:00,237:AuraEngine:INFO - === on_timeslot_start('ID#406 [Show: Musikprogramm, ShowID: 1 | 12:25:00 - 12:30:00 ]') === - [scheduler.py:436-do_start_timeslot()]
2021-07-05 12:25:00,237:AuraEngine:INFO - Active timeslot used for trackservice 'ID#406 [Show: Musikprogramm, ShowID: 1 | 12:25:00 - 12:30:00 ]' - [trackservice.py:61-on_timeslot_start()]
2021-07-05 12:25:00,239:AuraEngine:INFO - There is no timeslot- or show-fallback defined for timeslot#406. The station fallback will be used automatically. - [fallback.py:192-queue_fallback_playlist()]
2021-07-05 12:25:00,239:AuraEngine:INFO - Built 1 entry group(s) - [scheduler.py:343-queue_playlist_entries()]
2021-07-05 12:25:00,240:AuraEngine:ERROR - Timer 'PRELOAD:do_preload:1625480685.0' is due in the past. Executing immediately ... - [control.py:243-__init__()]
2021-07-05 12:25:00,240:AuraEngine:INFO - === preload_group('PlaylistEntry #28 [12:25:00 - 12:43:53 | 1133sec | Source: ...file://musikprogramm/7], PlaylistEntry #29 [12:43:53 - 12:58:18 | 865sec | Source: ...file://musikprogramm/8]') === - [scheduler.py:488-do_preload()]
2021-07-05 12:25:00,240:AuraEngine:INFO - Swapped queue channel from A > B - [channels.py:261-channel_swap()]
2021-07-05 12:25:00,241:AuraEngine:INFO - Loading entry 'PlaylistEntry #28 [12:25:00 - 12:43:53 | 1133sec | Source: ...file://musikprogramm/7]' - [engine.py:281-preload_group()]
2021-07-05 12:25:00,241:AuraEngine:ERROR - Timer 'PLAY:do_play:1625480700.0' is due in the past. Executing immediately ... - [control.py:243-__init__()]
2021-07-05 12:25:00,241:AuraEngine:INFO - === play('PlaylistEntry #28 [12:25:00 - 12:43:53 | 1133sec | Source: ...file://musikprogramm/7], PlaylistEntry #29 [12:43:53 - 12:58:18 | 865sec | Source: ...file://musikprogramm/8]') === - [scheduler.py:504-do_play()]
2021-07-05 12:25:00,241:AuraEngine:INFO - Finished queuing programme. - [scheduler.py:269-queue_programme()]
2021-07-05 12:25:00,241:AuraEngine:CRITICAL - PLAY: The entry/entries are not yet ready to be played (Entries: PlaylistEntry #28 [12:25:00 - 12:43:53 | 1133sec | Source: ...file://musikprogramm/7], PlaylistEntry #29 [12:43:53 - 12:58:18 | 865sec | Source: ...file://musikprogramm/8]) - [scheduler.py:507-do_play()]
2021-07-05 12:25:00,241:AuraEngine:INFO - in_filesystem_1.queue_push('/home/david/Code/aura/engine/audio/source/musikprogramm/7.flac') - [engine.py:543-queue_push()]
2021-07-05 12:25:00,241:AuraEngine:INFO -
[ ENGINE COMMAND QUEUE ]
=> [TIMESLOT:do_start_timeslot:1625480700.0] exec at 2021-07-05 12:25:00.236984 (alive: False)
=> [TIMESLOT:do_end_timeslot:1625480998.5] exec at 2021-07-05 12:29:58.237792 (alive: True)
=> [PRELOAD:do_preload:1625480685.0] exec at 2021-07-05 12:24:44.740595 (alive: False)
=> [PLAY:do_play:1625480700.0] exec at 2021-07-05 12:24:59.741067 (alive: False)
- [control.py:396-log_commands()]
2021-07-05 12:25:00,241:AuraEngine:INFO - PLAY: Wait a little until preloading is done ... - [scheduler.py:509-do_play()]
2021-07-05 12:25:00,246:AuraEngine:INFO - in_filesystem_1.queue_push result: 6 - [engine.py:545-queue_push()]
2021-07-05 12:25:00,247:AuraEngine:INFO - Loading entry 'PlaylistEntry #29 [12:43:53 - 12:58:18 | 865sec | Source: ...file://musikprogramm/8]' - [engine.py:281-preload_group()]
2021-07-05 12:25:00,247:AuraEngine:INFO - in_filesystem_1.queue_push('/home/david/Code/aura/engine/audio/source/musikprogramm/8.flac') - [engine.py:543-queue_push()]
2021-07-05 12:25:00,256:AuraEngine:INFO - in_filesystem_1.queue_push result: 7 - [engine.py:545-queue_push()]
2021-07-05 12:25:02,245:AuraEngine:INFO - Starting to fading-in 'in_filesystem_1'. Step is 0.015s and target volume is 100. - [mixer.py:358-fade_in()]
2021-07-05 12:25:02,336:AuraEngine:INFO - Resolved 'ResourceType.FILE' entry 'PlaylistEntry #28 [12:25:00 - 12:43:53 | 1133sec | Source: ...file://musikprogramm/7]' for URI '/home/david/Code/aura/engine/audio/source/musikprogramm/7.flac' - [trackservice.py:414-resolve_entry()]
2021-07-05 12:25:02,336:AuraEngine:INFO - [ECI] Event 'on_metadata' issued successfully - [control.py:164-process()]
2021-07-05 12:25:02,338:AuraEngine:INFO - Posting playlog to Engine API... - [trackservice.py:167-store_trackservice()]
2021-07-05 12:25:02,348:AuraEngine:INFO - Posting clock info update to Engine API... - [trackservice.py:217-store_clock_info()]
2021-07-05 12:25:03,808:AuraEngine:INFO - Finished with fading-in 'in_filesystem_1'. - [mixer.py:369-fade_in()]