Scheduled items did not play, dead air until manually removed & rescheduled

[rjhelms]

Describe the bug

This issue occurred around 15:00 local time (19:00 UTC) on 2023-03-20.

Schedule contained the following items:

• 15:00:00 - 2017-ID_Land_Acknowledgement_30sec.mp3, schedule ID 259048, audio ID 483
• 15:00:30 - TR_WeeklyRerun_SP23.mp3, schedule ID 259049, audio ID 5531
• 15:00:43 - 04_WE_1600_transitionally_MPreston_20230315.mp3, schedule ID 259050, audio ID 6001

The first played without issue, then playback was silent (stream output showed "Libretime Offline".)

Reviewing the logs, all seems normal except in liquidsoap.log - relevant excerpt attached below. It seems like what happened is the first item played without issue, then at 19:00:30 both 5531 and 483 (for a second time) were "accepted" by liquidsoap.

The log suggests item 259048 (audio 483) played again but in reality neither was output.

Third file did not play at 15:00:43 and playout remained silent until that item was removed from schedule and new items manually added.

It appears that liquidsoap was waiting the 30 seconds for 259048 to play a second time (through to 15:01) then failed with Failed to prepare track: request not ready.

All the current log files:

legacy.log
liquidsoap.log
playout.log
analyzer.log
api.log

To reproduce

Unknown. All relevant media has played in the past without issue.

Expected behavior

Scheduled media plays at time scheduled.

Relevant log output or error messages

Relevant section of liquidsoap.log:

2023/03/20 19:00:00 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:00 [lang:3] timeout --signal=KILL 45 libretime-playout-notify live 'live_dj' 'false' &
2023/03/20 19:00:00 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:00 [cue_cut_9619:3] End of track before cue-out point.
2023/03/20 19:00:00 [cross_9625:3] Analysis: -52.689721dB / -nandB (0.00s / 0.00s)
2023/03/20 19:00:00 [crossfade:3] Old <= medium, new <= medium and |old-new| <= margin.
2023/03/20 19:00:00 [crossfade:3] Old and new source are not too loud and close.
2023/03/20 19:00:00 [crossfade:3] Transition: crossed, fade-in, fade-out.
2023-03-20 19:00:00.248 | INFO     | libretime_playout.notify.main:live:73 - Sending currently playing live source 'live_dj' status 'false'
2023/03/20 19:00:00 [schedule_noise_switch:3] Switch to map_metadata_9702 with forgetful transition.
2023/03/20 19:00:00 [lang:3] transition called...
2023/03/20 19:00:00 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:00 [decoder:3] Method "FFMPEG" accepted "/var/lib/libretime/playout/scheduler/483.mp3".
2023/03/20 19:00:00 [lang:3] vars.show_name
2023/03/20 19:00:00 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2023/03/20 19:00:00 [dummy(dot)1:3] Source failed (no more tracks) stopping output...
2023/03/20 19:00:00 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:00 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:00 [lang:3] vars.show_name
2023/03/20 19:00:00 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:00 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:00 [lang:3] dynamic_source.get_id
2023/03/20 19:00:00 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:00 [s4:3] Prepared "/var/lib/libretime/playout/scheduler/483.mp3" (RID 0).
2023/03/20 19:00:00 [schedule_noise_switch:3] Switch to map_metadata_9692 with transition.
2023/03/20 19:00:00 [lang:3] transition called...
2023/03/20 19:00:00 [switch_9690:3] Switch to insert_metadata_9675.
2023/03/20 19:00:00 [cue_cut_9619:3] Cueing in...
2023/03/20 19:00:00 [lang:3] timeout --signal=KILL 45 libretime-playout-notify media '259048' &
2023/03/20 19:00:00 [lang:3] Using stream_format 0
2023/03/20 19:00:00 [lang:3] Using stream_format 0
2023/03/20 19:00:00 [lang:3] Using stream_format 0
2023-03-20 19:00:00.760 | INFO     | libretime_playout.notify.main:media:47 - Sending currently playing media id '259048'
2023/03/20 19:00:06 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:06 [lang:3] dynamic_source.get_id
2023/03/20 19:00:06 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:14 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:14 [lang:3] dynamic_source.get_id
2023/03/20 19:00:14 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:18 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:18 [lang:3] dynamic_source.get_id
2023/03/20 19:00:18 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:23 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:23 [lang:3] dynamic_source.get_id
2023/03/20 19:00:23 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:26 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:26 [lang:3] dynamic_source.get_id
2023/03/20 19:00:26 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:29 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:29 [lang:3] dynamic_source.get_id
2023/03/20 19:00:29 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:30 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:30 [lang:3] vars.show_name
2023/03/20 19:00:30 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:30 [cue_cut_9619:3] Cueing out...
2023/03/20 19:00:30 [cross_9625:3] Analysis: -32.068701dB / -nandB (0.00s / 0.00s)
2023/03/20 19:00:30 [decoder:3] Method "FFMPEG" accepted "/var/lib/libretime/playout/scheduler/483.mp3".
2023/03/20 19:00:30 [crossfade:3] Old <= medium, new <= medium and |old-new| <= margin.
2023/03/20 19:00:30 [crossfade:3] Old and new source are not too loud and close.
2023/03/20 19:00:30 [crossfade:3] Transition: crossed, fade-in, fade-out.
2023/03/20 19:00:30 [decoder:3] Method "FFMPEG" accepted "/var/lib/libretime/playout/scheduler/5531.mp3".
2023/03/20 19:00:30 [s4:3] Prepared "/var/lib/libretime/playout/scheduler/483.mp3" (RID 1).
2023/03/20 19:00:30 [cue_cut_9619:3] Cueing in...
2023/03/20 19:00:30 [lang:3] timeout --signal=KILL 45 libretime-playout-notify media '259048' &
2023/03/20 19:00:30 [lang:3] Using stream_format 0
2023/03/20 19:00:30 [lang:3] Using stream_format 0
2023/03/20 19:00:30 [lang:3] Using stream_format 0
2023-03-20 19:00:30.602 | INFO     | libretime_playout.notify.main:media:47 - Sending currently playing media id '259048'
2023/03/20 19:00:35 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:35 [lang:3] dynamic_source.get_id
2023/03/20 19:00:35 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:40 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:40 [lang:3] dynamic_source.get_id
2023/03/20 19:00:40 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:43 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:43 [lang:3] vars.show_name
2023/03/20 19:00:43 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:46 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:46 [lang:3] dynamic_source.get_id
2023/03/20 19:00:46 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:52 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:52 [lang:3] dynamic_source.get_id
2023/03/20 19:00:52 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:00:58 [server:3] New client: 127.0.0.1.
2023/03/20 19:00:58 [lang:3] dynamic_source.get_id
2023/03/20 19:00:58 [server:3] Client 127.0.0.1 disconnected.
2023/03/20 19:01:00 [cue_cut_9619:3] Cueing out...
2023/03/20 19:01:00 [s4:2] Finished with a non-existent file?! Something may have been moved or destroyed during decoding. It is VERY dangerous, avoid it!
2023/03/20 19:01:00 [s4:1] Failed to prepare track: request not ready.
2023/03/20 19:01:00 [cross_9625:3] Analysis: -32.004933dB / -nandB (0.00s / 0.00s)
2023/03/20 19:01:00 [crossfade:3] Old <= medium, new <= medium and |old-new| <= margin.
2023/03/20 19:01:00 [crossfade:3] Old and new source are not too loud and close.
2023/03/20 19:01:00 [crossfade:3] Transition: crossed, fade-in, fade-out.
2023/03/20 19:01:00 [dummy(dot)1:3] Source failed (no more tracks) stopping output...
2023/03/20 19:01:00 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2023/03/20 19:01:00 [schedule_noise_switch:3] Switch to map_metadata_9702 with forgetful transition.
2023/03/20 19:01:00 [lang:3] transition called...

