search

savonet / liquidsoap

Liquidsoap is a statically typed scripting general-purpose language with dedicated operators and backend for all thing media, streaming, file generation, automation, HTTP backend and more.
http://liquidsoap.info
GNU General Public License v2.0
1.41k stars 130 forks source link

LS 2.2.4: Metadata "off-by-one" & missing metadata is back, lots of `Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))` errors #3724

Closed Moonbase59 closed 9 months ago

Moonbase59 commented 9 months ago

Just updated to AzuraCast Rolling Release #8bb88cd (2024-02-08 5:06) (using the new LS 2.2.4), see https://github.com/AzuraCast/AzuraCast/issues/6930.

The "metadata missing" and "metadata off-by-one" errors are back, plus a lot of Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed)) in the Liquidsoap log:

2024/02/08 09:06:35 [lang:3] API nextsong - Sending POST request to 'http://127.0.0.1:6010/api/internal/1/liquidsoap/nextsong' with body: 
2024/02/08 09:06:35 [lang:3] API nextsong - Response (200): annotate:title="Kribbeln im Bauch",artist="Pe Werner",duration="227.00",song_id="92a6c5701ac9ef43137de779af9a6631",media_id="270537",playlist_id="247":media:Tagged/Werner, Pe/Werner, Pe - [compilations]/Werner, Pe - Kribbeln im Bauch.mp3
2024/02/08 09:06:35 [decoder.ffmpeg:3] Requested content-type for "/var/azuracast/stations/niteradio/media/Tagged/Werner, Pe/Werner, Pe - [compilations]/Werner, Pe - Kribbeln im Bauch.mp3": {audio=pcm(stereo)}
2024/02/08 09:06:35 [decoder.ffmpeg:3] FFmpeg recognizes "/var/azuracast/stations/niteradio/media/Tagged/Werner, Pe/Werner, Pe - [compilations]/Werner, Pe - Kribbeln im Bauch.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}
2024/02/08 09:06:35 [decoder.ffmpeg:3] Decoded content-type for "/var/azuracast/stations/niteradio/media/Tagged/Werner, Pe/Werner, Pe - [compilations]/Werner, Pe - Kribbeln im Bauch.mp3": {audio=pcm(stereo)}
2024/02/08 09:06:35 [cross:3] Analysis: -25.291740dB / -23.581858dB (2.98s / 3.02s)
2024/02/08 09:06:35 [cross:3] Computing crossfade duration over overlapping 2.98s buffered data at start and end.
2024/02/08 09:06:35 [lang:3] Using custom crossfade
2024/02/08 09:06:35 [cross.smart:3] No transition: using default.
2024/02/08 09:06:35 [cross_before.3:3] Content type is {audio=pcm(stereo)}.
2024/02/08 09:06:35 [buffer.7:3] Content type is {audio=pcm(stereo)}.
2024/02/08 09:06:35 [cross_after.3:3] Content type is {audio=pcm(stereo)}.
2024/02/08 09:06:35 [buffer.9:3] Content type is {audio=pcm(stereo)}.
2024/02/08 09:06:35 [cross_after_tail.2:3] Content type is {audio=pcm(stereo)}.
2024/02/08 09:06:35 [nowplaying:3] Now playing: Bay City Rollers - Summerlove Sensation
2024/02/08 09:06:35 [json.parse:3] You are parsing a JSON value without type annotation. This has confusing side-effects. Consider adding a type annotation: `let json.parse (x : ...) = ...`
2024/02/08 09:06:35 [nowplaying:3] API playlist/247 - Playlist "Pop", requests: true, scheduled: true
2024/02/08 09:06:35 [nowplaying:3] Show: "Pop (mit Musikwünschen)", color=0x2196f3, alpha=0.5
2024/02/08 09:06:36 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:39 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:42 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:44 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:47 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:49 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:51 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:53 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:55 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:06:58 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:00 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:02 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:04 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:08 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:10 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:13 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:15 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:17 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:19 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:21 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:23 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:25 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:27 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:30 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:33 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:35 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:37 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:39 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:41 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:43 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:45 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:47 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:50 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:52 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:55 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:57 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:07:59 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:01 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:03 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:05 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:07 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:09 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:11 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:13 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:16 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:19 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:21 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:24 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:26 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:28 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:30 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:32 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:35 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:37 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:40 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:42 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:45 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:47 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:49 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))
2024/02/08 09:08:52 [input.http:2] Decoding failed: Avutil.Error(Server returned 401 Unauthorized (authorization failed))

