Error while scheduling stream, logs crowded with redundant "Wait a Little Bit Until Preloading Is Done..." messages

When scheduling a stream (http://stream.fro.at:8008/fro-128.ogg), I get an error:

engine                 | 2024-02-22 12:42:44,816:engine:INFO - === preload('PlaylistEntry #5 [12:43:00 - 12:45:00 | 120.0sec | Source: ...m.fro.at:8008/fro-128.ogg]') === - [scheduler.py:550-do_preload()]
engine                 | 2024-02-22 12:42:44,816:engine:INFO - Got free 'http' channel 'in_stream_0' - [mixer.py:150-get_free_channel()]
engine                 | 2024-02-22 12:42:44,816:engine:INFO - Assign channel [2 : in_stream_0] to entry - [engine.py:318-preload()]
engine                 | 2024-02-22 12:42:44,819:engine:INFO - in_stream_0.start result: Done! - [channels.py:529-start()]
engine                 | 2024-02-22 12:42:44,820:engine:INFO - in_stream_0.status result: polling - [channels.py:482-is_ready()]
engine                 | Exception in thread PRELOAD#10:do_preload:2024-02-22_12:42:45:
engine                 | Traceback (most recent call last):
engine                 |   File "/usr/local/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
engine                 |     self.run()
engine                 |   File "/usr/local/lib/python3.10/threading.py", line 1378, in run
engine                 |     self.function(*self.args, **self.kwargs)
engine                 |   File "/srv/src/aura_engine/control.py", line 166, in wrapper_func
engine                 |     self.func(
engine                 |   File "/srv/src/aura_engine/scheduling/scheduler.py", line 551, in do_preload
engine                 |     self.engine.player.preload(entries[0])
engine                 |   File "/srv/src/aura_engine/engine.py", line 320, in preload
engine                 |     is_ready = entry.channel.load(uri, metadata=metadata)
engine                 |   File "/srv/src/aura_engine/core/channels.py", line 452, in load
engine                 |     if retries >= max_retries:
engine                 | TypeError: '>=' not supported between instances of 'int' and 'NoneType'

As a result engine keeps logging this continously:

engine                 | 2024-02-22 12:57:54,734:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-02-22 12:57:56,737:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-02-22 12:57:58,737:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-02-22 12:58:00,740:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-02-22 12:58:02,741:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]

---

Original ticket description, which had the same cause:

The log file of engine is experiencing an overflow of repetitive log entries containing the message PLAY: Wait a little bit until preloading is done .... I left engine running over night and hat 73 000 entries of only this message. This excessive logging is making it challenging to identify other important log information. I would suggest to optimize the logging to maintain clarity in the log file.

assigned to @Loxbie

2023-07-26: @chrizz and @Loxbie will discuss and add details on the bug.

assigned to @chrizz and unassigned @Loxbie

changed milestone to %1.0-alpha3 — Playful Platypus

added 1 deleted label

added To Do label

added 1 deleted label and removed 1 deleted label

added Doing label and removed To Do label

Just started this issue to get a better understanding of all these engine components and their interaction...

mentioned in issue engine-core#57 (closed)

I remember some redundant log messages in the dockerized alpha2-deployment but couldn't reproduce this issue yet by running engine and engine-core locally. Thus needs further investigation.

Beside that, I got stuck in another issue engine-core#57 (closed) which we should discuss related to pipewire/jack.

added 1 deleted label

mentioned in merge request !27 (merged)

mentioned in commit f0f3d9b7

closed

removed Doing label

reopened

changed title from Log File Crowded with Redundant "Wait a Little Bit Until Preloading Is Done..." Messages to Error while scheduling stream, logs crowded with redundant "Wait a Little Bit Until Preloading Is Done..." messages

changed milestone to %1.0-alpha4 — Raving Raccoon

added P1 bug labels

marked this issue as related to #100 (closed)

@chrizz I assume the config variable for max_retries is not correctly passed into Engine:

if retries >= max_retries:
engine                 | TypeError: '>=' not supported between instances of 'int' and 'NoneType'

Jup, there are some settings left in the old ini format.

Thanks for checking. So maybe it's an easy fix still in alpha-3 for @chrizz? But alpha-4 is surely fine too.

It's fixed in fe2c9438 but need to await aura-web fixes before testing...

mentioned in issue aura#285 (closed)

changed the description

changed the description

I didn't encouter redundant Wait a little bit until preloading is done messages anymore after fixing the line-in-selection issue, so could we close this ticket after sucessful testing?

This is not related to line-in but to scheduling streams.

See new testcase

mentioned in merge request !32 (merged)

changed milestone to %1.0-alpha3 — Playful Platypus

added 1 deleted label

added Doing label

added Blocked label and removed Doing label

added Doing label and removed Blocked label

Successfully tested in combination with aura-web. Scheduled the FRO livestream and playout started as expected.

engine  | 2024-02-23T16:04:20.869308041Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:04:20.869310630Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:05:00.366405             (alive: True, updates: 0)
engine  | 2024-02-23T16:04:20.869320017Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:59] exec at 2024-02-23 17:14:58.866613             (alive: True, updates: 0)
engine  | 2024-02-23T16:04:20.869322914Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:45.368510             (alive: True, updates: 0)
engine  | 2024-02-23T16:04:20.869325415Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:05:00.368912             (alive: True, updates: 0)
engine  | 2024-02-23T16:04:20.869327817Z
engine  | 2024-02-23T16:04:20.869330094Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:04:45.369380498Z 2024-02-23 17:04:45,369:engine:INFO - === preload('PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]') === - [scheduler.py:550-do_preload()]
engine  | 2024-02-23T16:04:45.372442160Z 2024-02-23 17:04:45,372:engine:DEBUG - Loading entry 'PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]' - [engine.py:294-preload()]
engine  | 2024-02-23T16:04:45.372465458Z 2024-02-23 17:04:45,372:engine:INFO - Got free 'http' channel 'in_stream_0' - [mixer.py:150-get_free_channel()]
engine  | 2024-02-23T16:04:45.372630935Z 2024-02-23 17:04:45,372:engine:INFO - Assign channel [2 : in_stream_0] to entry - [engine.py:318-preload()]
engine  | 2024-02-23T16:04:45.372689768Z 2024-02-23 17:04:45,372:engine:DEBUG - Loading stream 'http://stream.fro.at:8008/fro-128.ogg' - [channels.py:442-load()]
engine  | 2024-02-23T16:04:45.375439061Z 2024-02-23 17:04:45,375:engine:DEBUG - [>>] in_stream_0.stop - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.376486420Z 2024-02-23 17:04:45,376:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.377167963Z 2024-02-23 17:04:45,377:engine:DEBUG - [>>] in_stream_0.url http://stream.fro.at:8008/fro-128.ogg - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.378099658Z 2024-02-23 17:04:45,378:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.379021189Z 2024-02-23 17:04:45,378:engine:DEBUG - [>>] in_stream_0.start - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.380062980Z 2024-02-23 17:04:45,379:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.380156964Z 2024-02-23 17:04:45,380:engine:INFO - in_stream_0.start result: Done! - [channels.py:529-start()]
engine  | 2024-02-23T16:04:45.381059903Z 2024-02-23 17:04:45,380:engine:DEBUG - [>>] in_stream_0.status - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.382483059Z 2024-02-23 17:04:45,382:engine:DEBUG - [<<] polling - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:45.382527336Z 2024-02-23 17:04:45,382:engine:INFO - in_stream_0.status result: polling - [channels.py:482-is_ready()]
engine  | 2024-02-23T16:04:50.872316956Z 2024-02-23 17:04:50,871:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine  | 2024-02-23T16:04:50.872386357Z 2024-02-23 17:04:50,872:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine  | 2024-02-23T16:04:50.873432462Z 2024-02-23 17:04:50,872:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine  | 2024-02-23T16:04:50.874631391Z 2024-02-23 17:04:50,874:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine  | 2024-02-23T16:04:50.962469262Z 2024-02-23 17:04:50,961:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine  | 2024-02-23T16:04:50.963571153Z 2024-02-23 17:04:50,963:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine  | 2024-02-23T16:04:50.965057649Z 2024-02-23 17:04:50,964:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:04:50.976590237Z 2024-02-23 17:04:50,976:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:04:50.991380973Z 2024-02-23 17:04:50,990:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-02-23T17:15:00', 'repetitionOfId': None, 'scheduleId': 16, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 2, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'Sinüsse', 'showTopics': '', 'showType': 'Experimentell', 'start': '2024-02-23T17:05:00', 'title': 'Sinüsse', 'timeslot_id': 16, 'playlist_id': 14, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': {'id': 14, 'created': '2024-02-23T17:02:08.280539+01:00', 'updated': '2024-02-23T17:02:08.304684+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-02-20T20:18:07.930814+01:00', 'updated': '2024-02-22T23:31:09.697848+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine  | 2024-02-23T16:04:50.999440651Z 2024-02-23 17:04:50,998:engine:DEBUG - Storing playlist 14 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:04:51.006537321Z 2024-02-23 17:04:51,006:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:04:51.017696538Z 2024-02-23 17:04:51,017:engine:DEBUG - Storing playlist 1 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:04:51.022543682Z 2024-02-23 17:04:51,022:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:04:51.029456960Z 2024-02-23 17:04:51,029:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine  | 2024-02-23T16:04:51.031392094Z 2024-02-23 17:04:51,031:engine:INFO - For now, skipped 0 future timeslot(s) which are out of the scheduling window (T¹-60s to T²-60s) - [scheduler.py:405-filter_scheduling_window()]
engine  | 2024-02-23T16:04:51.031703539Z 2024-02-23 17:04:51,031:engine:DEBUG - Fading in timeslot in 9.0 seconds at 17:05:00 | Timeslot: ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [scheduler.py:451-__init__()]
engine  | 2024-02-23T16:04:51.031846714Z 2024-02-23 17:04:51,031:engine:DEBUG - Fading out timeslot in 607.5 seconds at 17:14:58 | Timeslot: ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [scheduler.py:455-__init__()]
engine  | 2024-02-23T16:04:51.032161509Z 2024-02-23 17:04:51,031:engine:DEBUG - Cancelling existing timer with ID: TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00 - [control.py:210-update_store()]
engine  | 2024-02-23T16:04:51.032346688Z 2024-02-23 17:04:51,032:engine:DEBUG - Stored command timer with ID: TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00 - [control.py:215-update_store()]
engine  | 2024-02-23T16:04:51.032586776Z 2024-02-23 17:04:51,032:engine:DEBUG - Timer 'TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00' to be executed in default manner - [control.py:117-__init__()]
engine  | 2024-02-23T16:04:51.033131538Z 2024-02-23 17:04:51,032:engine:DEBUG - Stored command timer with ID: TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58 - [control.py:215-update_store()]
engine  | 2024-02-23T16:04:51.033390865Z 2024-02-23 17:04:51,033:engine:DEBUG - Timer 'TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58' to be executed in default manner - [control.py:117-__init__()]
engine  | 2024-02-23T16:04:51.037160880Z 2024-02-23 17:04:51,036:engine:INFO - Built 1 entry group(s) - [scheduler.py:359-queue_playlist_entries()]
engine  | 2024-02-23T16:04:51.037348582Z 2024-02-23 17:04:51,037:engine:INFO - Preloading entries at 17:04:45, 15 seconds before playing it at 17:05:00 - [scheduler.py:533-__init__()]
engine  | 2024-02-23T16:04:51.039274217Z 2024-02-23 17:04:51,038:engine:DEBUG - Cancelling existing timer with ID: PRELOAD#16:do_preload:2024-02-23_17:04:45 - [control.py:210-update_store()]
engine  | 2024-02-23T16:04:51.039339975Z 2024-02-23 17:04:51,039:engine:DEBUG - Stored command timer with ID: PRELOAD#16:do_preload:2024-02-23_17:04:45 - [control.py:215-update_store()]
engine  | 2024-02-23T16:04:51.039588623Z 2024-02-23 17:04:51,039:engine:WARNING - Timer 'PRELOAD#16:do_preload:2024-02-23_17:04:45' is due in the past. Executing immediately ... - [control.py:110-__init__()]
engine  | 2024-02-23T16:04:51.040593224Z 2024-02-23 17:04:51,040:engine:INFO - === preload('PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]') === - [scheduler.py:550-do_preload()]
engine  | 2024-02-23T16:04:51.041603343Z 2024-02-23 17:04:51,040:engine:DEBUG - Parent finished, leave the existing child alone. - [control.py:204-update_store()]
engine  | 2024-02-23T16:04:51.041767414Z 2024-02-23 17:04:51,041:engine:INFO - Timer 'PLAY#16:do_play:2024-02-23_17:05:00' omitted cuz it already exists but is dead - [control.py:105-__init__()]
engine  | 2024-02-23T16:04:51.041989640Z 2024-02-23 17:04:51,041:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine  | 2024-02-23T16:04:51.043115649Z 2024-02-23 17:04:51,042:engine:DEBUG - Loading entry 'PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]' - [engine.py:294-preload()]
engine  | 2024-02-23T16:04:51.043643121Z 2024-02-23 17:04:51,042:engine:INFO -
engine  | 2024-02-23T16:04:51.043669758Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:04:51.043679050Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.531826             (alive: True, updates: 1)
engine  | 2024-02-23T16:04:51.043687988Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58] exec at 2024-02-23 17:14:58.032785             (alive: True, updates: 0)
engine  | 2024-02-23T16:04:51.043712160Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:44.538873             (alive: False, updates: 1)
engine  | 2024-02-23T16:04:51.043721238Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.540230             (alive: False, updates: 0)
engine  | 2024-02-23T16:04:51.043729407Z
engine  | 2024-02-23T16:04:51.043737276Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:04:51.043856382Z 2024-02-23 17:04:51,043:engine:INFO - Got free 'http' channel 'in_stream_0' - [mixer.py:150-get_free_channel()]
engine  | 2024-02-23T16:04:51.044238623Z 2024-02-23 17:04:51,043:engine:INFO - Assign channel [2 : in_stream_0] to entry - [engine.py:318-preload()]
engine  | 2024-02-23T16:04:51.044267772Z 2024-02-23 17:04:51,043:engine:DEBUG - Loading stream 'http://stream.fro.at:8008/fro-128.ogg' - [channels.py:442-load()]
engine  | 2024-02-23T16:04:51.046983129Z 2024-02-23 17:04:51,046:engine:DEBUG - [>>] in_stream_0.stop - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.050182766Z 2024-02-23 17:04:51,049:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.052803243Z 2024-02-23 17:04:51,052:engine:DEBUG - [>>] in_stream_0.url http://stream.fro.at:8008/fro-128.ogg - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.055886817Z 2024-02-23 17:04:51,055:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.057807983Z 2024-02-23 17:04:51,057:engine:DEBUG - [>>] in_stream_0.start - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.060093666Z 2024-02-23 17:04:51,059:engine:DEBUG - [<<] Done! - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.060171113Z 2024-02-23 17:04:51,060:engine:INFO - in_stream_0.start result: Done! - [channels.py:529-start()]
engine  | 2024-02-23T16:04:51.061595852Z 2024-02-23 17:04:51,061:engine:DEBUG - [>>] in_stream_0.status - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.063547752Z 2024-02-23 17:04:51,063:engine:DEBUG - [<<] polling - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:51.063627264Z 2024-02-23 17:04:51,063:engine:INFO - in_stream_0.status result: polling - [channels.py:482-is_ready()]
engine  | 2024-02-23T16:04:55.395959309Z 2024-02-23 17:04:55,395:engine:DEBUG - [>>] in_stream_0.status - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:55.397938058Z 2024-02-23 17:04:55,397:engine:DEBUG - [<<] connected http://stream.fro.at:8008/fro-128.ogg - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:55.397978241Z 2024-02-23 17:04:55,397:engine:INFO - in_stream_0.status result: connected http://stream.fro.at:8008/fro-128.ogg - [channels.py:482-is_ready()]
engine  | 2024-02-23T16:04:55.398103731Z 2024-02-23 17:04:55,397:engine:INFO - Ready to play stream, but wait 3.0 seconds to fill buffer... - [channels.py:496-is_ready()]
engine  | 2024-02-23T16:04:58.404435093Z 2024-02-23 17:04:58,403:engine:DEBUG - [>>] in_stream_0.set_track_metadata {"show_name": "Sinüsse", "show_id": 2, "timeslot_id": 16, "playlist_id": 14, "playlist_item": "0.0", "track_type": 1, "track_start": "2024/02/23 17:05:00", "track_duration": 600.0, "track_title": "", "track_album": "", "track_artist": ""} - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:58.406026020Z 2024-02-23 17:04:58,405:engine:DEBUG - [<<] OK - [client.py:160-log_debug()]
engine  | 2024-02-23T16:04:58.406069807Z 2024-02-23 17:04:58,405:engine:INFO - Response for 'in_stream_0.set_track_metadata': OK - [channels.py:303-set_track_metadata()]
engine  | 2024-02-23T16:04:58.406147525Z 2024-02-23 17:04:58,406:engine:ERROR - Successfully loaded entry 'PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg] - [engine.py:323-preload()]
engine  | 2024-02-23T16:04:58.406390103Z 2024-02-23 17:04:58,406:engine:DEBUG - on_queue(..) - [events.py:260-func()]
engine  | 2024-02-23T16:04:59.533686403Z 2024-02-23 17:04:59,533:engine:INFO - === on_timeslot_start('ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ]') === - [scheduler.py:481-do_start_timeslot()]
engine  | 2024-02-23T16:04:59.534362160Z 2024-02-23 17:04:59,533:engine:DEBUG - on_timeslot_start(..) - [events.py:185-func()]
engine  | 2024-02-23T16:05:00.370217869Z 2024-02-23 17:05:00,369:engine:INFO - === play('PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]') === - [scheduler.py:564-do_play()]
engine  | 2024-02-23T16:05:00.371463459Z 2024-02-23 17:05:00,370:engine:INFO - Nothing to stop, no active channel - [engine.py:416-stop()]
engine  | 2024-02-23T16:05:00.371912502Z 2024-02-23 17:05:00,371:engine:INFO - Fade in channel [2 : in_stream_0] - [channels.py:244-fade_in()]
engine  | 2024-02-23T16:05:00.376008430Z 2024-02-23 17:05:00,375:engine:DEBUG - [>>] mixer.select 2 true - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:00.381569716Z 2024-02-23 17:05:00,381:engine:DEBUG - [<<] ready=true selected=true single=false volume=0% remaining=inf - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:00.388650748Z 2024-02-23 17:05:00,388:engine:DEBUG - [>>] mixer.status 2 - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:00.395205926Z 2024-02-23 17:05:00,394:engine:DEBUG - [<<] ready=true selected=true single=false volume=0% remaining=inf - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:00.397055078Z 2024-02-23 17:05:00,396:engine:DEBUG - Fade in of [2 : in_stream_0] to 100% (0.015s steps) - [mixer.py:244-fade_in()]
engine  | 2024-02-23T16:05:00.676338620Z 2024-02-23 17:05:00,675:engine:INFO - Playout turned back into normal state - [engine.py:145-update_playout_state()]
engine  | 2024-02-23T16:05:01.078782317Z 2024-02-23 17:05:01,078:engine:DEBUG - [>>] in_stream_0.status - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:01.082549377Z 2024-02-23 17:05:01,082:engine:DEBUG - [<<] connected http://stream.fro.at:8008/fro-128.ogg - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:01.082681139Z 2024-02-23 17:05:01,082:engine:INFO - in_stream_0.status result: connected http://stream.fro.at:8008/fro-128.ogg - [channels.py:482-is_ready()]
engine  | 2024-02-23T16:05:01.082852919Z 2024-02-23 17:05:01,082:engine:INFO - Ready to play stream, but wait 3.0 seconds to fill buffer... - [channels.py:496-is_ready()]
engine  | 2024-02-23T16:05:03.137161117Z 2024-02-23 17:05:03,136:engine:DEBUG - Fade in of [2 : in_stream_0] done - [mixer.py:249-fade_in()]
engine  | 2024-02-23T16:05:03.137829225Z 2024-02-23 17:05:03,137:engine:DEBUG - on_play(..) - [events.py:218-func()]
engine  | 2024-02-23T16:05:03.139477893Z 2024-02-23 17:05:03,138:engine:INFO -
engine  | 2024-02-23T16:05:03.139520892Z
engine  | 2024-02-23T16:05:03.139535654Z    SCHEDULED NOW:
engine  | 2024-02-23T16:05:03.139548237Z ┌──────────────────────────────────────────────────────────────────────────────────────────────────────
engine  | 2024-02-23T16:05:03.139563268Z │   Playing timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ]
engine  | 2024-02-23T16:05:03.139575464Z │       └── Playlist ID#14 [items: 1 | 17:05:00 - 17:15:00]
engine  | 2024-02-23T16:05:03.139587338Z │         └── Entry 1 | PLAYING > PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg]
engine  | 2024-02-23T16:05:03.139601613Z └──────────────────────────────────────────────────────────────────────────────────────────────────────
engine  | 2024-02-23T16:05:03.139615607Z    SCHEDULED NEXT:
engine  | 2024-02-23T16:05:03.139627113Z ┌──────────────────────────────────────────────────────────────────────────────────────────────────────
engine  | 2024-02-23T16:05:03.139640685Z │   Nothing.
engine  | 2024-02-23T16:05:03.139652363Z └──────────────────────────────────────────────────────────────────────────────────────────────────────
engine  | 2024-02-23T16:05:03.139666114Z
engine  | 2024-02-23T16:05:03.139677145Z  - [scheduler.py:578-do_play()]
engine  | 2024-02-23T16:05:03.139713264Z 2024-02-23 17:05:03,138:engine:INFO - PUT clock info to 'http://engine-api:8008/api/v1/clock':
engine  | 2024-02-23T16:05:03.139727043Z {'engineSource': 1, 'currentTimeslot': {'timeslotId': 16, 'timeslotStart': datetime.datetime(2024, 2, 23, 17, 5), 'timeslotEnd': datetime.datetime(2024, 2, 23, 17, 15), 'showId': 2, 'showName': 'Sinüsse', 'playlistId': 14, 'playlistType': 0}, 'upcomingTimeslots': [], 'plannedPlaylist': {'playlistId': 14, 'entries': [{'trackType': 1, 'trackStart': datetime.datetime(2024, 2, 23, 17, 5), 'trackNum': 0, 'trackDuration': 600.0}]}} - [clock.py:136-post_clock_info()]
engine  | 2024-02-23T16:05:03.140478082Z 2024-02-23 17:05:03,140:engine:INFO - Built JSON: {
engine  | 2024-02-23T16:05:03.140515198Z     "currentTimeslot": {
engine  | 2024-02-23T16:05:03.140530370Z         "playlistId": 14,
engine  | 2024-02-23T16:05:03.140542916Z         "playlistType": 0,
engine  | 2024-02-23T16:05:03.140554982Z         "showId": 2,
engine  | 2024-02-23T16:05:03.140590466Z         "showName": "Sin\u00fcsse",
engine  | 2024-02-23T16:05:03.140603597Z         "timeslotEnd": "2024-02-23 17:15:00",
engine  | 2024-02-23T16:05:03.140616608Z         "timeslotId": 16,
engine  | 2024-02-23T16:05:03.140628221Z         "timeslotStart": "2024-02-23 17:05:00"
engine  | 2024-02-23T16:05:03.140640067Z     },
engine  | 2024-02-23T16:05:03.140651073Z     "engineSource": 1,
engine  | 2024-02-23T16:05:03.140662366Z     "plannedPlaylist": {
engine  | 2024-02-23T16:05:03.140674159Z         "entries": [
engine  | 2024-02-23T16:05:03.140685526Z             {
engine  | 2024-02-23T16:05:03.140696710Z                 "trackDuration": 600.0,
engine  | 2024-02-23T16:05:03.140708512Z                 "trackNum": 0,
engine  | 2024-02-23T16:05:03.140720495Z                 "trackStart": "2024-02-23 17:05:00",
engine  | 2024-02-23T16:05:03.140732254Z                 "trackType": 1
engine  | 2024-02-23T16:05:03.140743562Z             }
engine  | 2024-02-23T16:05:03.140754505Z         ],
engine  | 2024-02-23T16:05:03.140765951Z         "playlistId": 14
engine  | 2024-02-23T16:05:03.140777304Z     },
engine  | 2024-02-23T16:05:03.140788063Z     "upcomingTimeslots": []
engine  | 2024-02-23T16:05:03.140800165Z } - [api.py:184-serialize_json()]
engine  | 2024-02-23T16:05:04.088815912Z 2024-02-23 17:05:04,088:engine:DEBUG - [>>] in_stream_0.set_track_metadata {"show_name": "Sinüsse", "show_id": 2, "timeslot_id": 16, "playlist_id": 14, "playlist_item": "0.0", "track_type": 1, "track_start": "2024/02/23 17:05:00", "track_duration": 600.0, "track_title": "", "track_album": "", "track_artist": ""} - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:04.102303176Z 2024-02-23 17:05:04,100:engine:DEBUG - [<<] OK - [client.py:160-log_debug()]
engine  | 2024-02-23T16:05:04.102315538Z 2024-02-23 17:05:04,100:engine:INFO - Response for 'in_stream_0.set_track_metadata': OK - [channels.py:303-set_track_metadata()]
engine  | 2024-02-23T16:05:04.102318743Z 2024-02-23 17:05:04,100:engine:ERROR - Successfully loaded entry 'PlaylistEntry #7 [17:05:00 - 17:15:00 | 600.0sec | Source: ...m.fro.at:8008/fro-128.ogg] - [engine.py:323-preload()]
engine  | 2024-02-23T16:05:04.102321320Z 2024-02-23 17:05:04,100:engine:DEBUG - on_queue(..) - [events.py:260-func()]
engine  | 2024-02-23T16:05:21.046608876Z 2024-02-23 17:05:21,046:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine  | 2024-02-23T16:05:21.046775268Z 2024-02-23 17:05:21,046:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine  | 2024-02-23T16:05:21.047568054Z 2024-02-23 17:05:21,047:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine  | 2024-02-23T16:05:21.048647818Z 2024-02-23 17:05:21,048:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine  | 2024-02-23T16:05:21.070538798Z 2024-02-23 17:05:21,070:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine  | 2024-02-23T16:05:21.070774941Z 2024-02-23 17:05:21,070:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine  | 2024-02-23T16:05:21.071148778Z 2024-02-23 17:05:21,071:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:05:21.074408602Z 2024-02-23 17:05:21,074:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:05:21.094222011Z 2024-02-23 17:05:21,094:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-02-23T17:15:00', 'repetitionOfId': None, 'scheduleId': 16, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 2, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'Sinüsse', 'showTopics': '', 'showType': 'Experimentell', 'start': '2024-02-23T17:05:00', 'title': 'Sinüsse', 'timeslot_id': 16, 'playlist_id': 14, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': {'id': 14, 'created': '2024-02-23T17:02:08.280539+01:00', 'updated': '2024-02-23T17:02:08.304684+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-02-20T20:18:07.930814+01:00', 'updated': '2024-02-22T23:31:09.697848+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine  | 2024-02-23T16:05:21.096414379Z 2024-02-23 17:05:21,096:engine:DEBUG - Storing playlist 14 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:05:21.098217122Z 2024-02-23 17:05:21,098:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:05:21.102025996Z 2024-02-23 17:05:21,101:engine:DEBUG - Storing playlist 1 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:05:21.103779940Z 2024-02-23 17:05:21,103:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:05:21.106353585Z 2024-02-23 17:05:21,106:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine  | 2024-02-23T16:05:21.107077353Z 2024-02-23 17:05:21,106:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine  | 2024-02-23T16:05:21.107161228Z 2024-02-23 17:05:21,107:engine:INFO -
engine  | 2024-02-23T16:05:21.107173256Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:05:21.107177323Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.531826             (alive: False, updates: 1)
engine  | 2024-02-23T16:05:21.107180563Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58] exec at 2024-02-23 17:14:58.032785             (alive: True, updates: 0)
engine  | 2024-02-23T16:05:21.107183702Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:44.538873             (alive: False, updates: 1)
engine  | 2024-02-23T16:05:21.107186719Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.540230             (alive: False, updates: 0)
engine  | 2024-02-23T16:05:21.107189683Z
engine  | 2024-02-23T16:05:21.107200999Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:05:51.110072385Z 2024-02-23 17:05:51,109:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine  | 2024-02-23T16:05:51.110196569Z 2024-02-23 17:05:51,109:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine  | 2024-02-23T16:05:51.111390884Z 2024-02-23 17:05:51,110:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine  | 2024-02-23T16:05:51.112346734Z 2024-02-23 17:05:51,111:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine  | 2024-02-23T16:05:51.137482172Z 2024-02-23 17:05:51,137:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine  | 2024-02-23T16:05:51.137700871Z 2024-02-23 17:05:51,137:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine  | 2024-02-23T16:05:51.137949298Z 2024-02-23 17:05:51,137:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:05:51.140500846Z 2024-02-23 17:05:51,140:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:05:51.144001683Z 2024-02-23 17:05:51,143:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-02-23T17:15:00', 'repetitionOfId': None, 'scheduleId': 16, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 2, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'Sinüsse', 'showTopics': '', 'showType': 'Experimentell', 'start': '2024-02-23T17:05:00', 'title': 'Sinüsse', 'timeslot_id': 16, 'playlist_id': 14, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': {'id': 14, 'created': '2024-02-23T17:02:08.280539+01:00', 'updated': '2024-02-23T17:02:08.304684+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-02-20T20:18:07.930814+01:00', 'updated': '2024-02-22T23:31:09.697848+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine  | 2024-02-23T16:05:51.145842665Z 2024-02-23 17:05:51,145:engine:DEBUG - Storing playlist 14 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:05:51.147320288Z 2024-02-23 17:05:51,147:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:05:51.150400776Z 2024-02-23 17:05:51,150:engine:DEBUG - Storing playlist 1 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:05:51.151874769Z 2024-02-23 17:05:51,151:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:05:51.153927078Z 2024-02-23 17:05:51,153:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine  | 2024-02-23T16:05:51.154455206Z 2024-02-23 17:05:51,154:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine  | 2024-02-23T16:05:51.154522297Z 2024-02-23 17:05:51,154:engine:INFO -
engine  | 2024-02-23T16:05:51.154548191Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:05:51.154551810Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.531826             (alive: False, updates: 1)
engine  | 2024-02-23T16:05:51.154554779Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58] exec at 2024-02-23 17:14:58.032785             (alive: True, updates: 0)
engine  | 2024-02-23T16:05:51.154557610Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:44.538873             (alive: False, updates: 1)
engine  | 2024-02-23T16:05:51.154560171Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.540230             (alive: False, updates: 0)
engine  | 2024-02-23T16:05:51.154562720Z
engine  | 2024-02-23T16:05:51.154565027Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:06:21.157943877Z 2024-02-23 17:06:21,157:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine  | 2024-02-23T16:06:21.158093589Z 2024-02-23 17:06:21,157:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine  | 2024-02-23T16:06:21.159179142Z 2024-02-23 17:06:21,158:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine  | 2024-02-23T16:06:21.160267604Z 2024-02-23 17:06:21,159:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine  | 2024-02-23T16:06:21.185967403Z 2024-02-23 17:06:21,185:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine  | 2024-02-23T16:06:21.186128919Z 2024-02-23 17:06:21,186:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine  | 2024-02-23T16:06:21.186476531Z 2024-02-23 17:06:21,186:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:06:21.189255615Z 2024-02-23 17:06:21,189:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:06:21.192889055Z 2024-02-23 17:06:21,192:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-02-23T17:15:00', 'repetitionOfId': None, 'scheduleId': 16, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 2, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'Sinüsse', 'showTopics': '', 'showType': 'Experimentell', 'start': '2024-02-23T17:05:00', 'title': 'Sinüsse', 'timeslot_id': 16, 'playlist_id': 14, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': {'id': 14, 'created': '2024-02-23T17:02:08.280539+01:00', 'updated': '2024-02-23T17:02:08.304684+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-02-20T20:18:07.930814+01:00', 'updated': '2024-02-22T23:31:09.697848+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine  | 2024-02-23T16:06:21.194589851Z 2024-02-23 17:06:21,194:engine:DEBUG - Storing playlist 14 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:06:21.195929504Z 2024-02-23 17:06:21,195:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:06:21.198806427Z 2024-02-23 17:06:21,198:engine:DEBUG - Storing playlist 1 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:06:21.200139265Z 2024-02-23 17:06:21,200:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:06:21.202127004Z 2024-02-23 17:06:21,201:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine  | 2024-02-23T16:06:21.202581263Z 2024-02-23 17:06:21,202:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine  | 2024-02-23T16:06:21.202643289Z 2024-02-23 17:06:21,202:engine:INFO -
engine  | 2024-02-23T16:06:21.202649182Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:06:21.202651710Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.531826             (alive: False, updates: 1)
engine  | 2024-02-23T16:06:21.202665843Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58] exec at 2024-02-23 17:14:58.032785             (alive: True, updates: 0)
engine  | 2024-02-23T16:06:21.202668634Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:44.538873             (alive: False, updates: 1)
engine  | 2024-02-23T16:06:21.202671089Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.540230             (alive: False, updates: 0)
engine  | 2024-02-23T16:06:21.202673470Z
engine  | 2024-02-23T16:06:21.202675664Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:06:51.205803272Z 2024-02-23 17:06:51,205:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine  | 2024-02-23T16:06:51.205861089Z 2024-02-23 17:06:51,205:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine  | 2024-02-23T16:06:51.206783321Z 2024-02-23 17:06:51,206:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine  | 2024-02-23T16:06:51.207730633Z 2024-02-23 17:06:51,207:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine  | 2024-02-23T16:06:51.228685981Z 2024-02-23 17:06:51,228:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine  | 2024-02-23T16:06:51.228917668Z 2024-02-23 17:06:51,228:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine  | 2024-02-23T16:06:51.229268955Z 2024-02-23 17:06:51,229:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:06:51.232199456Z 2024-02-23 17:06:51,232:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine  | 2024-02-23T16:06:51.235880966Z 2024-02-23 17:06:51,235:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-02-23T17:15:00', 'repetitionOfId': None, 'scheduleId': 16, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 2, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'Sinüsse', 'showTopics': '', 'showType': 'Experimentell', 'start': '2024-02-23T17:05:00', 'title': 'Sinüsse', 'timeslot_id': 16, 'playlist_id': 14, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': {'id': 14, 'created': '2024-02-23T17:02:08.280539+01:00', 'updated': '2024-02-23T17:02:08.304684+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-02-20T20:18:07.930814+01:00', 'updated': '2024-02-22T23:31:09.697848+01:00', 'description': '', 'playoutMode': '', 'showId': 2, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine  | 2024-02-23T16:06:51.237770350Z 2024-02-23 17:06:51,237:engine:DEBUG - Storing playlist 14 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:06:51.239445744Z 2024-02-23 17:06:51,239:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:06:51.243029374Z 2024-02-23 17:06:51,242:engine:DEBUG - Storing playlist 1 for timeslot ID#16 [Show: Sinüsse, ShowID: 2 | 17:05:00 - 17:15:00 ] - [programme.py:408-store_playlist()]
engine  | 2024-02-23T16:06:51.244817308Z 2024-02-23 17:06:51,244:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine  | 2024-02-23T16:06:51.247209346Z 2024-02-23 17:06:51,247:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine  | 2024-02-23T16:06:51.247836181Z 2024-02-23 17:06:51,247:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine  | 2024-02-23T16:06:51.247936194Z 2024-02-23 17:06:51,247:engine:INFO -
engine  | 2024-02-23T16:06:51.247944100Z  [ ENGINE COMMAND QUEUE ]
engine  | 2024-02-23T16:06:51.247947494Z       =>   [TIMESLOT#16:do_start_timeslot:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.531826             (alive: False, updates: 1)
engine  | 2024-02-23T16:06:51.247950602Z             =>   [TIMESLOT#16:do_end_timeslot:2024-02-23_17:14:58] exec at 2024-02-23 17:14:58.032785             (alive: True, updates: 0)
engine  | 2024-02-23T16:06:51.247953650Z       =>   [PRELOAD#16:do_preload:2024-02-23_17:04:45] exec at 2024-02-23 17:04:44.538873             (alive: False, updates: 1)
engine  | 2024-02-23T16:06:51.247956656Z             =>   [PLAY#16:do_play:2024-02-23_17:05:00] exec at 2024-02-23 17:04:59.540230             (alive: False, updates: 0)
engine  | 2024-02-23T16:06:51.247959682Z
engine  | 2024-02-23T16:06:51.247962494Z  - [control.py:288-log_commands()]
engine  | 2024-02-23T16:07:21.250927077Z 2024-02-23 17:07:21,250:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]

closed

removed Doing label

reopened

added Doing label

Just encountered issue again:

engine                 | 2024-03-21T11:17:43.111510116Z 2024-03-21 12:17:43,110:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:45.114188114Z 2024-03-21 12:17:45,113:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:47.116883026Z 2024-03-21 12:17:47,116:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:49.119543521Z 2024-03-21 12:17:49,118:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:51.121908636Z 2024-03-21 12:17:51,121:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:53.124695474Z 2024-03-21 12:17:53,124:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:17:55.127383610Z 2024-03-21 12:17:55,126:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]

What is the stream URL you have scheduled?

edit: When scheduling a stream fails, there are some other relevant parts in the logs, indicating the stream connection tries etc. This is very important info, which already can give ideas on the cause. Can you please add this?

Basically looks OK:

engine                 | 2024-03-21T11:29:13.544802619Z 2024-03-21 12:29:13,544:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine                 | 2024-03-21T11:29:13.544957619Z 2024-03-21 12:29:13,544:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine                 | 2024-03-21T11:29:13.545853940Z 2024-03-21 12:29:13,545:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine                 | 2024-03-21T11:29:13.546976405Z 2024-03-21 12:29:13,546:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine                 | 2024-03-21T11:29:13.579592163Z 2024-03-21 12:29:13,579:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine                 | 2024-03-21T11:29:13.580596796Z 2024-03-21 12:29:13,580:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine                 | 2024-03-21T11:29:13.581708740Z 2024-03-21 12:29:13,581:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine                 | 2024-03-21T11:29:13.588061021Z 2024-03-21 12:29:13,587:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-03-21T18:00:00', 'repetitionOfId': None, 'scheduleId': 1, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 1, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'FRO Livestream Monitor', 'showTopics': '', 'showType': 'Unmoderiertes Musikprogramm', 'start': '2024-03-21T06:00:00', 'title': 'FRO Livestream Monitor', 'timeslot_id': 1, 'playlist_id': None, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': None, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-03-21T03:41:06.874014+01:00', 'updated': '2024-03-21T03:41:06.916559+01:00', 'description': '', 'playoutMode': '', 'showId': 1, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine                 | 2024-03-21T11:29:13.589210969Z 2024-03-21 12:29:13,589:engine:DEBUG - Playlist ID#None is not available! - [programme.py:396-store_playlist()]
engine                 | 2024-03-21T11:29:13.589753541Z 2024-03-21 12:29:13,589:engine:DEBUG - Storing playlist 1 for timeslot ID#1 [Show: FRO Livestream Monitor, ShowID: 1 | 06:00:00 - 18:00:00 ] - [programme.py:408-store_playlist()]
engine                 | 2024-03-21T11:29:13.591103427Z 2024-03-21 12:29:13,590:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine                 | 2024-03-21T11:29:13.593120150Z 2024-03-21 12:29:13,592:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine                 | 2024-03-21T11:29:13.593618323Z 2024-03-21 12:29:13,593:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine                 | 2024-03-21T11:29:13.593667072Z 2024-03-21 12:29:13,593:engine:INFO -
engine                 | 2024-03-21T11:29:13.593675117Z  [ ENGINE COMMAND QUEUE ]
engine                 | 2024-03-21T11:29:13.593678070Z       =>   [TIMESLOT#1:do_start_timeslot:2024-03-21_06:00:00] exec at 2024-03-21 05:59:59.957558             (alive: False, updates: 1)
engine                 | 2024-03-21T11:29:13.593680886Z             =>   [TIMESLOT#1:do_end_timeslot:2024-03-21_17:59:58] exec at 2024-03-21 17:59:58.457853             (alive: True, updates: 1)
engine                 | 2024-03-21T11:29:13.593683398Z       =>   [PRELOAD#1:do_preload:2024-03-21_05:59:45] exec at 2024-03-21 05:59:44.905397             (alive: False, updates: 0)
engine                 | 2024-03-21T11:29:13.593685849Z             =>   [PLAY#1:do_play:2024-03-21_06:00:00] exec at 2024-03-21 05:59:59.905683             (alive: True, updates: 0)
engine                 | 2024-03-21T11:29:13.593688285Z
engine                 | 2024-03-21T11:29:13.593690520Z  - [control.py:288-log_commands()]
engine                 | 2024-03-21T11:29:14.004986321Z 2024-03-21 12:29:14,004:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:16.007767482Z 2024-03-21 12:29:16,007:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:18.010396241Z 2024-03-21 12:29:18,009:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:20.013102302Z 2024-03-21 12:29:20,012:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:22.015790465Z 2024-03-21 12:29:22,015:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:24.017168650Z 2024-03-21 12:29:24,016:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:26.019280125Z 2024-03-21 12:29:26,018:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:28.022008507Z 2024-03-21 12:29:28,021:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:30.024694216Z 2024-03-21 12:29:30,024:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:32.027362748Z 2024-03-21 12:29:32,026:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:34.030045972Z 2024-03-21 12:29:34,029:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:36.032748007Z 2024-03-21 12:29:36,032:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:38.035444061Z 2024-03-21 12:29:38,034:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:40.038146926Z 2024-03-21 12:29:40,037:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:42.040764978Z 2024-03-21 12:29:42,040:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:43.596417111Z 2024-03-21 12:29:43,595:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine                 | 2024-03-21T11:29:43.596565841Z 2024-03-21 12:29:43,596:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine                 | 2024-03-21T11:29:43.597331686Z 2024-03-21 12:29:43,596:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine                 | 2024-03-21T11:29:43.598432857Z 2024-03-21 12:29:43,598:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine                 | 2024-03-21T11:29:43.628610869Z 2024-03-21 12:29:43,628:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine                 | 2024-03-21T11:29:43.629604171Z 2024-03-21 12:29:43,629:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine                 | 2024-03-21T11:29:43.632589561Z 2024-03-21 12:29:43,632:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine                 | 2024-03-21T11:29:43.647271273Z 2024-03-21 12:29:43,646:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-03-21T18:00:00', 'repetitionOfId': None, 'scheduleId': 1, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 1, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'FRO Livestream Monitor', 'showTopics': '', 'showType': 'Unmoderiertes Musikprogramm', 'start': '2024-03-21T06:00:00', 'title': 'FRO Livestream Monitor', 'timeslot_id': 1, 'playlist_id': None, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': None, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-03-21T03:41:06.874014+01:00', 'updated': '2024-03-21T03:41:06.916559+01:00', 'description': '', 'playoutMode': '', 'showId': 1, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine                 | 2024-03-21T11:29:43.652924884Z 2024-03-21 12:29:43,652:engine:DEBUG - Playlist ID#None is not available! - [programme.py:396-store_playlist()]
engine                 | 2024-03-21T11:29:43.655342477Z 2024-03-21 12:29:43,654:engine:DEBUG - Storing playlist 1 for timeslot ID#1 [Show: FRO Livestream Monitor, ShowID: 1 | 06:00:00 - 18:00:00 ] - [programme.py:408-store_playlist()]
engine                 | 2024-03-21T11:29:43.661797785Z 2024-03-21 12:29:43,661:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine                 | 2024-03-21T11:29:43.671238874Z 2024-03-21 12:29:43,670:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine                 | 2024-03-21T11:29:43.673824466Z 2024-03-21 12:29:43,673:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine                 | 2024-03-21T11:29:43.674239662Z 2024-03-21 12:29:43,673:engine:INFO -
engine                 | 2024-03-21T11:29:43.674281168Z  [ ENGINE COMMAND QUEUE ]
engine                 | 2024-03-21T11:29:43.674296025Z       =>   [TIMESLOT#1:do_start_timeslot:2024-03-21_06:00:00] exec at 2024-03-21 05:59:59.957558             (alive: False, updates: 1)
engine                 | 2024-03-21T11:29:43.674308361Z             =>   [TIMESLOT#1:do_end_timeslot:2024-03-21_17:59:58] exec at 2024-03-21 17:59:58.457853             (alive: True, updates: 1)
engine                 | 2024-03-21T11:29:43.674320359Z       =>   [PRELOAD#1:do_preload:2024-03-21_05:59:45] exec at 2024-03-21 05:59:44.905397             (alive: False, updates: 0)
engine                 | 2024-03-21T11:29:43.674331761Z             =>   [PLAY#1:do_play:2024-03-21_06:00:00] exec at 2024-03-21 05:59:59.905683             (alive: True, updates: 0)
engine                 | 2024-03-21T11:29:43.674343247Z
engine                 | 2024-03-21T11:29:43.674353962Z  - [control.py:288-log_commands()]
engine                 | 2024-03-21T11:29:44.043451433Z 2024-03-21 12:29:44,042:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:46.046152135Z 2024-03-21 12:29:46,045:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:48.048849216Z 2024-03-21 12:29:48,048:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:50.051537015Z 2024-03-21 12:29:50,050:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:52.054235490Z 2024-03-21 12:29:52,053:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:54.056921537Z 2024-03-21 12:29:54,056:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:56.059516956Z 2024-03-21 12:29:56,058:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:29:58.062202229Z 2024-03-21 12:29:58,061:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]

changed milestone to %1.0-alpha4 — Raving Raccoon

added 1 deleted label

No redundent logs after restarting aura-playout and same behavior as in unit test:

engine                 | 2024-03-21T11:42:22.363881795Z 2024-03-21 12:42:22,363:engine:INFO - PLAY: Wait a little bit until preloading is done ... - [scheduler.py:573-do_play()]
engine                 | 2024-03-21T11:42:23.385554371Z 2024-03-21 12:42:23,385:engine:DEBUG - [>>] in_stream_0.set_track_metadata {"show_name": "FRO Livestream Monitor", "show_id": 1, "timeslot_id": 1, "playlist_id": 1, "playlist_item": "0.0", "track_type": 1, "track_start": "2024/03/21 06:00:00", "track_duration": 43200.0, "track_title": "", "track_album": "", "track_artist": ""} - [client.py:160-log_debug()]
engine-core            | 2024-03-21T11:42:23.386291780Z 2024/03/21 12:42:23 [lang:3] Received JSON to set track metadata on channel 'in_stream_0' to:
engine-core            | 2024-03-21T11:42:23.386653874Z 2024/03/21 12:42:23 [lang:3]  {"show_name": "FRO Livestream Monitor", "show_id": 1, "timeslot_id": 1, "playlist_id": 1, "playlist_item": "0.0", "track_type": 1, "track_start": "2024/03/21 06:00:00", "track_duration": 43200.0, "track_title": "", "track_album": "", "track_artist": ""}
engine-core            | 2024-03-21T11:42:23.386840100Z 2024/03/21 12:42:23 [metadata:5] Merge | last metadata: []
engine-core            | 2024-03-21T11:42:23.386860459Z 2024/03/21 12:42:23 [metadata:5] Merge | current metadata: [("show_name", "FRO Livestream Monitor"), ("show_id", "1"), ("timeslot_id", "1"), ("playlist_id", "1"), ("playlist_item", "0.0"), ("track_type", "1"), ("track_start", "2024/03/21 06:00:00"), ("track_duration", "43200."), ("track_title", ""), ("track_album", ""), ("track_artist", "")]
engine-core            | 2024-03-21T11:42:23.386920050Z 2024/03/21 12:42:23 [metadata:5] Merge | resulting metadata: [("track_artist", ""), ("track_album", ""), ("track_title", ""), ("track_duration", "43200."), ("track_start", "2024/03/21 06:00:00"), ("track_type", "1"), ("playlist_item", "0.0"), ("playlist_id", "1"), ("timeslot_id", "1"), ("show_id", "1"), ("show_name", "FRO Livestream Monitor")]
engine                 | 2024-03-21T11:42:23.387391197Z 2024-03-21 12:42:23,387:engine:DEBUG - [<<] OK - [client.py:160-log_debug()]
engine                 | 2024-03-21T11:42:23.387499542Z 2024-03-21 12:42:23,387:engine:INFO - Response for 'in_stream_0.set_track_metadata': OK - [channels.py:303-set_track_metadata()]
engine                 | 2024-03-21T11:42:23.387580517Z 2024-03-21 12:42:23,387:engine:ERROR - Successfully loaded entry 'PlaylistEntry #16 [06:00:00 - 18:00:00 | 43200.0sec | Source: ...m.fro.at:8008/fro-128.ogg] - [engine.py:323-preload()]
engine                 | 2024-03-21T11:42:23.387734814Z 2024-03-21 12:42:23,387:engine:DEBUG - on_queue(..) - [events.py:260-func()]
engine                 | 2024-03-21T11:42:24.366489041Z 2024-03-21 12:42:24,365:engine:INFO - Nothing to stop, no active channel - [engine.py:416-stop()]
engine                 | 2024-03-21T11:42:24.366629987Z 2024-03-21 12:42:24,366:engine:INFO - Fade in channel [2 : in_stream_0] - [channels.py:244-fade_in()]
engine                 | 2024-03-21T11:42:24.370551875Z 2024-03-21 12:42:24,370:engine:DEBUG - [>>] mixer.select 2 true - [client.py:160-log_debug()]
engine                 | 2024-03-21T11:42:24.375590427Z 2024-03-21 12:42:24,375:engine:DEBUG - [<<] ready=true selected=true single=false volume=0% remaining=inf - [client.py:160-log_debug()]
engine                 | 2024-03-21T11:42:24.382253843Z 2024-03-21 12:42:24,381:engine:DEBUG - [>>] mixer.status 2 - [client.py:160-log_debug()]
engine-core            | 2024-03-21T11:42:24.385285067Z 2024/03/21 12:42:24 [fallback-source:3] Switch to stripped_stream with transition.
engine-core            | 2024-03-21T11:42:24.386020341Z 2024/03/21 12:42:24 [mksafe:5] Activations changed: static=[], dynamic=[fallback-source:lineout_0:lineout_0].
engine                 | 2024-03-21T11:42:24.388691286Z 2024-03-21 12:42:24,388:engine:DEBUG - [<<] ready=true selected=true single=false volume=0% remaining=inf - [client.py:160-log_debug()]
engine                 | 2024-03-21T11:42:24.390425283Z 2024-03-21 12:42:24,390:engine:DEBUG - Fade in of [2 : in_stream_0] to 100% (0.015s steps) - [mixer.py:244-fade_in()]
engine-core            | 2024-03-21T11:42:24.399512428Z 2024/03/21 12:42:24 [stripped_stream:5] Activations changed: static=[fallback-source:lineout_0:lineout_0, stripped_stream], dynamic=[fallback-source:lineout_0:lineout_0].
engine-core            | 2024-03-21T11:42:24.400087067Z 2024/03/21 12:42:24 [switch_2:3] Switch to on_metadata_5.
engine-core            | 2024-03-21T11:42:24.400666860Z 2024/03/21 12:42:24 [on_metadata_5:5] Activations changed: static=[switch_2:add_0:metadata.map_1:insert_metadata_3:mixer:stripped_stream:stripped_stream], dynamic=[switch_2:add_0:metadata.map_1:insert_metadata_3:mixer:stripped_stream:stripped_stream].
engine-core            | 2024-03-21T11:42:24.400699299Z 2024/03/21 12:42:24 [in_stream_0:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.400710464Z 2024/03/21 12:42:24 [metadata:5] Merge | last metadata: [("timeslot_id", "1"), ("show_id", "1"), ("track_title", ""), ("track_duration", "43200."), ("track_type", "1"), ("playlist_id", "1"), ("show_name", "FRO Livestream Monitor"), ("track_start", "2024/03/21 06:00:00"), ("track_album", ""), ("playlist_item", "0.0"), ("track_artist", "")]
engine-core            | 2024-03-21T11:42:24.400723438Z 2024/03/21 12:42:24 [metadata:5] Merge | current metadata: [("timeslot_id", "1"), ("show_id", "1"), ("track_title", ""), ("track_duration", "43200."), ("track_type", "1"), ("playlist_id", "1"), ("show_name", "FRO Livestream Monitor"), ("track_start", "2024/03/21 06:00:00"), ("track_album", ""), ("playlist_item", "0.0"), ("track_artist", "")]
engine-core            | 2024-03-21T11:42:24.400734336Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("timeslot_id", "1")
engine-core            | 2024-03-21T11:42:24.400742204Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("show_id", "1")
engine-core            | 2024-03-21T11:42:24.400952700Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_title", "")
engine-core            | 2024-03-21T11:42:24.400971906Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_duration", "43200.")
engine-core            | 2024-03-21T11:42:24.400999913Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_type", "1")
engine-core            | 2024-03-21T11:42:24.401009148Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("playlist_id", "1")
engine-core            | 2024-03-21T11:42:24.401016666Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("show_name", "FRO Livestream Monitor")
engine-core            | 2024-03-21T11:42:24.401024335Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_start", "2024/03/21 06:00:00")
engine-core            | 2024-03-21T11:42:24.401032225Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_album", "")
engine-core            | 2024-03-21T11:42:24.401039985Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("playlist_item", "0.0")
engine-core            | 2024-03-21T11:42:24.401047527Z 2024/03/21 12:42:24 [metadata:5] Remove existing entry ("track_artist", "")
engine-core            | 2024-03-21T11:42:24.401605036Z 2024/03/21 12:42:24 [metadata:5] Merge | resulting metadata: [("track_artist", ""), ("playlist_item", "0.0"), ("track_album", ""), ("track_start", "2024/03/21 06:00:00"), ("show_name", "FRO Livestream Monitor"), ("playlist_id", "1"), ("track_type", "1"), ("track_duration", "43200."), ("track_title", ""), ("show_id", "1"), ("timeslot_id", "1")]
engine-core            | 2024-03-21T11:42:24.401878619Z 2024/03/21 12:42:24 [in_stream_0:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.401899066Z 2024/03/21 12:42:24 [in_stream_0:5] Got metadata at position 0: calling handler...
engine-core            | 2024-03-21T11:42:24.401949663Z 2024/03/21 12:42:24 [metadata:3] Raw metadata before POST:
engine-core            | 2024-03-21T11:42:24.402201933Z 2024/03/21 12:42:24 [metadata:3]
engine-core            | 2024-03-21T11:42:24.402235021Z 2024/03/21 12:42:24 [metadata:3]  [("timeslot_id", "1"), ("show_id", "1"), ("track_title", ""), ("track_duration", "43200."), ("track_type", "1"), ("playlist_id", "1"), ("show_name", "FRO Livestream Monitor"), ("track_start", "2024/03/21 06:00:00"), ("track_album", ""), ("playlist_item", "0.0"), ("track_artist", "")]
engine-core            | 2024-03-21T11:42:24.402249757Z 2024/03/21 12:42:24 [metadata:3]
engine-core            | 2024-03-21T11:42:24.402257872Z 2024/03/21 12:42:24 [metadata:3]
engine-core            | 2024-03-21T11:42:24.402265281Z 2024/03/21 12:42:24 [lang:3] Posting playlog to 'http://engine-api:8008/api/v1/playlog': {
engine-core            | 2024-03-21T11:42:24.402273025Z 2024/03/21 12:42:24 [lang:3]   "logSource": 1,
engine-core            | 2024-03-21T11:42:24.402280842Z 2024/03/21 12:42:24 [lang:3]   "timeslotId": 1,
engine-core            | 2024-03-21T11:42:24.402288281Z 2024/03/21 12:42:24 [lang:3]   "trackDuration": 43200.0,
engine-core            | 2024-03-21T11:42:24.402295789Z 2024/03/21 12:42:24 [lang:3]   "trackType": 1,
engine-core            | 2024-03-21T11:42:24.402496340Z 2024/03/21 12:42:24 [lang:3]   "trackStart": "2024/03/21 06:00:00",
engine-core            | 2024-03-21T11:42:24.404063609Z 2024/03/21 12:42:24 [lang:3]   "showId": 1,
engine-core            | 2024-03-21T11:42:24.404297493Z 2024/03/21 12:42:24 [lang:3]   "trackArtist": "",
engine-core            | 2024-03-21T11:42:24.404313678Z 2024/03/21 12:42:24 [lang:3]   "playlistId": 1,
engine-core            | 2024-03-21T11:42:24.404320424Z 2024/03/21 12:42:24 [lang:3]   "trackTitle": "",
engine-core            | 2024-03-21T11:42:24.404326369Z 2024/03/21 12:42:24 [lang:3]   "trackAlbum": "",
engine-core            | 2024-03-21T11:42:24.404343961Z 2024/03/21 12:42:24 [lang:3]   "trackNum": 0,
engine-core            | 2024-03-21T11:42:24.404350603Z 2024/03/21 12:42:24 [lang:3]   "showName": "FRO Livestream Monitor"
engine-core            | 2024-03-21T11:42:24.404356580Z 2024/03/21 12:42:24 [lang:3] }
engine-core            | 2024-03-21T11:42:24.411017819Z 2024/03/21 12:42:24 [lang:3] Successfully posted playlog to Engine API.
engine-core            | 2024-03-21T11:42:24.411254151Z 2024/03/21 12:42:24 [in_stream_0:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411272967Z 2024/03/21 12:42:24 [amplify_4:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411279250Z 2024/03/21 12:42:24 [on_track_2:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411284276Z 2024/03/21 12:42:24 [on_metadata_5:5] Got metadata at position 0: calling handler...
engine-core            | 2024-03-21T11:42:24.411288695Z 2024/03/21 12:42:24 [on_metadata_5:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411295573Z 2024/03/21 12:42:24 [switch_2:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411300059Z 2024/03/21 12:42:24 [add_0:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411304404Z 2024/03/21 12:42:24 [insert_metadata_3:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411308818Z 2024/03/21 12:42:24 [mixer:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411313167Z 2024/03/21 12:42:24 [stripped_stream:5] Got metadata at position 0: calling handlers...
engine-core            | 2024-03-21T11:42:24.411317622Z 2024/03/21 12:42:24 [lang:3] Skipping track in fallback folder ...
engine-core            | 2024-03-21T11:42:24.411322023Z 2024/03/21 12:42:24 [fallback_folder:4] Finished with "/var/audio/fallback/Sine432.mp3".
engine-core            | 2024-03-21T11:42:24.411449333Z 2024/03/21 12:42:24 [fallback-source:5] Got metadata at position 0: calling handlers...
engine                 | 2024-03-21T11:42:24.455944264Z 2024-03-21 12:42:24,455:engine:INFO - Playout turned back into normal state - [engine.py:145-update_playout_state()]
engine                 | 2024-03-21T11:42:27.099843258Z 2024-03-21 12:42:27,099:engine:DEBUG - Fade in of [2 : in_stream_0] done - [mixer.py:249-fade_in()]
engine                 | 2024-03-21T11:42:27.101308495Z 2024-03-21 12:42:27,100:engine:DEBUG - on_play(..) - [events.py:218-func()]
engine                 | 2024-03-21T11:42:27.101979135Z 2024-03-21 12:42:27,100:engine:INFO -
engine                 | 2024-03-21T11:42:27.102024562Z
engine                 | 2024-03-21T11:42:27.102038920Z    SCHEDULED NOW:
engine                 | 2024-03-21T11:42:27.102050285Z ┌──────────────────────────────────────────────────────────────────────────────────────────────────────
engine                 | 2024-03-21T11:42:27.102064454Z │   Playing timeslot ID#1 [Show: FRO Livestream Monitor, ShowID: 1 | 06:00:00 - 18:00:00 ]
engine                 | 2024-03-21T11:42:27.102076910Z │      No playlist assigned to timeslot. Instead playing the 'show' playlist below ↓↓↓
engine                 | 2024-03-21T11:42:27.102089312Z │       └── Playlist ID#1 [items: 1 | 06:00:00 - 18:00:00]
engine                 | 2024-03-21T11:42:27.102100919Z │         └── Entry 1 | PLAYING > PlaylistEntry #16 [06:00:00 - 18:00:00 | 43200.0sec | Source: ...m.fro.at:8008/fro-128.ogg]
engine                 | 2024-03-21T11:42:27.102113709Z └──────────────────────────────────────────────────────────────────────────────────────────────────────
engine                 | 2024-03-21T11:42:27.102126935Z    SCHEDULED NEXT:
engine                 | 2024-03-21T11:42:27.102137602Z ┌──────────────────────────────────────────────────────────────────────────────────────────────────────
engine                 | 2024-03-21T11:42:27.102150504Z │   Nothing.
engine                 | 2024-03-21T11:42:27.102185828Z └──────────────────────────────────────────────────────────────────────────────────────────────────────
engine                 | 2024-03-21T11:42:27.102200753Z
engine                 | 2024-03-21T11:42:27.102212036Z  - [scheduler.py:578-do_play()]
engine                 | 2024-03-21T11:42:27.102517025Z 2024-03-21 12:42:27,101:engine:INFO - PUT clock info to 'http://engine-api:8008/api/v1/clock':
engine                 | 2024-03-21T11:42:27.102553447Z {'engineSource': 1, 'currentTimeslot': {'timeslotId': 1, 'timeslotStart': datetime.datetime(2024, 3, 21, 6, 0), 'timeslotEnd': datetime.datetime(2024, 3, 21, 18, 0), 'showId': 1, 'showName': 'FRO Livestream Monitor', 'playlistId': None, 'playlistType': 2}, 'upcomingTimeslots': [], 'plannedPlaylist': {'playlistId': 1, 'entries': [{'trackType': 1, 'trackStart': datetime.datetime(2024, 3, 21, 6, 0), 'trackNum': 0, 'trackDuration': 43200.0}]}} - [clock.py:136-post_clock_info()]
engine                 | 2024-03-21T11:42:27.103282050Z 2024-03-21 12:42:27,102:engine:INFO - Built JSON: {
engine                 | 2024-03-21T11:42:27.103319259Z     "currentTimeslot": {
engine                 | 2024-03-21T11:42:27.103333326Z         "playlistId": null,
engine                 | 2024-03-21T11:42:27.103344843Z         "playlistType": 2,
engine                 | 2024-03-21T11:42:27.103355937Z         "showId": 1,
engine                 | 2024-03-21T11:42:27.103366769Z         "showName": "FRO Livestream Monitor",
engine                 | 2024-03-21T11:42:27.103378296Z         "timeslotEnd": "2024-03-21 18:00:00",
engine                 | 2024-03-21T11:42:27.103405135Z         "timeslotId": 1,
engine                 | 2024-03-21T11:42:27.103416338Z         "timeslotStart": "2024-03-21 06:00:00"
engine                 | 2024-03-21T11:42:27.103427653Z     },
engine                 | 2024-03-21T11:42:27.103438886Z     "engineSource": 1,
engine                 | 2024-03-21T11:42:27.103449769Z     "plannedPlaylist": {
engine                 | 2024-03-21T11:42:27.103460807Z         "entries": [
engine                 | 2024-03-21T11:42:27.103471618Z             {
engine                 | 2024-03-21T11:42:27.103482160Z                 "trackDuration": 43200.0,
engine                 | 2024-03-21T11:42:27.103493271Z                 "trackNum": 0,
engine                 | 2024-03-21T11:42:27.103504399Z                 "trackStart": "2024-03-21 06:00:00",
engine                 | 2024-03-21T11:42:27.103515656Z                 "trackType": 1
engine                 | 2024-03-21T11:42:27.103527097Z             }
engine                 | 2024-03-21T11:42:27.103537853Z         ],
engine                 | 2024-03-21T11:42:27.103548304Z         "playlistId": 1
engine                 | 2024-03-21T11:42:27.103559077Z     },
engine                 | 2024-03-21T11:42:27.103569373Z     "upcomingTimeslots": []
engine                 | 2024-03-21T11:42:27.103580483Z } - [api.py:184-serialize_json()]
engine                 | 2024-03-21T11:42:40.182462677Z 2024-03-21 12:42:40,181:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine                 | 2024-03-21T11:42:40.182648286Z 2024-03-21 12:42:40,182:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine                 | 2024-03-21T11:42:40.183611529Z 2024-03-21 12:42:40,183:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine                 | 2024-03-21T11:42:40.184729747Z 2024-03-21 12:42:40,184:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine                 | 2024-03-21T11:42:40.213732540Z 2024-03-21 12:42:40,213:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine                 | 2024-03-21T11:42:40.214816613Z 2024-03-21 12:42:40,214:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine                 | 2024-03-21T11:42:40.215861157Z 2024-03-21 12:42:40,215:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine                 | 2024-03-21T11:42:40.222695975Z 2024-03-21 12:42:40,222:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-03-21T18:00:00', 'repetitionOfId': None, 'scheduleId': 1, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 1, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'FRO Livestream Monitor', 'showTopics': '', 'showType': 'Unmoderiertes Musikprogramm', 'start': '2024-03-21T06:00:00', 'title': 'FRO Livestream Monitor', 'timeslot_id': 1, 'playlist_id': None, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': None, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-03-21T03:41:06.874014+01:00', 'updated': '2024-03-21T03:41:06.916559+01:00', 'description': '', 'playoutMode': '', 'showId': 1, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine                 | 2024-03-21T11:42:40.224123802Z 2024-03-21 12:42:40,224:engine:DEBUG - Playlist ID#None is not available! - [programme.py:396-store_playlist()]
engine                 | 2024-03-21T11:42:40.224714196Z 2024-03-21 12:42:40,224:engine:DEBUG - Storing playlist 1 for timeslot ID#1 [Show: FRO Livestream Monitor, ShowID: 1 | 06:00:00 - 18:00:00 ] - [programme.py:408-store_playlist()]
engine                 | 2024-03-21T11:42:40.226190888Z 2024-03-21 12:42:40,226:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine                 | 2024-03-21T11:42:40.228486085Z 2024-03-21 12:42:40,228:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine                 | 2024-03-21T11:42:40.228932595Z 2024-03-21 12:42:40,228:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]
engine                 | 2024-03-21T11:42:40.228997826Z 2024-03-21 12:42:40,228:engine:DEBUG - Removing already executed timer with ID: PRELOAD#1:do_preload:2024-03-21_05:59:45 - [control.py:251-remove_stale_timers()]
engine                 | 2024-03-21T11:42:40.229050204Z 2024-03-21 12:42:40,228:engine:DEBUG - Removing already executed timer with ID: PLAY#1:do_play:2024-03-21_06:00:00 - [control.py:251-remove_stale_timers()]
engine                 | 2024-03-21T11:42:40.229123945Z 2024-03-21 12:42:40,229:engine:INFO -
engine                 | 2024-03-21T11:42:40.229130789Z  [ ENGINE COMMAND QUEUE ]
engine                 | 2024-03-21T11:42:40.229133439Z       =>   [TIMESLOT#1:do_start_timeslot:2024-03-21_06:00:00] exec at 2024-03-21 05:59:59.819434             (alive: False, updates: 0)
engine                 | 2024-03-21T11:42:40.229136065Z             =>   [TIMESLOT#1:do_end_timeslot:2024-03-21_17:59:58] exec at 2024-03-21 17:59:58.319767             (alive: True, updates: 0)
engine                 | 2024-03-21T11:42:40.229138584Z
engine                 | 2024-03-21T11:42:40.229140837Z  - [control.py:288-log_commands()]
engine                 | 2024-03-21T11:43:10.232148386Z 2024-03-21 12:43:10,231:engine:INFO - == start fetching new timeslots (every 30 seconds) == - [scheduler.py:106-run()]
engine                 | 2024-03-21T11:43:10.232486117Z 2024-03-21 12:43:10,231:engine:DEBUG - Trying to fetch new programme from API endpoints... - [programme.py:65-refresh()]
engine                 | 2024-03-21T11:43:10.233127092Z 2024-03-21 12:43:10,232:engine:DEBUG - Fetching timeslots from STEERING - [api.py:99-run()]
engine                 | 2024-03-21T11:43:10.234199859Z 2024-03-21 12:43:10,233:engine:DEBUG - Fetch timeslots from Steering API... - [api.py:151-get_current_timeslots()]
engine                 | 2024-03-21T11:43:10.262307457Z 2024-03-21 12:43:10,262:engine:DEBUG - Removed 0 unnecessary timeslots, 1 left - [api.py:246-filter_timeslots()]
engine                 | 2024-03-21T11:43:10.262537440Z 2024-03-21 12:43:10,262:engine:DEBUG - Fetching playlists from TANK - [api.py:101-run()]
engine                 | 2024-03-21T11:43:10.263393783Z 2024-03-21 12:43:10,263:engine:DEBUG - Fetch playlist from Tank API... - [api.py:217-fetch_playlist()]
engine                 | 2024-03-21T11:43:10.270312438Z 2024-03-21 12:43:10,270:engine:DEBUG - Store/Update TIMESLOT havetoadd=False - data: {'end': '2024-03-21T18:00:00', 'repetitionOfId': None, 'scheduleId': 1, 'showCategories': '', 'showFundingCategory': 'Standard', 'showHosts': '', 'showId': 1, 'showLanguages': '', 'showMusicFocus': '', 'showName': 'FRO Livestream Monitor', 'showTopics': '', 'showType': 'Unmoderiertes Musikprogramm', 'start': '2024-03-21T06:00:00', 'title': 'FRO Livestream Monitor', 'timeslot_id': 1, 'playlist_id': None, 'default_schedule_playlist_id': 0, 'default_show_playlist_id': 1, 'playlist': None, 'default_schedule_playlist': None, 'default_show_playlist': {'id': 1, 'created': '2024-03-21T03:41:06.874014+01:00', 'updated': '2024-03-21T03:41:06.916559+01:00', 'description': '', 'playoutMode': '', 'showId': 1, 'entries': [{'uri': 'http://stream.fro.at:8008/fro-128.ogg'}]}} - [programme.py:387-store_timeslot()]
engine                 | 2024-03-21T11:43:10.272097084Z 2024-03-21 12:43:10,271:engine:DEBUG - Playlist ID#None is not available! - [programme.py:396-store_playlist()]
engine                 | 2024-03-21T11:43:10.272951329Z 2024-03-21 12:43:10,272:engine:DEBUG - Storing playlist 1 for timeslot ID#1 [Show: FRO Livestream Monitor, ShowID: 1 | 06:00:00 - 18:00:00 ] - [programme.py:408-store_playlist()]
engine                 | 2024-03-21T11:43:10.275512318Z 2024-03-21 12:43:10,275:engine:INFO - Expanded duration of playlist entry #0 - [programme.py:514-expand_entry_duration()]
engine                 | 2024-03-21T11:43:10.279442117Z 2024-03-21 12:43:10,279:engine:INFO - Finished fetching current programme from API (1 timeslots) - [programme.py:80-refresh()]
engine                 | 2024-03-21T11:43:10.280635100Z 2024-03-21 12:43:10,280:engine:INFO - Finished queuing programme. - [scheduler.py:285-queue_programme()]

closed

removed Doing label