Problems with scheduled programs not playing (log)

Get Help
1

Ubuntu : 20.04.6 LTS
Libretime ver : 3.1.0

I am attaching the log because there is a problem that the scheduled program does not play.

The audio wasn’t playing properly, so I tried the following way.

When I reboot the server, the audio in the schedule box was not played until the end.

It plays again properly as we move on to the next schedule section.

I’d like to ask what the cause is.

Logs when a scheduled program does not play at 18:00 (liquidsoap.log)

2024-01-11 17:59:46,686 | INFO     | libretime_playout.notify.main:media:72 - Sending currently playing media id '487'
2024/01/11 17:59:58 [cue_cut_9411:3] End of track before cue-out point.
2024/01/11 17:59:58 [switch:blank+schedule:3] Switch to map_metadata:offline with forgetful transition.
2024/01/11 17:59:58 [lang:3] transition called...
2024/01/11 17:59:58 [dummy(dot)3:3] Source failed (no more tracks) stopping output...
2024/01/11 17:59:58 [dummy(dot)1:3] Source failed (no more tracks) stopping output...
2024/01/11 18:00:00 [server:3] New client: 127.0.0.1.
2024/01/11 18:00:00 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 18:01:49 [server:3] New client: 127.0.0.1.
2024/01/11 18:01:49 [lang:3] web_stream.get_id
2024/01/11 18:01:49 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 18:02:05 [server:3] New client: 127.0.0.1.
2024/01/11 18:02:05 [lang:3] web_stream.get_id
2024/01/11 18:02:05 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 18:08:48 [server:3] New client: 127.0.0.1.
2024/01/11 18:08:48 [lang:3] web_stream.get_id
2024/01/11 18:08:48 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 18:15:29 [server:3] New client: 127.0.0.1.
2024/01/11 18:15:29 [lang:3] web_stream.get_id
2024/01/11 18:15:29 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 18:22:11 [server:3] New client: 127.0.0.1.

Logs when a scheduled program does not play at 18:00 (playout.log)