Test stream which should play 30s song/30s beep, 30s song/30s beep, … at https://radio.niteradio.net/public/niteradio-test (web player). This nicely shows the "metadata off-by-one" effect. You can also follow "Nite Radio Test" on this web page: https://grav1.niteradio.net/blog/winterzeit-ist-radiozeit to see the effect.

"Missing metadata" usually happens on the other stations whenever a (hidden) jingle plays after a song—the previous song’s metadata is shown until the next song after the jingle finishes.

The exact same setup worked fine on AzuraCast Rolling Release #1e2aa03 (2024-02-04 11:46), LS 2.2.4+git@6721bb156.

Let’s handle the issue here, although I also reported it over at AzuraCast.

toots commented 9 months ago

Thank you for reporting but, if you fill an issue, can we focus on liquidsoap-specific issues? I'm not sure that there is much that I can use here. The server error could be anything in the azura cast application logic.

There's a report of missing metadata on a crossfade duration of 0.0 here: https://github.com/savonet/liquidsoap/issues/3610

Are we in the same situation? I'm treating a crossfade duration of 0. as a programming error and pushing a work around with logging onto rolling-release-v2.2.x.

Moonbase59 commented 9 months ago

Well @BusterNeece said in https://github.com/AzuraCast/AzuraCast/issues/6930#issuecomment-1933566399 :

Probably should be on the Liquidsoap repo. Nothing I can do about any of this.

Unsure about #3610, but I do use a "short fade" of 0.1s, which worked fine using LS 2.2.4+git@6721bb1. I think cue_cut isn’t used anymore in AzuraCast’s code. Here is my custom crossfading part for the "normal" stations:

# Be sure to have ReplayGain applied before crossing.
radio = amplify(1.,override="replaygain_track_gain",radio)

# If a song has <song> <silence> <bonus track>,
# blank.eat() will skip <silence> and play <bonus track>
#radio = blank.eat(radio, max_blank=5.0, threshold=-60.0)
# blank.skip() will skip to next song and NOT play <bonus track>.
# Defaults: max_blank=20.0 (seconds), threshold=-40.0 (dB)
#radio = blank.skip(radio, max_blank=5.0, threshold=-80.0)
radio = blank.eat(radio, max_blank=.1, threshold=-50.0)

#radio = blank.skip(radio, max_blank=0.1, threshold=-40.0)

def live_aware_crossfade(old, new) =
    if to_live() then
        # If going to the live show, play a simple sequence
        # fade out AutoDJ, do (almost) not fade in streamer
        sequence([fade.out(duration=3.0,old.source),fade.in(duration=0.1,new.source)])
    else
        # Otherwise, use the simple transition
        log("Using custom crossfade")
        #cross.simple(old.source, new.source, fade_in=0.1, fade_out=3.5)
        cross.smart(old, new, fade_in=0.1, fade_out=2.5, margin=8.)
        #add(normalize=false, [old.source, new.source])
    end
end

radio = cross(duration=3.0, width=2.0, live_aware_crossfade, radio)
#radio = cross(minimum=0., duration=2.00, width=2.00, live_aware_crossfade, radio)

# Add a smooth TOTH time announcement
radio = smooth_add(duration=2., p=.3, normal=radio, special=switch(id="toth_switch", [(predicate.once({ 0m }), playlist_zeitansage)]))

and here for "Nite Radio Test" (the 30s/30s test):

# Be sure to have ReplayGain applied before crossing.
radio = amplify(1.,override="replaygain_track_gain",radio)

# If a song has <song> <silence> <bonus track>,
# blank.eat() will skip <silence> and play <bonus track>
#radio = blank.eat(radio, max_blank=5.0, threshold=-60.0)
# blank.skip() will skip to next song and NOT play <bonus track>.
# Defaults: max_blank=20.0 (seconds), threshold=-40.0 (dB)
#radio = blank.skip(radio, max_blank=5.0, threshold=-80.0)
radio = blank.eat(radio, max_blank=.1, threshold=-50.0)