LibreTime version

3.0.1

Installation method and OS / Environment

Operating system: Ubuntu 20.04.5 LTS
Method: installer script

Installation details

No response

Client Environment

Operating system: Windows 10
Browser: Version 111.0.5563.65

Screenshots

No response

[jooola]

Hmm, after a quick look at the playout logs, I wonder why you have so much update_schedule messages, does the schedule get updated every 5 to 20 seconds on the UI ? Some of the schedule send aren't even changing.

Btw, You seem to still rely on uwsgi, is that correct ?

You also have a lot of logs saying some of your files are missing, probably not related but just raising it here.

[rjhelms]

Hmm, after a quick look at the playout logs, I wonder why you have so much update_schedule messages, does the schedule get updated every 5 to 20 seconds on the UI ? Some of the schedule send aren't even changing.

That is a very good question. I'm not certain when update_schedule fires? Would updates to future shows cause it? I could definitely see updates every 5-20 seconds occurring in bursts as people are building out future programs, if every time someone adds a track to a show it sends update_schedule.

Btw, You seem to still rely on uwsgi, is that correct ?

How could I verify this? This instance was originally created on a build somewhere between alpha 8 and 9 (2003e68 per my notes) and has been upgraded a few times since, most recently to 3.0.1 in January.

Edit: based on my running processes, no uwsgi is running - Libretime is using gunicorn as expected after alpha-13.

You also have a lot of logs saying some of your files are missing, probably not related but just raising it here.

I have noticed that as well. Not sure what would cause that - all the files that are referenced in liquidsoap.log would be created (and deleted) by playout, yes?

[github-actions]

This issue has been automatically marked as stale because it has not had activity in the last 5 months. It will be closed if no activity occurs in the next month.
Please chat to us on the forum or ask for help on #libretime:matrix.org if you have any questions or need further support with getting this issue resolved.
You may also label an issue as pinned if you would like to make sure that it does not get closed by this bot.