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.35k stars 122 forks source link

ffmpeg.filter.loudnorm triggers Invalid ffmpeg content: non-monotonic PTS error #3944

Open smiccoli opened 1 month ago

smiccoli commented 1 month ago

Describe the bug Liquidsoap 2.2.5 crashes with the following error if the ffmpeg filter ffmpeg.filter.loudnorm is used on a source returned by a buffer(). Other filters such as ffmpeg.filter.pan and ffmpeg.filter.volume dont present the same behavior and work well with sources returned by buffer().

Incorrect BOM value
Error reading lyrics, skipped
2024/05/31 13:56:27 >>> LOG START
2024/05/31 13:56:08 [ffmpeg.filter.bitstream:3] No valid mode found for filter pgs_frame_merge!
2024/05/31 13:56:09 [main:3] Liquidsoap 2.2.5
2024/05/31 13:56:09 [main:3] Using: alsa=0.3.0 angstrom=0.15.0 ao=0.2.4 asetmap=0.8.1 asn1-combinators=0.2.6 astring=0.8.5 base64=3.5.1 bigarray=[distributed with Ocaml] bigarray-compat=1.1.0 bigstringaf=0.9.1 bjack=0.1.6 bos=0.2.1 bytes=[distributed with OCaml 4.02 or above] ca-certs=v0.2.3 camlimages.all_formats=4.2.6 camlimages.core=5.0.4 camlimages.exif=5.0.4 camlimages.gif=5.0.4 camlimages.jpeg=5.0.4 camlimages.png=5.0.4 camlimages.tiff=5.0.4 camlimages.xpm=5.0.4 camlp-streams camomile.lib=2.0 cohttp=5.3.0 cohttp-lwt=5.3.0 cohttp-lwt-unix=5.3.0 conduit=6.2.0 conduit-lwt=6.2.0 conduit-lwt-unix=6.2.0 cry=1.0.3 cstruct=6.2.0 ctypes=0.21.1 ctypes-foreign=0.21.1 ctypes.stubs=0.21.1 curl=0.9.2 domain-name=0.4.0 domain_shims dssi=0.1.5 dtools=0.4.5 dune-build-info=3.11.1 dune-private-libs.dune-section=3.11.1 dune-site=3.11.1 dune-site.private=3.11.1 duppy=0.9.4 eqaf=0.9 eqaf.bigstring=0.9 eqaf.cstruct=0.9 faad=0.5.2 fdkaac=0.3.3 ffmpeg-av=1.1.10 ffmpeg-avcodec=1.1.10 ffmpeg-avdevice=1.1.10 ffmpeg-avfilter=1.1.10 ffmpeg-avutil=1.1.10 ffmpeg-swresample=1.1.10 ffmpeg-swscale=1.1.10 fileutils=0.6.4 flac=0.5.1 flac.decoder=0.5.1 flac.ogg=0.5.1 fmt=0.9.0 fpath=0.7.3 frei0r=0.1.2 gd=1.0a5 gen=1.1 gmap=0.3.0 hkdf=1.0.4 inotify=2.4.1 integers ipaddr=5.5.0 ipaddr-sexp=5.5.0 ipaddr.unix=5.5.0 irc-client irc-client-unix jemalloc ladspa=0.2.2 lame=0.3.7 lastfm=0.3.4 lilv=0.1.0 liquidsoap-lang=2.2.5 liquidsoap-lang.console=2.2.5 liquidsoap_alsa=f0fdb0e-dirty liquidsoap_ao=f0fdb0e-dirty liquidsoap_bjack=f0fdb0e-dirty liquidsoap_builtins=f0fdb0e-dirty liquidsoap_camlimages=f0fdb0e-dirty liquidsoap_core=f0fdb0e-dirty liquidsoap_dssi=f0fdb0e-dirty liquidsoap_faad=f0fdb0e-dirty liquidsoap_fdkaac=f0fdb0e-dirty liquidsoap_ffmpeg=f0fdb0e-dirty liquidsoap_flac=f0fdb0e-dirty liquidsoap_frei0r=f0fdb0e-dirty liquidsoap_gd=f0fdb0e-dirty liquidsoap_irc=f0fdb0e-dirty liquidsoap_jemalloc=f0fdb0e-dirty liquidsoap_ladspa=f0fdb0e-dirty liquidsoap_lame=f0fdb0e-dirty liquidsoap_lastfm=f0fdb0e-dirty liquidsoap_lilv=f0fdb0e-dirty liquidsoap_lo=f0fdb0e-dirty liquidsoap_mad=f0fdb0e-dirty liquidsoap_mem_usage=f0fdb0e-dirty liquidsoap_memtrace=f0fdb0e-dirty liquidsoap_ogg=f0fdb0e-dirty liquidsoap_ogg_flac=f0fdb0e-dirty liquidsoap_optionals=f0fdb0e-dirty liquidsoap_opus=f0fdb0e-dirty liquidsoap_osc=f0fdb0e-dirty liquidsoap_oss=f0fdb0e-dirty liquidsoap_portaudio=f0fdb0e-dirty liquidsoap_posix_time=f0fdb0e-dirty liquidsoap_prometheus=f0fdb0e-dirty liquidsoap_pulseaudio=f0fdb0e-dirty liquidsoap_runtime=f0fdb0e-dirty liquidsoap_samplerate=f0fdb0e-dirty liquidsoap_sdl=f0fdb0e-dirty liquidsoap_shine=f0fdb0e-dirty liquidsoap_soundtouch=f0fdb0e-dirty liquidsoap_speex=f0fdb0e-dirty liquidsoap_srt=f0fdb0e-dirty liquidsoap_ssl=f0fdb0e-dirty liquidsoap_stereotool=f0fdb0e-dirty liquidsoap_taglib=f0fdb0e-dirty liquidsoap_theora=f0fdb0e-dirty liquidsoap_tls=f0fdb0e-dirty liquidsoap_vorbis=f0fdb0e-dirty liquidsoap_xmlplaylist=f0fdb0e-dirty liquidsoap_yaml=f0fdb0e-dirty lo=0.2.0 logs=0.7.0 logs.fmt=0.7.0 logs.lwt=0.7.0 lwt=5.7.0 lwt.unix=5.7.0 macaddr=5.5.0 mad=0.5.3 magic-mime=1.3.1 mem_usage=0.1.1 memtrace=0.2.3 menhirLib=20230608 metadata=0.3.0 mirage-crypto=0.11.2 mirage-crypto-ec=0.11.2 mirage-crypto-pk=0.11.2 mirage-crypto-rng=0.11.2 mirage-crypto-rng.unix=0.11.2 mm=0.8.5 mm.audio=0.8.5 mm.base=0.8.5 mm.image=0.8.5 mm.midi=0.8.5 mm.video=0.8.5 ocplib-endian ocplib-endian.bigstring ogg=0.7.4 ogg.decoder=0.7.4 opus=0.2.3 opus.decoder=0.2.3 osc osc-unix parsexp=v0.16.0 pbkdf pcre=7.5.0 portaudio=0.2.3 posix-base=5a7f328 posix-socket=5a7f328 posix-socket.constants=5a7f328 posix-socket.stubs=5a7f328 posix-socket.types=5a7f328 posix-time2=5a7f328 posix-time2.constants=5a7f328 posix-time2.stubs=5a7f328 posix-time2.types=5a7f328 posix-types=5a7f328 posix-types.constants=5a7f328 ppx_sexp_conv.runtime-lib=v0.16.0 prometheus=1.2 prometheus-app=1.2 ptime=1.1.0 ptime.clock.os=1.1.0 pulseaudio=0.1.6 re=1.11.0 result=1.5 rresult=0.7.0 samplerate=0.1.7 saturn_lockfree=0.4.1 sedlex=3.2 seq=[distributed with OCaml 4.07 or above] sexplib=v0.16.0 sexplib0=v0.16.0 shine=0.2.3 soundtouch=0.1.9 speex=0.4.2 speex.decoder=0.4.2 srt=0.3.1 srt.constants=0.3.1 srt.stubs=0.3.1 srt.stubs.locked=0.3.1 srt.types=0.3.1 ssl=0.7.0 stdlib-shims=0.3.0 stereotool=f0fdb0e-dirty str=[distributed with Ocaml] stringext=1.6.0 taglib=0.3.10 theora=0.4.1 theora.decoder=0.4.1 threads=[distributed with Ocaml] threads.posix=[internal] tls=0.17.1 tsdl=v1.0.0 tsdl-image=0.5 tsdl-ttf=0.6 unix=[distributed with Ocaml] unix-errno=52c6ecb unix-errno.errno_bindings=52c6ecb unix-errno.errno_types=52c6ecb unix-errno.errno_types_detected=52c6ecb unix-errno.unix=52c6ecb uri=4.4.0 uri-sexp=4.4.0 uri.services=4.4.0 vorbis=0.8.1 vorbis.decoder=0.8.1 x509=0.16.5 xmlm=1.4.0 xmlplaylist=0.1.5 yaml=3.2.0 yaml.bindings=3.2.0 yaml.bindings.types=3.2.0 yaml.c=3.2.0 yaml.ffi=3.2.0 yaml.types=3.2.0 zarith=1.13
2024/05/31 13:56:09 [clock:3] Using native (high-precision) implementation for latency control
2024/05/31 13:56:23 [main:3] Standard library loaded in 14.78 seconds.
2024/05/31 13:56:27 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2024/05/31 13:56:27 [frame:3] Video frame size set to: 1280x720
2024/05/31 13:56:27 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2024/05/31 13:56:27 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2024/05/31 13:56:27 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2024/05/31 13:56:27 [sandbox:3] Running inside a docker container, disabling sandboxing.
2024/05/31 13:56:27 [startup:3] DSSI plugins registration: 0.00s
2024/05/31 13:56:27 [startup:3] FFmpeg filters registration: 0.15s
2024/05/31 13:56:27 [startup:3] FFmpeg bitstream filters registration: 0.01s
2024/05/31 13:56:27 [startup:3] Lilv plugins registration: 0.00s
2024/05/31 13:56:27 [startup:3] Frei0r plugin registration: 0.00s
2024/05/31 13:56:27 [startup:3] LADSPA plugins registration: 0.00s
2024/05/31 13:56:27 [startup:3] Typechecking: 13.98s
2024/05/31 13:56:27 [startup:3] Evaluation: 0.03s
2024/05/31 13:56:27 [startup:3] Typechecking: 0.06s
2024/05/31 13:56:27 [startup:3] Evaluation: 0.01s
2024/05/31 13:56:27 [startup:3] Typechecking: 3.43s
2024/05/31 13:56:27 [startup:3] Evaluation: 0.10s
2024/05/31 13:56:27 [startup:3] Loaded /radio/bug-pts.liq: 3.53s
2024/05/31 13:56:27 [buffer.consumer:3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [single:3] "/var/sample.mp3" is static, resolving once for all...
Incorrect BOM value
Error reading lyrics, skipped
Incorrect BOM value
Error reading lyrics, skipped
2024/05/31 13:56:27 [decoder.ffmpeg:3] Requested content-type for "/var/sample.mp3": {audio=pcm(stereo)}
2024/05/31 13:56:27 [decoder.ffmpeg:3] FFmpeg recognizes "/var/sample.mp3" as audio: {codec: mp3, 44100Hz, 2 channel(s)}, video: {codec: mjpeg, 700x700, yuvj444p}
2024/05/31 13:56:27 [decoder.ffmpeg:3] Decoded content-type for "/var/sample.mp3": {audio=pcm(stereo)}
2024/05/31 13:56:27 [ffmpeg_filter_audio_input:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [ffmpeg_raw_encode_audio:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [audio.producer:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [audio.consumer:3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [buffer.producer:3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [audio.consumer.2:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [source.2:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [ffmpeg.filter.audio.output:3] Content type is {audio=ffmpeg.audio.raw}.
2024/05/31 13:56:27 [pulse_out(liquidsoap:):3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [ffmpeg_raw_decode_audio:3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [audio.producer.2:3] Content type is {audio=pcm(stereo)}.
2024/05/31 13:56:27 [clock.main:3] Streaming loop starts in auto-sync mode
2024/05/31 13:56:27 [clock.main:3] Delegating synchronization to CPU clock
2024/05/31 13:56:27 [clock.pulseaudio:3] Streaming loop starts in auto-sync mode
2024/05/31 13:56:27 [clock.pulseaudio:3] Delegating synchronization to CPU clock
2024/05/31 13:56:27 [video.converter:3] Using preferred video converter: ffmpeg.
2024/05/31 13:56:27 [audio.converter:3] Using samplerate converter: libsamplerate.
2024/05/31 13:56:27 [video.text:3] Using sdl implementation
Incorrect BOM value
Error reading lyrics, skipped
Incorrect BOM value
Error reading lyrics, skipped
2024/05/31 13:56:27 [single:3] Prepared "/var/sample.mp3" (RID 0).
[mp3float @ 0x7f8182cc2800] Could not update timestamps for skipped samples.
2024/05/31 13:56:28 [buffer.producer:3] Buffer emptied, start buffering...
2024/05/31 13:56:28 [audio.consumer:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:28 [ffmpeg_filter_audio_input:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:28 [audio.consumer.2:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:28 [pulse_out(liquidsoap:):3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:29 [buffer.producer:3] Buffer emptied, start buffering...
2024/05/31 13:56:29 [audio.consumer:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:29 [ffmpeg_filter_audio_input:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:29 [audio.consumer.2:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:29 [pulse_out(liquidsoap:):3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:30 [buffer.producer:3] Buffer emptied, start buffering...
2024/05/31 13:56:30 [audio.consumer:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:30 [ffmpeg_filter_audio_input:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:30 [audio.consumer.2:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:30 [pulse_out(liquidsoap:):3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:31 [ffmpeg:3] Invalid ffmpeg content: non-monotonic PTS: 84672 < 127008
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Source ffmpeg_filter_audio_input failed while streaming: Content_base.Invalid!
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Raised at Ffmpeg_utils.Duration.push in file "src/core/tools/ffmpeg_utils.ml", line 319, characters 14-35
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Called from Ffmpeg_filter_io.base_output#send_frame.(fun) in file "src/core/io/ffmpeg_filter_io.ml", line 127, characters 12-79
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Called from Stdlib__List.iter in file "list.ml", line 110, characters 12-15
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Called from Output.output#output in file "src/core/outputs/output.ml", line 192, characters 45-70
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] Called from Clock.MkClock.clock#end_tick.(fun) in file "src/core/clock.ml", line 318, characters 16-24
2024/05/31 13:56:31 [clock.ffmpeg.filter:2] 
2024/05/31 13:56:31 [audio.consumer.2:3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:31 [pulse_out(liquidsoap:):3] Source failed (no more tracks) stopping output...
2024/05/31 13:56:31 [threads:3] Main loop exited
2024/05/31 13:56:31 [main:3] Shutdown started!
2024/05/31 13:56:31 [threads:3] Waiting for main threads to terminate...
2024/05/31 13:56:31 [clock.main:3] Streaming loop stopped.
2024/05/31 13:56:31 [clock.pulseaudio:3] Streaming loop stopped.
2024/05/31 13:56:31 [threads:3] Main threads terminated.
2024/05/31 13:56:31 [threads:3] Shutting down scheduler...
2024/05/31 13:56:31 [threads:3] Scheduler shut down.
2024/05/31 13:56:31 [main:3] Cleaning downloaded files...
2024/05/31 13:56:31 [main:3] Freeing memory...
2024/05/31 13:56:31 >>> LOG END

To Reproduce A minimal script to reproduce the issue is the most efficient way to have your bug addressed and fixed very quickly!

settings.init.allow_root := true

def ffmpeg_loudnorm(s) =
  def mkfilter(graph) =
    audio_track = ffmpeg.filter.audio.input(graph, source.tracks(s).audio)
    audio_track = ffmpeg.filter.pan(args="mono|c0<c0+c1", graph, audio_track)
    audio_track = ffmpeg.filter.loudnorm(i=-14., tp=-2., lra=11., graph, audio_track)
    audio_track = ffmpeg.filter.audio.output(graph, audio_track)
    source({audio = audio_track, metadata = track.metadata(audio_track), track_marks = track.track_marks(audio_track)})
  end
  ffmpeg.filter.create(mkfilter)
end

source = single("/var/opt/hdis-archive/tracks/sample.mp3")
source = buffer(source)
source = ffmpeg.raw.encode.audio(%ffmpeg(%audio.raw), source)
source = ffmpeg_loudnorm(source)
source = ffmpeg.raw.decode.audio(source)
channel = output.pulseaudio(fallible=true, source)```

Expected behavior Loudnorm filter should work with both buffered and non-buffered sources.

Version details

Install method Custom docker image starting from the official debian:bookworm-slim Inside the dockerfile, FFmpeg installed via debian repos while Liquidsoap is installed via the deb package from github release.

Moonbase59 commented 1 month ago

Could you provide the /var/sample.mp3 for us to check?

Such errors often happen with defective or concatenated/cut MP3s, and there are lots of ways an MP3 file can be broken.

You could use tools like MP3 Diags to diagnose/repair and rmlyrics3 to remove Lyrics3 tags.

smiccoli commented 1 month ago

how can i provide you with the file without making it public? it's a song for which we have the rights but i dont think it is not ok to share in github.

I checked it with mp3diags but besides a "normalization missing (an)" and "picture ignored (ej)" notes there's nothing apparently wrong with it.

Moonbase59 commented 1 month ago

Only getting (an) & (ej) is a good first thing. Often MP3s have many more errors.

If the file was small (like max a few MB), you could try sending it to moonbase (at) quantentunnel (dot) de, or, if you’re on Discord, contact me there (Moonbase59) in a private message (max. 20 MB I believe).

I’ll of course only use it for diagnosis and delete it again afterwards.

What version of ffmpeg are you running in your Docker (ffmpeg -version)?

smiccoli commented 1 month ago

ok, ive sent it to you on discord DM. Let me know if I can help with something more

Moonbase59 commented 1 month ago

Thanks! We tried finding faults with the MP3, but found none at first.

ffprobe sample.mp3 showed the same

Incorrect BOM value
Error reading lyrics, skipped

as in the log above.

Interestingly, autocue’s cue_file -fw sample.mp3 made that go away (maybe a glitch in the tags, or ffmpeg demuxing buffer problem).

So then we tried repairing the non-contiguous presentation time stamps (PTS) by doing

ffmpeg -i sample-fixed.mp3 -map_metadata 0 -c copy -reset_timestamps 1 -fflags +genpts sample-new-pts.mp3

and the resultant sample-new-pts indeed has contiguous time stamps now. (The discontinuity might have been caused by previous editing.)

In Liquidsoap, we don’t get the "Incorrect BOM value" error anymore, but @smiccoli tells me when using the

source = buffer(source)

from above code, LS still crashes, and when leaving that out it plays fine.