# Skip base part of song, play only first and last 15 seconds
skipped = ref(false)
def skip_song(s) =
  if source.elapsed(s) > 15. then
    if skipped() == false then
      # seeking can take a while!
      s = source.seek(s, source.remaining(s) - 15.)
      log(label="skip_song", "Skipping #{s}s…")
      skipped := true
    end
  else
    skipped := false
  end
end
radio = source.on_frame(radio, {skip_song(radio)})

def live_aware_crossfade(old, new) =
    if to_live() then
        # If going to the live show, play a simple sequence
        # fade out AutoDJ, do (almost) not fade in streamer
        sequence([fade.out(duration=3.0,old.source),fade.in(duration=0.1,new.source)])
    else
        # Otherwise, use the simple transition
        log("Using custom crossfade")
        #cross.simple(old.source, new.source, fade_in=0.00, fade_out=3.50)
        sequence([old.source,new.source])
    end
end

radio = cross(minimum=0., duration=4.00, width=2.00, live_aware_crossfade, radio)

# Add a smooth TOTH time announcement
radio = smooth_add(duration=2., p=.3, normal=radio, special=switch(id="toth_switch", [(predicate.once({ 0m }), playlist_zeitansage)]))
toots commented 9 months ago

I'm sorry but this is still not helpful. This issue has multiple problems in one. This is really not ideal. I need something that is isolated. Can we close this and submit several ones separately?

The 401 error is definitely returned from the ffmpeg library. I don't think we have much to do about it, typically.

Moonbase59 commented 9 months ago

Well, I’m a bit exhausted from all these day and night testing and bug-finding sessions lately, I’ll probably roll back to my backup, so I can at least have something running. Sorry. Guess there will be others that report the same problem shortly.

Or maybe you and Buster can fix it.

toots commented 9 months ago

Thank you for your patience.

I'm happy to fix anything just trying to know what I should actually fix.. 🙂

Moonbase59 commented 9 months ago

Guess it must have something to do with something that you fixed in https://github.com/AzuraCast/AzuraCast/issues/6905, that now got "unfixed" again. Just a guess, though. Went back to my backup (using LS LS 2.2.4+git@6721bb1) that has that fixed.

So one of the things that got changed between these two versions.

toots commented 9 months ago

Let's bisect it! I'll give you a list of all the builds between the one that worked and the release, there aren't a lot of them.

toots commented 9 months ago

Ok from oldest to most recent here are the builds between the commit that works and 2.2.4:

https://github.com/savonet/liquidsoap/actions/runs/7777587246 https://github.com/savonet/liquidsoap/actions/runs/7778389069 https://github.com/savonet/liquidsoap/actions/runs/7804254376 https://github.com/savonet/liquidsoap/actions/runs/7820707974 https://github.com/savonet/liquidsoap/actions/runs/7825725349

It would be great it you could see which on is the first to introduce the issue.

Thanks!

Moonbase59 commented 9 months ago

Yeah, okay, thanks for trying to help. But I’m really exhausted, so maybe tomorrow, if that’s ok with you?

Does the list include or exclude LS 2.2.4+git@6721bb1 and LS 2.2.4 release?

Do you think it will be okay if I just go and replace each within my AzuraCast Docker and see if the metadata/avutil errs start happening?

toots commented 9 months ago

Yes exactly. We already know the first and last status so the first faulty one should be one of those.

Moonbase59 commented 9 months ago

Guess I caught the bugger:

Somewhere in between

Metadata is ok in the first one, but "off-by-one" in the second (which is the first of two marked "2.2.4" without a git commit number). No Avutil.Error so far (testing on AzuraCast Rolling Release #1e2aa03 (2024-02-04 11:46)).

Should I continue testing the rest of the bunch? Or do you need some logs or stuff from this non-functioning version?

Moonbase59 commented 9 months ago

(working with @toots on that in the Discord)

Moonbase59 commented 9 months ago

Since about 2024-02-10 05:30 GMT, I’m now running my stations on Liquidsoap 2.2.4-1+git@f1b53e8be. Looks good so far, I’ll leave it running for a while, record some streams and see.

Thanks @toots for the intensive debugging session and the work fixing it!

Moonbase59 commented 9 months ago

Since about 2024-02-10 07:09 GMT, now running the more official Liquidsoap 2.2.4-1.

Moonbase59 commented 9 months ago

I’d say this is fixed. Thanks again!