Closed Vaalyn closed 2 years ago
I have broken down the generated Liquidsoap script in order to replicate this issue and found that the short script seems to not cause this double-fetching when I call local_3.skip
or dynamic_startup.skip
.
Here is the short script I built:
init.allow_root.set(true)
init.daemon.set(false)
init.daemon.pidfile.path.set("/var/azuracast/liquidsoap-test.pid")
log.stdout.set(true)
log.file.set(false)
settings.server.telnet.set(true)
settings.server.telnet.bind_addr.set("0.0.0.0")
settings.server.telnet.port.set(8104)
settings.harbor.bind_addrs.set(["0.0.0.0"])
settings.tag.encodings.set(["UTF-8","ISO-8859-1"])
settings.encoder.metadata.export.set(["artist","title","album","song"])
setenv("TZ", "Europe/Berlin")
autodj_is_loading = ref(true)
ignore(autodj_is_loading)
autodj_ping_attempts = ref(0)
ignore(autodj_ping_attempts)
# AutoDJ Next Song Script
def autodj_next_song() =
uri = list.hd(default="", process.read.lines('php /var/azuracast/test.php'))
log("Raw Response: #{uri}")
if uri == "" or string.match(pattern="Error", uri) then
[]
else
r = request.create(uri)
if request.resolve(r) then
[r]
else
[]
end
end
end
# Delayed ping for AutoDJ Next Song
def wait_for_next_song(autodj)
autodj_ping_attempts := !autodj_ping_attempts + 1
delay = ref(0.5)
if source.is_ready(!autodj) then
log("AutoDJ is ready!")
autodj_is_loading := false
delay := -1.0
elsif !autodj_ping_attempts > 200 then
log("AutoDJ could not be initialized within the specified timeout.")
autodj_is_loading := false
delay := -1.0
end
!delay
end
dynamic = mksafe(request.dynamic.list(id="next_song", timeout=20., retry_delay=2., autodj_next_song))
dynamic = cue_cut(id="cue_next_song", dynamic)
radio = fallback(
id = "dynamic_startup",
track_sensitive = false,
[
dynamic,
source.available(
blank(id = "autodj_startup_blank", duration = 120.),
predicate.activates({!autodj_is_loading})
)
]
)
ref_dynamic = ref(dynamic);
thread.run.recurrent(delay=0.25, { wait_for_next_song(ref_dynamic) })
add_skip_command(radio)
output.icecast(%mp3(samplerate=44100, stereo=true, bitrate=128, id3v2=true), id="local_3", host = "127.0.0.1", port = 8000, password = "na4R2NKn", mount = "/test", name = "Blah", description = "A test radio station.", genre = "Test Genre", public = true, encoding = "UTF-8", radio)
The php script that I call with list.hd(default="", process.read.lines('php /var/azuracast/test.php'))
looks like this:
<?php
file_put_contents(__DIR__ . '/debug.txt', time() . PHP_EOL, FILE_APPEND);
$songs = [
'annotate:title="No Better Feelin\'",artist="Lee Chae-rin",duration="173.00",liq_amplify="0.00dB":/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/11 - No Better Feelin\'.mp3',
'annotate:title="I\'m The Friend You Need",artist="Daniel Ingram",duration="135.00",liq_amplify="0.00dB":/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/02 - I\'m The Friend You Need.mp3',
'annotate:title="I\'ll Be Around",artist="Palmer Reed",duration="229.00",liq_amplify="0.00dB":/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/12 - I\'ll Be Around.mp3',
'annotate:title="Time To Be Awesome",artist="Daniel ingram",duration="173.00",liq_amplify="0.00dB":/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/03 - Time To Be Awesome.mp3',
];
echo $songs[array_rand($songs)];
With the file_put_contents
at the top of the PHP script I'm checking the timestamps when the script was called to see if there are multiple entries at the same time which would indicate double-fetching.
After some further tests it looks like after updating the Liquidsoap version from bb61734bcb3b844352a496b7e5a21129d78badc5 to the full 2.0 release it does not send multiple requests anymore but when skipping it is still behaving in a "strange" way.
I'll try to describe what I'm seeing:
The request.dynamic.list
is set with the default prefetch of 1
.
The song A - A
ist currently playing, LS has prefetched B - B
as the next song.
In the AzuraCast upcoming song queue there are C - C
, D - D
and E - E
.
I send a skip
command to LS, it calls the next song API / script, gets C - C
and instead of playing the already prefetched B - B
it is playing the C - C
that was returned by the request to the next song API / script. When it then finished playing the C - C
it switches to the previously fetched B - B
.
Am I doing something "wrong" in the script that is causing LS to pick C - C
before the already prefetched B - B
?
Hi @Vaalyn. Thanks for this report and your work testing different versions.
Is there any chance you could test from the v2.0.1
branch? This is our upcoming bugfix release branch. I have pushed some cleanup of request.dynamic
, particularly removing request.dynamic.list
that had an unnecessary complexity using list
due to the fact that we did not have a null
type some time ago.
Now, there is only request.dynamic
, which can return null
if no requests are available, and request.dynamic.list
is built on top of it. This allowed to cleanup the internal implementation logic. There's a good chance this might fix the behavior that you are seeing.
Hey @toots, I've tried with the v2.0.1
branch, specifically commit 43aa734dd37595e991ad7d8d9b8560e7d47c19fe
This version behaves in the same way as v2.0.0
in that it prefers the newly requested song over the already prefetched one.
I have changed the LS script to use request.dynamic
and changed the callback autodj_next_song()
to return the request or null()
accordingly to match the signature required for request.dynamic
.
For reference:
def autodj_next_song() =
uri = list.hd(process.read.lines(env=[("API_AUTH", !azuracast_api_auth)], 'curl -s --request POST --url http://web/api/internal/1/nextsong --form api_auth="$API_AUTH"'), default="")
log("AzuraCast Raw Response: #{uri}")
if uri == "" or string.match(pattern="Error", uri) then
null()
else
r = request.create(uri)
if request.resolve(r) then
r
else
null()
end
end
end
...
dynamic = request.dynamic(id="next_song", timeout=20., retry_delay=2., autodj_next_song)
Here is the LS log from when I tested the skipping on this version:
2021/11/08 06:11:49 [requests:3] Prepared "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/05 - Open Up Your Eyes.mp3" (RID 11).
2021/11/08 06:11:49 [requests_fallback:3] Switch to cue_requests with forgetful transition.
[mp3float @ 0x7f432d4da640] Could not update timestamps for skipped samples.
2021/11/08 06:11:49 [cue_requests:3] Cueing in...
2021/11/08 06:11:49 [crossfade_0:3] Analysis: -10.524359dB / -20.505240dB (2.96s / 2.96s)
2021/11/08 06:11:49 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
2021/11/08 06:11:49 [lang:3] AzuraCast Feedback Response: OK
2021/11/08 06:15:09 [decoder:2] Decoding "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/05 - Open Up Your Eyes.mp3" ended: Ffmpeg_decoder.End_of_file.
2021/11/08 06:15:09 [requests_fallback:3] Switch to autodj_fallback with forgetful transition.
2021/11/08 06:15:09 [dynamic_startup:3] Switch to cue_next_song.
[mp3float @ 0x7f432c0da980] Could not update timestamps for skipped samples.
2021/11/08 06:15:09 [cue_next_song:3] Cueing in...
2021/11/08 06:15:09 [crossfade_0:3] Analysis: -66.696927dB / -16.782825dB (2.96s / 2.96s)
2021/11/08 06:15:09 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
2021/11/08 06:15:10 [lang:3] AzuraCast Feedback Response: OK
2021/11/08 06:15:10 [lang:3] AzuraCast Raw Response: annotate:title="I'll Chase The Sky",artist="Paul Blair",duration="172.00",song_id="3cbb3823523518d9d27ea333dd4cb956",media_id="2676",liq_amplify="0.00dB",playlist_id="1":/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/10 - I'll Chase The Sky.mp3
2021/11/08 06:16:13 [server:3] New client: 172.18.0.5.
2021/11/08 06:16:13 [server:3] Client 172.18.0.5 disconnected.
2021/11/08 06:16:13 [server:3] New client: 172.18.0.5.
2021/11/08 06:16:13 [server:3] Client 172.18.0.5 disconnected.
2021/11/08 06:16:13 [next_song:3] Prepared "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/10 - I\'ll Chase The Sky.mp3" (RID 12).
2021/11/08 06:16:13 [requests:3] Prepared "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/07 - Off To See The World.mp3" (RID 13).
2021/11/08 06:16:13 [requests_fallback:3] Switch to cue_requests with forgetful transition.
[mp3float @ 0x7f432dd6bb80] Could not update timestamps for skipped samples.
2021/11/08 06:16:13 [cue_requests:3] Cueing in...
2021/11/08 06:16:13 [crossfade_0:3] Analysis: -10.694457dB / -37.310025dB (2.96s / 2.96s)
2021/11/08 06:16:13 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
2021/11/08 06:16:13 [lang:3] AzuraCast Feedback Response: OK
2021/11/08 06:19:14 [decoder:2] Decoding "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/07 - Off To See The World.mp3" ended: Ffmpeg_decoder.End_of_file.
2021/11/08 06:19:14 [requests_fallback:3] Switch to autodj_fallback with forgetful transition.
[mp3float @ 0x7f432ca85480] Could not update timestamps for skipped samples.
2021/11/08 06:19:14 [cue_next_song:3] Cueing in...
2021/11/08 06:19:14 [crossfade_0:3] Analysis: -72.784371dB / -26.692810dB (2.96s / 2.96s)
2021/11/08 06:19:14 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
As you can see here it is preparing these 2 songs after the skip:
2021/11/08 06:16:13 [next_song:3] Prepared "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/10 - I\'ll Chase The Sky.mp3" (RID 12).
2021/11/08 06:16:13 [requests:3] Prepared "/var/azuracast/stations/azuratest_radio/media/MLP Movie Soundtrack/07 - Off To See The World.mp3" (RID 13).
The song I'll Chase The Sky.mp3
is the one that was already prefetched and Off To See The World.mp3
is the one that was fetched when the skip command was sent to LS. It then started playing the Off To See The World.mp3
and right after it finished it started playing the I'll Chase The Sky.mp3
.
Thanks for checking this. I'll try to reproduce locally very soon.
Hi, thanks for the report. I'm gonna try to reproduce today. Couple of things meanwhile:
log.level.set(4)
?Can you try without resolving the request:
def autodj_next_song() =
uri = list.hd(process.read.lines(env=[("API_AUTH", !azuracast_api_auth)], 'curl -s --request POST --url http://web/api/internal/1/nextsong --form api_auth="$API_AUTH"'), default="")
log("AzuraCast Raw Response: #{uri}")
if uri == "" or string.match(pattern="Error", uri) then
null()
else
request.create(uri)
end
end
With 2.0.x
, request resolution depends on the expect audio content of the source so it's better to let the source perform the resolution b/c it knows what to expect for format.
I've made the changes to the autodj_next_song()
code as instructed and set the log level to 4
.
Still the same behaviour, the newly requested song is played before the prefetched one.
Here is the log output:
2021/11/10 17:14:14 >>> LOG START
2021/11/10 17:14:12 [main:3] Liquidsoap 2.0.1+git@43aa734d
2021/11/10 17:14:12 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.5.0 sedlex=2.4 menhirLib=20211012 curl=0.9.1 dtools=0.4.4 duppy=0.9.2 cry=0.6.5 mm=0.7.1 ogg=0.7.0 ogg.decoder=0.7.0 vorbis=0.8.0 vorbis.decoder=0.8.0 opus=0.2.0 opus.decoder=0.2.0 mad=0.5.0 flac=0.3.0 flac.ogg=0.3.0 flac.decoder=0.3.0 dynlink=[distributed with Ocaml] lame=0.3.4 frei0r=0.1.2 fdkaac=0.3.2 ffmpeg-avutil=1.0.1 ffmpeg-avcodec=1.0.1 ffmpeg-avdevice=1.0.1 ffmpeg-av=1.0.1 ffmpeg-avfilter=1.0.1 ffmpeg-swresample=1.0.1 ffmpeg-swscale=1.0.1 samplerate=0.1.6 taglib=0.3.6 ssl=0.5.9 camomile=1.0.2 faad=0.5.0 ladspa=0.2.0
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:12 [main:3] DISCLAIMER: This version of Liquidsoap has been
2021/11/10 17:14:12 [main:3] compiled from a snapshot of the development code.
2021/11/10 17:14:12 [main:3] As such, it should not be used in production
2021/11/10 17:14:12 [main:3] unless you know what you are doing!
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:12 [main:3] We are, however, very interested in any feedback
2021/11/10 17:14:12 [main:3] about our development code and committed to fix
2021/11/10 17:14:12 [main:3] issues as soon as possible.
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:12 [main:3] If you are interested in collaborating to
2021/11/10 17:14:12 [main:3] the development of Liquidsoap, feel free to
2021/11/10 17:14:12 [main:3] drop us a mail at <savonet-devl@lists.sf.net>
2021/11/10 17:14:12 [main:3] or to join the slack chat at <http://slack.liquidsoap.info>.
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:12 [main:3] Please send any bug report or feature request
2021/11/10 17:14:12 [main:3] at <https://github.com/savonet/liquidsoap/issues>.
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:12 [main:3] We hope you enjoy this snapshot build of Liquidsoap!
2021/11/10 17:14:12 [main:3]
2021/11/10 17:14:13 [clock:3] Using builtin (low-precision) implementation for latency control
2021/11/10 17:14:14 [playlist_default:4] Reloading playlist.
2021/11/10 17:14:14 [playlist parser:4] Trying youtube-dl parser
2021/11/10 17:14:14 [playlist parser:4] Trying application/x-cue parser
2021/11/10 17:14:14 [playlist parser:4] Trying audio/x-scpls parser
2021/11/10 17:14:14 [playlist parser:4] Trying application/x-mpegURL parser
2021/11/10 17:14:14 [frame:4] frame.audio.samplerate set to: 44100
2021/11/10 17:14:14 [frame:4] frame.video.framerate set to: 25
2021/11/10 17:14:14 [frame:4] frame.audio.channels set to: 2
2021/11/10 17:14:14 [frame:4] frame.video.default set to: false
2021/11/10 17:14:14 [frame:4] frame.midi.channels set to: 0
2021/11/10 17:14:14 [frame:4] frame.video.width set to: 1280
2021/11/10 17:14:14 [frame:4] frame.video.height set to: 720
2021/11/10 17:14:14 [frame:4] frame.audio.samplerate set to: 44100
2021/11/10 17:14:14 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2021/11/10 17:14:14 [frame:3] Video frame size set to: 1280x720
2021/11/10 17:14:14 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2021/11/10 17:14:14 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2021/11/10 17:14:14 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2021/11/10 17:14:14 [sandbox:3] Running inside a docker container, disabling sandboxing.
2021/11/10 17:14:14 [video.converter:3] Using preferred video converter: ffmpeg.
2021/11/10 17:14:14 [audio.converter:3] Using samplerate converter: ffmpeg.
2021/11/10 17:14:14 [clock:4] Currently 5 clocks allocated.
2021/11/10 17:14:14 [clock.main:4] Starting 5 sources...
2021/11/10 17:14:14 [source:4] Source input_streamer gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [input_streamer:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [harbor:4] Opening port 8005 with icy = false
2021/11/10 17:14:14 [harbor:4] Opening port 8006 with icy = true
2021/11/10 17:14:14 [harbor:3] Adding mountpoint '/' on port 8005
2021/11/10 17:14:14 [source:4] Source output.dummy_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [dummy:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source local_1 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [local_1:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source safe_fallback gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source compress_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [compress_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source amplify_2 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [amplify_2:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source amplify_1 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [amplify_1:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source on_frame_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [on_frame_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source rms_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [rms_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source amplify_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [amplify_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source custom_metadata gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [custom_metadata:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source live_fallback gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source crossfade_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [crossfade_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source requests_fallback gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source cue_requests gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [cue_requests:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source requests gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [requests:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source autodj_fallback gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source dynamic_startup gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source cue_next_song gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [cue_next_song:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source next_song gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [next_song:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source source.available_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source.available_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source autodj_startup_blank gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [autodj_startup_blank:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source standard_playlists gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source switch_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source cue_playlist_default gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [cue_playlist_default:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source playlist_default gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [playlist_default:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [source:4] Source error_jingle gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [error_jingle:3] /usr/local/share/icecast/web/error.mp3 is static, resolving once for all...
2021/11/10 17:14:14 [decoder.ogg:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.mp4:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.aac:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.flac:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.aiff:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.wav:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
2021/11/10 17:14:14 [decoder.ffmpeg:4] ffmpeg recognizes /usr/local/share/icecast/web/error.mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [decoder:4] Selected decoder FFMPEG for file "/usr/local/share/icecast/web/error.mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:14:14 [metadata.flac:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [metadata.mp4:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [decoder.ogg:4] Unsupported file extension for "/usr/local/share/icecast/web/error.mp3"!
2021/11/10 17:14:14 [error_jingle:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [error_jingle:3] Prepared "/usr/local/share/icecast/web/error.mp3" (RID 1).
2021/11/10 17:14:14 [local_1:3] Connecting mount /radio for source@127.0.0.1...
2021/11/10 17:14:14 [local_1:3] Connection setup was successful.
2021/11/10 17:14:14 [source:4] Source local_2 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [local_2:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [local_2:3] Connecting mount /test for source@127.0.0.1...
2021/11/10 17:14:14 [local_2:3] Connection setup was successful.
2021/11/10 17:14:14 [source:4] Source local_3 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [local_3:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:14 [local_3:3] Connecting mount /ueh for source@127.0.0.1...
2021/11/10 17:14:15 [local_3:3] Connection setup was successful.
2021/11/10 17:14:15 [clock.main:3] Streaming loop starts in auto-sync mode
2021/11/10 17:14:15 [clock.main:3] Delegating synchronisation to CPU clock
2021/11/10 17:14:15 [threads:4] Created thread "clock_main" (1 total).
2021/11/10 17:14:15 [clock:4] Main phase starts.
2021/11/10 17:14:15 [threads:4] Created thread "generic queue #1" (1 total).
2021/11/10 17:14:15 [threads:4] Created thread "generic queue #2" (2 total).
2021/11/10 17:14:15 [threads:4] Created thread "non-blocking queue #1" (3 total).
2021/11/10 17:14:15 [threads:4] Created thread "non-blocking queue #2" (4 total).
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.aac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.aiff:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.wav:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
[mp3 @ 0x7f2490005580] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7f2490021940] Estimating duration from bitrate, this may be inaccurate
2021/11/10 17:14:15 [decoder.ffmpeg:4] ffmpeg recognizes /var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:15 [decoder:4] Selected decoder FFMPEG for file "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:14:15 [metadata.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [metadata.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3"!
[mp3float @ 0x7f249800f300] Could not update timestamps for skipped samples.
2021/11/10 17:14:15 [dummy:3] Source failed (no more tracks) stopping output...
2021/11/10 17:14:15 [safe_fallback:3] Switch to error_jingle.
2021/11/10 17:14:15 [playlist_default:4] Queued 1 requests
2021/11/10 17:14:15 [playlist_default:4] Remaining 0 requests
[mp3 @ 0x7f249812b2c0] Estimating duration from bitrate, this may be inaccurate
[mp3 @ 0x7f2498144440] Estimating duration from bitrate, this may be inaccurate
2021/11/10 17:14:15 [playlist_default:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3" (RID 2).
2021/11/10 17:14:15 [safe_fallback:3] Switch to compress_0 with transition.
2021/11/10 17:14:15 [live_fallback:3] Switch to crossfade_0.
2021/11/10 17:14:15 [crossfade_0:4] Buffering end of track...
2021/11/10 17:14:15 [requests_fallback:3] Switch to autodj_fallback.
2021/11/10 17:14:15 [autodj_fallback:3] Switch to standard_playlists.
2021/11/10 17:14:15 [standard_playlists:3] Switch to switch_0.
2021/11/10 17:14:15 [switch_0:3] Switch to cue_playlist_default.
2021/11/10 17:14:15 [cue_playlist_default:4] Cue points : none / none
2021/11/10 17:14:15 [cue_playlist_default:3] Cueing in...
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.aac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.aiff:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.wav:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
2021/11/10 17:14:15 [crossfade_0:4] More buffering will be needed.
2021/11/10 17:14:15 [amplify_0:4] Overriding amplification: 1.000000.
2021/11/10 17:14:15 [amplify_2:4] Overriding amplification: 1.000000.
2021/11/10 17:14:15 [decoder.ffmpeg:4] ffmpeg recognizes /var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:15 [decoder:4] Selected decoder FFMPEG for file "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:14:15 [metadata.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [metadata.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3"!
2021/11/10 17:14:15 [playlist_default:4] Queued 1 requests
2021/11/10 17:14:15 [lang:3] AzuraCast Raw Response: annotate:title="She Calmed Down",artist="Neighsayer",duration="352.00",song_id="ffdc79e9baac02c73cb5f1258b6835bd",media_id="631",liq_amplify="0.00dB",playlist_id="20":/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.aac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.aiff:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.wav:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
2021/11/10 17:14:15 [decoder.ffmpeg:4] ffmpeg recognizes /var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:14:15 [decoder:4] Selected decoder FFMPEG for file "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:14:15 [metadata.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [metadata.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3"!
2021/11/10 17:14:15 [next_song:4] Queued 1 requests
2021/11/10 17:14:15 [lang:3] AzuraCast Feedback Response: OK
2021/11/10 17:14:15 [next_song:4] Remaining 0 requests
2021/11/10 17:14:15 [next_song:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3" (RID 4).
2021/11/10 17:14:15 [lang:3] AutoDJ is ready!
2021/11/10 17:15:07 [server:3] New client: 172.25.0.5.
2021/11/10 17:15:07 [requests:4] Pushing <request(id=5)> on the queue.
2021/11/10 17:15:07 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.aac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.aiff:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.wav:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
2021/11/10 17:15:07 [decoder.ffmpeg:4] ffmpeg recognizes /var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [decoder:4] Selected decoder FFMPEG for file "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:15:07 [metadata.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [metadata.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3"!
2021/11/10 17:15:07 [requests:4] Queued 1 requests
2021/11/10 17:15:07 [server:3] Client 172.25.0.5 disconnected.
2021/11/10 17:15:07 [server:3] New client: 172.25.0.5.
2021/11/10 17:15:07 [playlist_default:4] Finished with "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It's Okay (Periwinkle Edit).mp3".
2021/11/10 17:15:07 [server:3] Client 172.25.0.5 disconnected.
2021/11/10 17:15:07 [playlist_default:4] Remaining 0 requests
2021/11/10 17:15:07 [playlist_default:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3" (RID 3).
2021/11/10 17:15:07 [autodj_fallback:3] Switch to dynamic_startup with forgetful transition.
2021/11/10 17:15:07 [requests:4] Remaining 0 requests
2021/11/10 17:15:07 [requests:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3" (RID 5).
2021/11/10 17:15:07 [requests_fallback:3] Switch to cue_requests with forgetful transition.
[mp3float @ 0x7f249856ebc0] Could not update timestamps for skipped samples.
2021/11/10 17:15:07 [cue_requests:4] Cue points : none / none
2021/11/10 17:15:07 [cue_requests:3] Cueing in...
2021/11/10 17:15:07 [crossfade_0:3] Analysis: -14.073396dB / -41.825024dB (2.96s / 2.96s)
2021/11/10 17:15:07 [crossfade_0:4] Before: ("on_air_timestamp", "1636564455.00")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("encoded_by", "Online Media Technologies")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("kind", "{audio=pcm(stereo),video=none,midi=none}")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("artist", "Single Purpose")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("decoder", "FFMPEG")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("title", "It\'s Okay (Periwinkle Edit)")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("filename", "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("temporary", "false")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("source", "playlist_default")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("media_id", "709")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("initial_uri", "annotate:title=\"It\'s Okay (Periwinkle Edit)\",artist=\"Single Purpose\",duration=\"296.00\",song_id=\"1bcd8c0bb8b2f3b4c7b1a6f6d39c1eb8\",media_id=\"709\",liq_amplify=\"0.00dB\",playlist_id=\"20\":/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It\'s Okay (Periwinkle Edit).mp3")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("song_id", "1bcd8c0bb8b2f3b4c7b1a6f6d39c1eb8")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("tenc", "Online Media Technologies")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("url", "https://www.avs4you.com")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("status", "playing")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("encodedby", "Online Media Technologies")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("wxxx", "\u0001\uFFFD\uFFFD\u0000\u0000https://www.avs4you.com")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("playlist_id", "20")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("on_air", "2021/11/10 17:14:15")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("rid", "2")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("duration", "296.00")
2021/11/10 17:15:07 [crossfade_0:4] Before: ("liq_amplify", "0.00dB")
2021/11/10 17:15:07 [crossfade_0:4] After : ("on_air_timestamp", "1636564507.00")
2021/11/10 17:15:07 [crossfade_0:4] After : ("tempo", "125.13")
2021/11/10 17:15:07 [crossfade_0:4] After : ("kind", "{audio=pcm(stereo),video=none,midi=none}")
2021/11/10 17:15:07 [crossfade_0:4] After : ("artist", "Carbon Maestro")
2021/11/10 17:15:07 [crossfade_0:4] After : ("decoder", "FFMPEG")
2021/11/10 17:15:07 [crossfade_0:4] After : ("title", "Darkest Hour")
2021/11/10 17:15:07 [crossfade_0:4] After : ("bpm", "125.13")
2021/11/10 17:15:07 [crossfade_0:4] After : ("filename", "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3")
2021/11/10 17:15:07 [crossfade_0:4] After : ("tlen", "187430")
2021/11/10 17:15:07 [crossfade_0:4] After : ("temporary", "false")
2021/11/10 17:15:07 [crossfade_0:4] After : ("source", "requests")
2021/11/10 17:15:07 [crossfade_0:4] After : ("media_id", "629")
2021/11/10 17:15:07 [crossfade_0:4] After : ("initial_uri", "annotate:title=\"Darkest Hour\",artist=\"Carbon Maestro\",duration=\"187.00\",song_id=\"b3eaa7634c4ffc593bfae2a400659e7c\",media_id=\"629\",liq_amplify=\"0.00dB\",playlist_id=\"20\":/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3")
2021/11/10 17:15:07 [crossfade_0:4] After : ("length", "187430")
2021/11/10 17:15:07 [crossfade_0:4] After : ("song_id", "b3eaa7634c4ffc593bfae2a400659e7c")
2021/11/10 17:15:07 [crossfade_0:4] After : ("tkey", "Dm")
2021/11/10 17:15:07 [crossfade_0:4] After : ("status", "playing")
2021/11/10 17:15:07 [crossfade_0:4] After : ("replaygain_track_gain", "-3.923 dB")
2021/11/10 17:15:07 [crossfade_0:4] After : ("initialkey", "Dm")
2021/11/10 17:15:07 [crossfade_0:4] After : ("tbpm", "125.13")
2021/11/10 17:15:07 [crossfade_0:4] After : ("playlist_id", "20")
2021/11/10 17:15:07 [crossfade_0:4] After : ("on_air", "2021/11/10 17:15:07")
2021/11/10 17:15:07 [crossfade_0:4] After : ("popm", "\u0000\u0000")
2021/11/10 17:15:07 [crossfade_0:4] After : ("rid", "5")
2021/11/10 17:15:07 [crossfade_0:4] After : ("duration", "187.00")
2021/11/10 17:15:07 [crossfade_0:4] After : ("liq_amplify", "0.00dB")
2021/11/10 17:15:07 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
2021/11/10 17:15:07 [source:4] Source add_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [add_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source fade.in gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [fade.in:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source fade.in gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [fade.in:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source crossfade_0_after gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [crossfade_0_after:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source buffer_1 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [buffer_1:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source fade.out gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [fade.out:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source fade.out gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [fade.out:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source on_end_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [on_end_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source crossfade_0_before gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [crossfade_0_before:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [source:4] Source buffer_0 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [buffer_0:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:15:07 [crossfade_0_after:4] Fading in (type: sin, duration: 2.s).
2021/11/10 17:15:07 [amplify_0:4] Overriding amplification: 1.000000.
2021/11/10 17:15:07 [amplify_2:4] Overriding amplification: 1.000000.
2021/11/10 17:15:08 [lang:3] AzuraCast Feedback Response: OK
2021/11/10 17:15:08 [crossfade_0_before:4] Fading out with 2.s remaining.
2021/11/10 17:15:10 [buffer_1:4] Buffer emptied, buffering needed.
2021/11/10 17:15:10 [buffer_0:4] Buffer emptied, buffering needed.
2021/11/10 17:15:10 [crossfade_0:4] Buffering end of track...
2021/11/10 17:15:10 [crossfade_0:4] More buffering will be needed.
2021/11/10 17:18:11 [decoder:4] Decoding "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3" ended: Ffmpeg_decoder.End_of_file.
2021/11/10 17:18:11 [decoder:4] Raised at Ffmpeg_decoder.mk_decoder.(fun).f in file "decoder/ffmpeg_decoder.ml", line 691, characters 12-29
2021/11/10 17:18:11 [decoder:4] Called from Decoder.mk_decoder.fill in file "decoder/decoder.ml", line 500, characters 10-31
2021/11/10 17:18:11 [decoder:4]
2021/11/10 17:18:12 [requests:4] Finished with "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3".
2021/11/10 17:18:12 [requests_fallback:3] Switch to autodj_fallback with forgetful transition.
2021/11/10 17:18:12 [dynamic_startup:3] Switch to cue_next_song.
[mp3float @ 0x7f2498c0df00] Could not update timestamps for skipped samples.
2021/11/10 17:18:12 [cue_next_song:4] Cue points : none / none
2021/11/10 17:18:12 [cue_next_song:3] Cueing in...
2021/11/10 17:18:12 [crossfade_0:3] Analysis: -43.998118dB / -30.168927dB (2.96s / 2.96s)
2021/11/10 17:18:12 [crossfade_0:4] Before: ("on_air_timestamp", "1636564507.00")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("tempo", "125.13")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("kind", "{audio=pcm(stereo),video=none,midi=none}")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("artist", "Carbon Maestro")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("decoder", "FFMPEG")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("title", "Darkest Hour")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("bpm", "125.13")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("filename", "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("tlen", "187430")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("temporary", "false")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("source", "requests")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("media_id", "629")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("initial_uri", "annotate:title=\"Darkest Hour\",artist=\"Carbon Maestro\",duration=\"187.00\",song_id=\"b3eaa7634c4ffc593bfae2a400659e7c\",media_id=\"629\",liq_amplify=\"0.00dB\",playlist_id=\"20\":/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("length", "187430")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("song_id", "b3eaa7634c4ffc593bfae2a400659e7c")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("tkey", "Dm")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("status", "playing")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("replaygain_track_gain", "-3.923 dB")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("initialkey", "Dm")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("tbpm", "125.13")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("playlist_id", "20")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("on_air", "2021/11/10 17:15:07")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("popm", "\u0000\u0000")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("rid", "5")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("duration", "187.00")
2021/11/10 17:18:12 [crossfade_0:4] Before: ("liq_amplify", "0.00dB")
2021/11/10 17:18:12 [crossfade_0:4] After : ("on_air_timestamp", "1636564692.00")
2021/11/10 17:18:12 [crossfade_0:4] After : ("tempo", "120.00")
2021/11/10 17:18:12 [crossfade_0:4] After : ("kind", "{audio=pcm(stereo),video=none,midi=none}")
2021/11/10 17:18:12 [crossfade_0:4] After : ("artist", "Neighsayer")
2021/11/10 17:18:12 [crossfade_0:4] After : ("decoder", "FFMPEG")
2021/11/10 17:18:12 [crossfade_0:4] After : ("title", "She Calmed Down")
2021/11/10 17:18:12 [crossfade_0:4] After : ("bpm", "120.00")
2021/11/10 17:18:12 [crossfade_0:4] After : ("filename", "/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3")
2021/11/10 17:18:12 [crossfade_0:4] After : ("tlen", "351975")
2021/11/10 17:18:12 [crossfade_0:4] After : ("temporary", "false")
2021/11/10 17:18:12 [crossfade_0:4] After : ("source", "next_song")
2021/11/10 17:18:12 [crossfade_0:4] After : ("media_id", "631")
2021/11/10 17:18:12 [crossfade_0:4] After : ("initial_uri", "annotate:title=\"She Calmed Down\",artist=\"Neighsayer\",duration=\"352.00\",song_id=\"ffdc79e9baac02c73cb5f1258b6835bd\",media_id=\"631\",liq_amplify=\"0.00dB\",playlist_id=\"20\":/var/azuracast/stations/vaachar/media/Many Files/NightDj/neighsayer_-_she_calmed_down.mp3")
2021/11/10 17:18:12 [crossfade_0:4] After : ("length", "351975")
2021/11/10 17:18:12 [crossfade_0:4] After : ("song_id", "ffdc79e9baac02c73cb5f1258b6835bd")
2021/11/10 17:18:12 [crossfade_0:4] After : ("tkey", "Cm")
2021/11/10 17:18:12 [crossfade_0:4] After : ("status", "playing")
2021/11/10 17:18:12 [crossfade_0:4] After : ("replaygain_track_gain", "-0.630 dB")
2021/11/10 17:18:12 [crossfade_0:4] After : ("initialkey", "Cm")
2021/11/10 17:18:12 [crossfade_0:4] After : ("tbpm", "120.00")
2021/11/10 17:18:12 [crossfade_0:4] After : ("playlist_id", "20")
2021/11/10 17:18:12 [crossfade_0:4] After : ("on_air", "2021/11/10 17:18:12")
2021/11/10 17:18:12 [crossfade_0:4] After : ("popm", "\u0000\u0000")
2021/11/10 17:18:12 [crossfade_0:4] After : ("rid", "4")
2021/11/10 17:18:12 [crossfade_0:4] After : ("duration", "352.00")
2021/11/10 17:18:12 [crossfade_0:4] After : ("liq_amplify", "0.00dB")
2021/11/10 17:18:12 [crossfade_0:3] Simple transition: crossed, fade-in, fade-out.
2021/11/10 17:18:12 [source:4] Source add_1 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [add_1:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source fade.in gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [fade.in:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source fade.in gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [fade.in:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source crossfade_0_after gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [crossfade_0_after:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source buffer_3 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [buffer_3:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source fade.out gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [fade.out:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source fade.out gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [fade.out:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source on_end_1 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [on_end_1:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source crossfade_0_before gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [crossfade_0_before:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [source:4] Source buffer_2 gets up with content kind: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [buffer_2:4] Content type is {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [crossfade_0_after:4] Fading in (type: sin, duration: 2.s).
2021/11/10 17:18:12 [amplify_0:4] Overriding amplification: 1.000000.
2021/11/10 17:18:12 [amplify_2:4] Overriding amplification: 1.000000.
2021/11/10 17:18:12 [lang:3] AzuraCast Feedback Response: OK
2021/11/10 17:18:12 [lang:3] AzuraCast Raw Response: annotate:title="Loveheart",artist="Carbon Maestro",duration="202.00",song_id="2a752a30ef242aa0e11fc2afcb214003",media_id="491",liq_amplify="0.00dB",playlist_id="20":/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3
2021/11/10 17:18:12 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.aac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.aiff:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.wav:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder:4] Available decoders: FFMPEG (priority: 10), MAD (priority: 1)
2021/11/10 17:18:12 [decoder.ffmpeg:4] ffmpeg recognizes /var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3 as: audio: {codec: mp3, 44100Hz, 2 channel(s)} and content-type: {audio=pcm(stereo),video=none,midi=none}.
2021/11/10 17:18:12 [decoder:4] Selected decoder FFMPEG for file "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3" with expected kind {audio=pcm(stereo),video=none,midi=none} and detected content {audio=pcm(stereo),video=none,midi=none}
2021/11/10 17:18:12 [metadata.flac:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [metadata.mp4:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [decoder.ogg:4] Unsupported file extension for "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_loveheart_.mp3"!
2021/11/10 17:18:12 [next_song:4] Queued 1 requests
2021/11/10 17:18:13 [crossfade_0_before:4] Fading out with 2.s remaining.
2021/11/10 17:18:15 [buffer_3:4] Buffer emptied, buffering needed.
2021/11/10 17:18:15 [buffer_2:4] Buffer emptied, buffering needed.
2021/11/10 17:18:15 [crossfade_0:4] Buffering end of track...
2021/11/10 17:18:15 [crossfade_0:4] More buffering will be needed.
Thanks for this! If I looks at the logs, I see this:
First, the skip:
2021/11/10 17:15:07 [server:3] Client 172.25.0.5 disconnected.
2021/11/10 17:15:07 [server:3] New client: 172.25.0.5.
2021/11/10 17:15:07 [playlist_default:4] Finished with "/var/azuracast/stations/vaachar/media/Many Files/NightDj/Single Purpose - It's Okay (Periwinkle Edit).mp3".
2021/11/10 17:15:07 [server:3] Client 172.25.0.5 disconnected.
Then this:
2021/11/10 17:15:07 [playlist_default:4] Remaining 0 requests
2021/11/10 17:15:07 [playlist_default:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/John Doe - Stroll.mp3" (RID 3).
2021/11/10 17:15:07 [autodj_fallback:3] Switch to dynamic_startup with forgetful transition.
2021/11/10 17:15:07 [requests:4] Remaining 0 requests
2021/11/10 17:15:07 [requests:3] Prepared "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3" (RID 5).
It looks here that the requests
source is also preparing a request. This is this source from your script:
requests = request.queue(id="requests")
requests = cue_cut(id="cue_requests", requests)
The fallback is also switching to this source:
2021/11/10 17:15:07 [requests_fallback:3] Switch to cue_requests with forgetful transition.
Eventually, the next song goes back to the auto dj source:
2021/11/10 17:18:12 [requests:4] Finished with "/var/azuracast/stations/vaachar/media/Many Files/NightDj/carbon_maestro_-_darkest_hour.mp3".
2021/11/10 17:18:12 [requests_fallback:3] Switch to autodj_fallback with forgetful transition.
2021/11/10 17:18:12 [dynamic_startup:3] Switch to cue_next_song.
So, it looks to me that the extra song is coming from the requests
source.
Hey @toots you are absolutely right, the track was indeed coming from the requests
source.
I didn't notice this and this helped greatly in figuring out why this was happening.
I looked through the AzuraCast code so see what is pushing tracks to this requests
source and landed on a piece of code that was added a long time ago to the skipping code in AC that was intended to push tracks to that queue prior to skipping to have it already contain a track before skipping (I guess this was intended to alleviate the skip problem in LS 1.x where it would fall back to the hardcoded playlists instead of waiting for a response from the next song API).
Neither me nor Buster realized that this was happening / that this piece of code was there. Thank you so much for pointing out where the track was coming from in Liquidsoap ❤️
When we removed this piece of legacy code the skipping started to work as expected.
Describe the bug When sending a
skip
command via telnet to a LS process that is usingrequest.dynamic.list
with the defaultprefetch
of1
I'm seeing it sending 2 requests to my API that returns the next song.To Reproduce I'm currently working on an update for AzuraCast to use Liquidsoap 2.0 and noticed this issue so I don't yet have a simplified example. I hope that the LS script we generate can help somewhat:
The specific telnet command that is sent is:
requests_fallback.skip
Expected behavior When sending a
skip
via telnet therequest.dynamic.list
should only call the given function as often as needed to fill the defined amount of prefetched songs.Version details
Install method Opam from the GitHub source. See: https://github.com/AzuraCast/docker-azuracast-radio/blob/bddd4d1cae39db628de1a832355e8f1c887b0fa1/Dockerfile
Please let me know if you need anything (for example: specific logs from a specific log level) and I'll get them.