2024-01-11 17:58:23,424 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 17:58:23,424 | INFO     | libretime_playout.player.queue:main:39 - waiting 72.575266s until next scheduled item
2024-01-11 17:58:34,513 | INFO     | libretime_playout.message_handler:on_message:47 - handling event update_schedule: {'schedule': {'media': {'2024-0>
2024-01-11 17:58:34,515 | INFO     | libretime_playout.player.fetch:handle_message:110 - New timeout: 400.0
2024-01-11 17:58:34,515 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4412
2024-01-11 17:58:34,516 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 17:58:34,516 | INFO     | libretime_playout.player.queue:main:39 - waiting 61.483779s until next scheduled item
2024-01-11 17:59:36,019 | INFO     | libretime_playout.player.queue:main:39 - waiting 9.980147s until next scheduled item
2024-01-11 17:59:46,004 | INFO     | libretime_playout.player.queue:main:39 - waiting 13.995791s until next scheduled item
2024-01-11 18:00:00,002 | INFO     | libretime_playout.player.queue:main:36 - waiting indefinitely for schedule
2024-01-11 18:01:49,343 | INFO     | libretime_playout.message_handler:on_message:47 - handling event update_schedule: {'schedule': {'media': {'2024-0>
2024-01-11 18:01:49,344 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 280 to cache /var/lib/libretime/playout/scheduler/280.m>
2024-01-11 18:01:49,347 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:01:49,348 | INFO     | libretime_playout.player.queue:main:39 - waiting 10690.651664s until next scheduled item
2024-01-11 18:01:49,394 | INFO     | libretime_playout.player.fetch:cache_cleanup:255 - File '/var/lib/libretime/playout/scheduler/285.mp3' removed
2024-01-11 18:01:49,409 | INFO     | libretime_playout.player.fetch:cache_cleanup:255 - File '/var/lib/libretime/playout/scheduler/245.mp3' removed
2024-01-11 18:01:49,424 | INFO     | libretime_playout.player.fetch:cache_cleanup:255 - File '/var/lib/libretime/playout/scheduler/185.mp3' removed
2024-01-11 18:01:49,424 | INFO     | libretime_playout.player.fetch:handle_message:110 - New timeout: 400.0
2024-01-11 18:01:49,424 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4413
2024-01-11 18:01:49,972 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 276 to cache /var/lib/libretime/playout/scheduler/276.m>
2024-01-11 18:01:50,611 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 209 to cache /var/lib/libretime/playout/scheduler/209.m>
2024-01-11 18:02:05,990 | INFO     | libretime_playout.message_handler:on_message:47 - handling event update_schedule: {'schedule': {'media': {'2024-0>
2024-01-11 18:02:05,993 | INFO     | libretime_playout.player.fetch:handle_message:110 - New timeout: 400.0
2024-01-11 18:01:49,424 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4413
2024-01-11 18:01:49,972 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 276 to cache /var/lib/libretime/playout/scheduler/276.m>
2024-01-11 18:01:50,611 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 209 to cache /var/lib/libretime/playout/scheduler/209.m>
2024-01-11 18:02:05,990 | INFO     | libretime_playout.message_handler:on_message:47 - handling event update_schedule: {'schedule': {'media': {'2024-0>
2024-01-11 18:02:05,993 | INFO     | libretime_playout.player.fetch:handle_message:110 - New timeout: 400.0
2024-01-11 18:02:05,993 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4414
2024-01-11 18:02:05,995 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:02:05,995 | INFO     | libretime_playout.player.queue:main:39 - waiting 10674.004188s until next scheduled item
2024-01-11 18:08:45,994 | INFO     | libretime_playout.player.fetch:main:332 - Queue timeout. Fetching schedule manually
2024-01-11 18:08:48,041 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 105 to cache /var/lib/libretime/playout/scheduler/105.w>
2024-01-11 18:08:48,043 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4415
2024-01-11 18:08:48,045 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:08:48,045 | INFO     | libretime_playout.player.queue:main:39 - waiting 10271.954327s until next scheduled item
2024-01-11 18:08:48,104 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 140 to cache /var/lib/libretime/playout/scheduler/140.m>
2024-01-11 18:08:48,125 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 208 to cache /var/lib/libretime/playout/scheduler/208.m>
2024-01-11 18:08:48,138 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 286 to cache /var/lib/libretime/playout/scheduler/286.m>
2024-01-11 18:08:48,776 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 206 to cache /var/lib/libretime/playout/scheduler/206.m>
2024-01-11 18:08:48,805 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 104 to cache /var/lib/libretime/playout/scheduler/104.w>
2024-01-11 18:08:48,826 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 292 to cache /var/lib/libretime/playout/scheduler/292.m>
2024-01-11 18:08:49,356 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 234 to cache /var/lib/libretime/playout/scheduler/234.m>
2024-01-11 18:08:49,369 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 293 to cache /var/lib/libretime/playout/scheduler/293.m>
2024-01-11 18:08:49,983 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 229 to cache /var/lib/libretime/playout/scheduler/229.m>
2024-01-11 18:08:49,999 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 294 to cache /var/lib/libretime/playout/scheduler/294.m>
2024-01-11 18:08:50,614 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 188 to cache /var/lib/libretime/playout/scheduler/188.m>
2024-01-11 18:08:50,629 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 295 to cache /var/lib/libretime/playout/scheduler/295.m>
2024-01-11 18:08:51,243 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 231 to cache /var/lib/libretime/playout/scheduler/231.m>
2024-01-11 18:08:51,256 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 245 to cache /var/lib/libretime/playout/scheduler/245.m>
2024-01-11 18:08:51,275 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 299 to cache /var/lib/libretime/playout/scheduler/299.m>
2024-01-11 18:08:51,902 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 241 to cache /var/lib/libretime/playout/scheduler/241.m>
2024-01-11 18:08:51,916 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 296 to cache /var/lib/libretime/playout/scheduler/296.m>
2024-01-11 18:08:52,553 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 237 to cache /var/lib/libretime/playout/scheduler/237.m>
2024-01-11 18:08:52,569 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 297 to cache /var/lib/libretime/playout/scheduler/297.m>
2024-01-11 18:08:53,185 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 238 to cache /var/lib/libretime/playout/scheduler/238.m>
2024-01-11 18:08:53,200 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 158 to cache /var/lib/libretime/playout/scheduler/158.m>
2024-01-11 18:08:53,211 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 298 to cache /var/lib/libretime/playout/scheduler/298.m>
2024-01-11 18:08:53,883 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 239 to cache /var/lib/libretime/playout/scheduler/239.m>
2024-01-11 18:08:53,900 | INFO     | libretime_playout.player.file:copy_file:47 - copying file 167 to cache /var/lib/libretime/playout/scheduler/167.m>
2024-01-11 18:15:28,044 | INFO     | libretime_playout.player.fetch:main:332 - Queue timeout. Fetching schedule manually
2024-01-11 18:15:29,974 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4416
2024-01-11 18:15:29,976 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:15:29,977 | INFO     | libretime_playout.player.queue:main:39 - waiting 9870.022831s until next scheduled item
2024-01-11 18:22:09,975 | INFO     | libretime_playout.player.fetch:main:332 - Queue timeout. Fetching schedule manually
2024-01-11 18:22:11,948 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4417
2024-01-11 18:22:11,950 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:22:11,950 | INFO     | libretime_playout.player.queue:main:39 - waiting 9468.049462s until next scheduled item
2024-01-11 18:28:51,949 | INFO     | libretime_playout.player.fetch:main:332 - Queue timeout. Fetching schedule manually
2024-01-11 18:28:53,954 | INFO     | libretime_playout.player.fetch:main:311 - Loop #4418
2024-01-11 18:28:53,955 | INFO     | libretime_playout.player.queue:main:57 - New schedule received
2024-01-11 18:28:53,955 | INFO     | libretime_playout.player.queue:main:39 - waiting 9066.044467s until next scheduled item
2024-01-11 18:35:33,954 | INFO     | libretime_playout.player.fetch:main:332 - Queue timeout. Fetching schedule manually

Finally, the server reboot, the program still fails to play. (liquidsoap.log)

2024/01/11 19:23:53 >>> LOG START
2024/01/11 19:23:52 [main:3] Liquidsoap 1.4.2
2024/01/11 19:23:52 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=[unspecified] sedlex=2.1 menhirLib=20200123 dtools=0.4.1 duppy=0>
2024/01/11 19:23:52 [gstreamer.loader:3] Loaded GStreamer 1.16.3 0
2024/01/11 19:23:52 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
2024/01/11 19:23:52 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz master.
2024/01/11 19:23:52 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2024/01/11 19:23:52 [frame:3] Targetting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2024/01/11 19:23:52 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2024/01/11 19:23:53 [lang:3] timeout --signal=KILL 45 libretime-playout-notify started &
2024/01/11 19:23:53 [sandbox:3] Sandboxing disabled
2024/01/11 19:23:53 [video.converter:3] Using preferred video converter: gavl.
2024/01/11 19:23:53 [audio.converter:3] Using samplerate converter: ffmpeg.
2024/01/11 19:23:53 [harbor:3] Adding mountpoint '/show' on port 8002
2024/01/11 19:23:53 [harbor:3] Adding mountpoint '/main' on port 8001
2024/01/11 19:23:53 [icecast:1:3] Connecting mount main for source@localhost...
2024/01/11 19:23:53 [icecast:1:3] Connection setup was successful.
2024/01/11 19:23:53 [lang:3] timeout --signal=KILL 45 libretime-playout-notify stream '1' '1704968632.99' &
2024/01/11 19:23:53 [clock.wallclock_main:3] Streaming loop starts, synchronized with wallclock.
2024/01/11 19:23:53 [map_metadata:offline:3] Inserting missing metadata.
2024/01/11 19:23:53 [switch:blank+schedule+show+main:3] Switch to switch:blank+schedule+show.
2024/01/11 19:23:53 [switch:blank+schedule+show:3] Switch to switch:blank+schedule.
2024/01/11 19:23:53 [switch:blank+schedule:3] Switch to map_metadata:offline.
2024-01-11 19:23:53,142 | INFO     | libretime_playout.notify.main:stream:153 - Sending output stream '1' status 'OK'
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [lang:3] queues.s0_skip
2024/01/11 19:23:53 [lang:3] queues.s1_skip
2024/01/11 19:23:53 [lang:3] queues.s2_skip
2024/01/11 19:23:53 [lang:3] queues.s3_skip
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [lang:3] sources.stop_input_main
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [lang:3] sources.stop_input_show
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [lang:3] sources.start_schedule
2024/01/11 19:23:53 [server:3] Client 127.0.0.1 disconnected.
2024/01/11 19:23:53 [server:3] New client: 127.0.0.1.
2024/01/11 19:23:53 [lang:3] queues.s0_skip
2

I’m also having a similar issue with v3.0.2 and 4.0.0.
The show is correctly loaded and tracks appear as playing normally. But the “on air” light goes off and output is lost.
Attaching more logs:

==> /var/log/libretime/liquidsoap.log <==
2024/02/22 07:18:55 [schedule_noise_switch:3] Switch to map_metadata_9897 with transition.
2024/02/22 07:18:55 [lang:3] transition called…
2024-02-22 07:18:56.076 | INFO | libretime_playout.notify.main:media:47 - Sending currently playing media id ‘2955’
2024/02/22 07:22:03 [cue_cut_9824:3] Cueing out…
2024/02/22 07:22:03 [cross_9830:3] Analysis: -30.602426dB / -nandB (0.00s / 0.00s)
2024/02/22 07:22:03 [crossfade:3] No transition: using default.
2024/02/22 07:22:03 [schedule_noise_switch:3] Switch to map_metadata_9907 with forgetful transition.
2024/02/22 07:22:03 [lang:3] transition called…
2024/02/22 07:22:03 [dummy(dot)2:3] Source failed (no more tracks) stopping output…
2024/02/22 07:22:03 [dummy:3] Source failed (no more tracks) stopping output…

/var/log/libretime/playout.log <==
│ │ │ │ └ (<libretime_playout.player.liquidsoap_gateway.TelnetLiquidsoap object at 0x7f8e672209d0>, ‘s4’, {‘type’: <EventKind.FILE: 'fi…
│ │ │ └ None
│ │ └ 15
│ └ <function TelnetLiquidsoap.queue_push at 0x7f8e67b23670>
└ <function __timeout at 0x7f8e67b9dca0>

File “/usr/local/lib/python3.9/dist-packages/libretime_playout/timeout.py”, line 21, in __timeout
raise RuntimeError(“Thread did not terminate”)

RuntimeError: Thread did not terminate

==> /var/log/libretime/playout.log <==

File “/usr/local/lib/python3.9/dist-packages/libretime_playout/timeout.py”, line 21, in __timeout
raise RuntimeError(“Thread did not terminate”)

RuntimeError: Thread did not terminate
2024-02-24 09:05:01.620 | INFO | libretime_playout.player.fetch:main:412 - Queue timeout. Fetching schedule manually
2024-02-24 09:05:05.483 | INFO | libretime_playout.player.liquidsoap:verify_correct_present_media:177 - Need to add items to Liquidsoap now: {3405}
2024-02-24 09:05:05.592 | INFO | libretime_playout.player.fetch:cache_cleanup:337 - File ‘/var/lib/libretime/playout/scheduler/210.mp3’ removed
2024-02-24 09:05:05.698 | INFO | libretime_playout.player.fetch:cache_cleanup:337 - File ‘/var/lib/libretime/playout/scheduler/22.mp3’ removed
2024-02-24 09:05:05.701 | INFO | libretime_playout.player.fetch:main:391 - Loop #3105