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.4k stars 130 forks source link

cannot stream mp4 videos on 2.0.2-1 #2159

Closed WitzHsiao closed 2 years ago

WitzHsiao commented 2 years ago

Code is pretty simple

source = playlist(reload_mode="watch", mode="normal", "list.m3u")
enc=%ffmpeg(
  format="flv",
  %audio.copy,
  %video.copy)
output.url(
  fallible=true,
  url="rtmp://localhost:1935/live",
  enc,
  source)

please check logs below

2022/01/15 05:27:10 >>> LOG START
2022/01/15 05:27:09 [main:3] Liquidsoap 2.0.2
2022/01/15 05:27:09 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.5.0 sedlex=2.5 menhirLib=20
211128 curl=0.9.2 dtools=0.4.4 duppy=0.9.2 cry=0.6.5 mm=0.7.2 ogg=0.7.0 ogg.decoder=0.7.0 vorbis=0.8.0 vorbis.decod
er=0.8.0 mad=0.5.1 dynlink=[distributed with Ocaml] lame=0.3.5 ffmpeg=1.1.1 samplerate=0.1.6 taglib=0.3.8 camomile=
1.0.2
2022/01/15 05:27:09 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
2022/01/15 05:27:09 [clock:3] Using builtin (low-precision) implementation for latency control
2022/01/15 05:27:10 [list.m3u:4] Reloading playlist.
2022/01/15 05:27:10 [request:5] Resolving request [[list.m3u]].
2022/01/15 05:27:10 [request:5] Resolved to [[list.m3u]].
2022/01/15 05:27:10 [playlist parser:4] Trying youtube-dl parser
2022/01/15 05:27:10 [playlist parser:4] Trying application/x-cue parser
2022/01/15 05:27:10 [playlist parser:4] Trying audio/x-scpls parser
2022/01/15 05:27:10 [playlist parser:4] Trying application/x-mpegURL parser
2022/01/15 05:27:10 [frame:4] frame.audio.channels set to: 2
2022/01/15 05:27:10 [frame:4] frame.video.default set to: false
2022/01/15 05:27:10 [frame:4] frame.midi.channels set to: 0
2022/01/15 05:27:10 [frame:4] frame.video.width set to: 1280
2022/01/15 05:27:10 [frame:4] frame.video.height set to: 720
2022/01/15 05:27:10 [frame:4] frame.audio.samplerate set to: 44100
2022/01/15 05:27:10 [frame:4] frame.video.framerate set to: 25
2022/01/15 05:27:10 [frame:4] frame.audio.samplerate set to: 44100
2022/01/15 05:27:10 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2022/01/15 05:27:10 [frame:3] Video frame size set to: 1280x720
2022/01/15 05:27:10 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2022/01/15 05:27:10 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2022/01/15 05:27:10 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2022/01/15 05:27:10 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2022/01/15 05:27:10 [video.converter:3] Using preferred video converter: ffmpeg.
2022/01/15 05:27:10 [audio.converter:3] Using samplerate converter: ffmpeg.
2022/01/15 05:27:10 [lifecycle:5] At stage: "Liquidsoap application start"
2022/01/15 05:27:10 [clock:4] Currently 1 clocks allocated.
2022/01/15 05:27:10 [clock.main:4] Starting 1 sources...
2022/01/15 05:27:10 [source:4] Source output.file_0 gets up with content kind: {audio=ffmpeg.audio.copy,video=ffmpe
g.video.copy,midi=none}.
2022/01/15 05:27:10 [output.url:5] Clock is main[].
2022/01/15 05:27:10 [output.url:5] Content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}, conte
nt type: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}
2022/01/15 05:27:10 [output.url:4] Content type is {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/15 05:27:10 [source:4] Source list.m3u gets up with content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.vid
eo.copy,midi=none}.
2022/01/15 05:27:10 [list.m3u:5] Clock is main[].
2022/01/15 05:27:10 [list.m3u:5] Content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}, content
 type: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}
2022/01/15 05:27:10 [list.m3u:4] Content type is {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/15 05:27:10 [list.m3u:5] Activations changed: static=[output.url:output.url], dynamic=[].
2022/01/15 05:27:10 [output.url:5] Activations changed: static=[output.url], dynamic=[].
2022/01/15 05:27:10 [output.url:5] Enabling caching mode: active source.
2022/01/15 05:27:10 [threads:4] Created thread "clock_main" (1 total).
2022/01/15 05:27:10 [clock:4] Main phase starts.
2022/01/15 05:27:10 [clock.main:3] Streaming loop starts in auto-sync mode
2022/01/15 05:27:10 [threads:4] Created thread "generic queue #1" (1 total).
2022/01/15 05:27:10 [clock.main:3] Delegating synchronisation to CPU clock
2022/01/15 05:27:10 [threads:4] Created thread "generic queue #2" (2 total).
2022/01/15 05:27:10 [list.m3u:5] Next song will be "./5.mp4".
2022/01/15 05:27:10 [threads:4] Created thread "non-blocking queue #1" (3 total).
2022/01/15 05:27:10 [request:5] Resolving request [[./5.mp4]].
2022/01/15 05:27:10 [threads:4] Created thread "non-blocking queue #2" (4 total).
2022/01/15 05:27:10 [request:6] Resolve step ./5.mp4 in [[./5.mp4]].
2022/01/15 05:27:10 [decoder.ogg:4] Unsupported file extension for "./5.mp4"!
2022/01/15 05:27:10 [decoder:4] Available decoders: FFMPEG (priority: 10)
2022/01/15 05:27:10 [list.m3u:5] Queue is empty!
2022/01/15 05:27:10 [list.m3u:5] Failed to prepare track: no file.
2022/01/15 05:27:10 [list.m3u:5] Queue is empty!
2022/01/15 05:27:10 [list.m3u:5] Failed to prepare track: no file.
2022/01/15 05:27:10 [output.url:3] Source failed (no more tracks) stopping output...
2022/01/15 05:27:11 [decoder.ffmpeg:4] ffmpeg recognizes ./5.mp4 as: audio: {codec: aac, 48000Hz, 2 channel(s)}, vi
deo: {codec: h264, 1920x1080, yuv420p} and content-type: {audio=ffmpeg.audio.copy(sample_rate=48000,sample_format=f
ltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=yuv420p,aspect_ratio=1/1,height=1080,
width=1920,codec="h264"),midi=none}.
2022/01/15 05:27:11 [decoder:4] Selected decoder FFMPEG for file "./5.mp4" with expected kind {audio=ffmpeg.audio.c
opy(sample_rate=48000,sample_format=fltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=
yuv420p,aspect_ratio=1/1,height=1080,width=1920,codec="h264"),midi=none} and detected content {audio=ffmpeg.audio.c
opy(sample_rate=48000,sample_format=fltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=
yuv420p,aspect_ratio=1/1,height=1080,width=1920,codec="h264"),midi=none}
2022/01/15 05:27:11 [list.m3u:5] Queue is empty!
2022/01/15 05:27:11 [list.m3u:5] Failed to prepare track: no file.
2022/01/15 05:27:11 [decoder.ogg:4] Unsupported file extension for "./5.mp4"!
2022/01/15 05:27:11 [decoder.taglib:4] Unsupported file extension for "./5.mp4"!
2022/01/15 05:27:11 [decoder.id3v2:4] Unsupported file extension for "./5.mp4"!
2022/01/15 05:27:11 [request:5] Resolved to [[./5.mp4]].
2022/01/15 05:27:11 [request:5] Resolving request [[./5.mp4]].
2022/01/15 05:27:11 [request:5] Resolved to [[./5.mp4]].
2022/01/15 05:27:11 [list.m3u:4] Queued 1 requests
2022/01/15 05:27:11 [list.m3u:4] Remaining 0 requests
2022/01/15 05:27:11 [list.m3u:3] Prepared "./5.mp4" (RID 1).
[rtmp @ 0x7f89b3015d00] Server error: Already publishing
2022/01/15 05:27:11 [clock.main:4] Source output.url failed while streaming: Avutil.Error(Operation not permitted)!
2022/01/15 05:27:11 [clock.main:4] Raised by primitive operation at Av.open_output in file "av/av.ml", line 246, ch
aracters 20-77
2022/01/15 05:27:11 [clock.main:4] Called from Ffmpeg_encoder_common.encoder.make in file "encoder/ffmpeg_encoder_c
ommon.ml", line 97, characters 22-62
2022/01/15 05:27:11 [clock.main:4] Called from Ffmpeg_encoder_common.encoder in file "encoder/ffmpeg_encoder_common
.ml", line 115, characters 20-29
2022/01/15 05:27:11 [clock.main:4] Called from Pipe_output.base#start in file "outputs/pipe_output.ml", line 63, ch
aracters 22-32
2022/01/15 05:27:11 [clock.main:4] Called from Start_stop.base#transition_to in file "tools/start_stop.ml", line 50
, characters 12-22
2022/01/15 05:27:11 [clock.main:4] Called from Output.output#output in file "outputs/output.ml", line 154, characte
rs 8-41
2022/01/15 05:27:11 [clock.main:4] Called from Clock.clock#end_tick.(fun) in file "clock.ml", line 299, characters
14-22
2022/01/15 05:27:11 [clock.main:4]
2022/01/15 05:27:11 [output.url:5] Activations changed: static=[], dynamic=[].
2022/01/15 05:27:11 [source:5] Source output.url gets down.
2022/01/15 05:27:11 [list.m3u:5] Activations changed: static=[], dynamic=[].
2022/01/15 05:27:11 [source:5] Source list.m3u gets down.
2022/01/15 05:27:11 [list.m3u:4] Waiting for feeding task to stop...
2022/01/15 05:27:11 [list.m3u:4] Finished with "./5.mp4".
2022/01/15 05:27:11 [list.m3u:4] Cleaning up request queue...
2022/01/15 05:27:11 [clock.main:3] Streaming loop stopped.
2022/01/15 05:27:11 [threads:4] Thread "clock_main" terminated (0 remaining).
2022/01/15 05:27:11 [main:3] Shutdown started!
2022/01/15 05:27:11 [lifecycle:5] At stage: "Liquidsoap core shutdown"
2022/01/15 05:27:11 [main:3] Waiting for main threads to terminate...
2022/01/15 05:27:11 [main:3] Main threads terminated.
2022/01/15 05:27:11 [lifecycle:5] At stage: "Liquidsoap scheduler shutdown"
2022/01/15 05:27:11 [threads:3] Shutting down scheduler...
2022/01/15 05:27:11 [threads:4] Thread "non-blocking queue #2" terminated (3 remaining).
2022/01/15 05:27:11 [threads:4] Thread "generic queue #1" terminated (2 remaining).
2022/01/15 05:27:11 [threads:4] Thread "generic queue #2" terminated (1 remaining).
2022/01/15 05:27:11 [threads:4] Thread "non-blocking queue #1" terminated (0 remaining).
2022/01/15 05:27:11 [threads:3] Scheduler shut down.
2022/01/15 05:27:11 [lifecycle:5] At stage: "Liquidsoap final cleanup"
2022/01/15 05:27:11 [main:3] Cleaning downloaded files...
2022/01/15 05:27:11 [main:3] Freeing memory...
2022/01/15 05:27:11 >>> LOG END

I can stream with ffmpeg -v debug -re -f concat -safe 0 -i ./list.txt -c copy -f flv rtmp://localhost:1935/live without any issue. by the way, single file works fine.

toots commented 2 years ago

This script works fine here:

log.level.set(4)

p = playlist("/tmp/pl")

output.url(
  fallible=true,
  %ffmpeg(format="flv", %audio.copy, %video.copy),
  url="rtmp://a.rtmp.youtube.com/live2/XXXX",
  p
)

The error in your logs seems to relate to a connection issue:

[rtmp @ 0x7f89b3015d00] Server error: Already publishing
WitzHsiao commented 2 years ago

Weird, my rtmp server is on docker, I recreate container everytime, but still got the issue. can you help me to reproduce it? The following is my nginx config.

worker_processes auto;
rtmp_auto_push on;
error_log /dev/stdout info;
daemon off;

events {
    worker_connections 1024;
}
rtmp {
    server {
        listen 1935;
        listen [::]:1935 ipv6only=on;

        application live {
            live on;
            record off;
            meta copy;
            push rtmp://a.rtmp.youtube.com/live2/XXXX;
        }
    }
}

and I run it with docker run -d -p 1935:1935 -v /path/nginx.conf:/etc/nginx/nginx.conf.template alfg/nginx-rtmp

toots commented 2 years ago

I'll see if I can reproduce. Have you tried pushing directly to YT? Does that work?

WitzHsiao commented 2 years ago

I can try ,but In my case I’m going to use rtmp server to push to multiple service

toots commented 2 years ago

I'm keeping a tab on this, will try to reproduce as soon as possible. Have you tried to increase the ffmpeg log verbosity? 

settings.ffmpeg.log.verbosity.set("debug")

Should give us a lot of information.

WitzHsiao commented 2 years ago

@toots, thank you for your help. please check the log below

2022/01/22 00:56:20 >>> LOG START
2022/01/22 00:56:19 [main:3] Liquidsoap 2.0.2
2022/01/22 00:56:19 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.5.0 sedlex=2.5 menhirLib=20211128 curl=0.9.2 dtools=0.4.4 duppy=0.9.2 cry=0.6.5 mm=0.7.2 ogg=0.7.0 ogg.decoder=0.7.0 vorbis=0.8.0 vorbis.decoder=0.8.0 mad=0.5.1 dynlink=[distributed with Ocaml] lame=0.3.5 ffmpeg=1.1.1 samplerate=0.1.6 taglib=0.3.8 camomile=1.0.2
2022/01/22 00:56:19 [dynamic.loader:3] Could not find dynamic module for fdkaac encoder.
2022/01/22 00:56:19 [clock:3] Using builtin (low-precision) implementation for latency control
2022/01/22 00:56:20 [list.m3u:4] Reloading playlist.
2022/01/22 00:56:20 [request:5] Resolving request [[list.m3u]].
2022/01/22 00:56:20 [request:5] Resolved to [[list.m3u]].
2022/01/22 00:56:20 [playlist parser:4] Trying youtube-dl parser
2022/01/22 00:56:20 [playlist parser:4] Trying application/x-cue parser
2022/01/22 00:56:20 [playlist parser:4] Trying audio/x-scpls parser
2022/01/22 00:56:20 [playlist parser:4] Trying application/x-mpegURL parser
2022/01/22 00:56:20 [frame:4] frame.audio.channels set to: 2
2022/01/22 00:56:20 [frame:4] frame.video.default set to: false
2022/01/22 00:56:20 [frame:4] frame.midi.channels set to: 0
2022/01/22 00:56:20 [frame:4] frame.video.width set to: 1280
2022/01/22 00:56:20 [frame:4] frame.video.height set to: 720
2022/01/22 00:56:20 [frame:4] frame.audio.samplerate set to: 44100
2022/01/22 00:56:20 [frame:4] frame.video.framerate set to: 25
2022/01/22 00:56:20 [frame:4] frame.audio.samplerate set to: 44100
2022/01/22 00:56:20 [frame:3] Using 44100Hz audio, 25Hz video, 44100Hz main.
2022/01/22 00:56:20 [frame:3] Video frame size set to: 1280x720
2022/01/22 00:56:20 [frame:3] Frame size must be a multiple of 1764 ticks = 1764 audio samples = 1 video samples.
2022/01/22 00:56:20 [frame:3] Targeting 'frame.duration': 0.04s = 1764 audio samples = 1764 ticks.
2022/01/22 00:56:20 [frame:3] Frames last 0.04s = 1764 audio samples = 1 video samples = 1764 ticks.
2022/01/22 00:56:20 [sandbox:3] Could not find binary bwrap, disabling sandboxing.
2022/01/22 00:56:20 [video.converter:3] Using preferred video converter: ffmpeg.
2022/01/22 00:56:20 [audio.converter:3] Using samplerate converter: ffmpeg.
2022/01/22 00:56:20 [lifecycle:5] At stage: "Liquidsoap application start"
2022/01/22 00:56:20 [clock:4] Currently 1 clocks allocated.
2022/01/22 00:56:20 [clock.main:4] Starting 1 sources...
2022/01/22 00:56:20 [source:4] Source output.file_0 gets up with content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/22 00:56:20 [output.url:5] Clock is main[].
2022/01/22 00:56:20 [output.url:5] Content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}, content type: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}
2022/01/22 00:56:20 [output.url:4] Content type is {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/22 00:56:20 [source:4] Source list.m3u gets up with content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/22 00:56:20 [list.m3u:5] Clock is main[].
[rtmp @ 0x7fefc8004980] No default whitelist set
2022/01/22 00:56:20 [list.m3u:5] Content kind: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}, content type: {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}
2022/01/22 00:56:20 [list.m3u:4] Content type is {audio=ffmpeg.audio.copy,video=ffmpeg.video.copy,midi=none}.
2022/01/22 00:56:20 [list.m3u:5] Activations changed: static=[output.url:output.url], dynamic=[].
[tcp @ 0x7fefc6e0ce40] No default whitelist set
[tcp @ 0x7fefc6e0ce40] Original list of addresses:
[tcp @ 0x7fefc6e0ce40] Address ::1 port 1935
[tcp @ 0x7fefc6e0ce40] Address 127.0.0.1 port 1935
[tcp @ 0x7fefc6e0ce40] Interleaved list of addresses:
[tcp @ 0x7fefc6e0ce40] Address ::1 port 1935
[tcp @ 0x7fefc6e0ce40] Address 127.0.0.1 port 1935
[tcp @ 0x7fefc6e0ce40] Starting connection attempt to ::1 port 1935
[tcp @ 0x7fefc6e0ce40] Successfully connected to ::1 port 1935
[rtmp @ 0x7fefc8004980] Handshaking...
[rtmp @ 0x7fefc8004980] Type answer 3
[rtmp @ 0x7fefc8004980] Server version 13.14.10.13
[rtmp @ 0x7fefc8004980] Proto = rtmp, path = /live, app = live, fname =
[rtmp @ 0x7fefc8004980] Window acknowledgement size = 5000000
[rtmp @ 0x7fefc8004980] Max sent, unacked = 5000000
[rtmp @ 0x7fefc8004980] New incoming chunk size = 4096
[rtmp @ 0x7fefc8004980] Releasing stream...
[rtmp @ 0x7fefc8004980] FCPublish stream...
[rtmp @ 0x7fefc8004980] Creating stream...
[rtmp @ 0x7fefc8004980] Sending publish command for ''
2022/01/22 00:56:20 [output.url:5] Activations changed: static=[output.url], dynamic=[].
2022/01/22 00:56:20 [output.url:5] Enabling caching mode: active source.
2022/01/22 00:56:20 [threads:4] Created thread "clock_main" (1 total).
2022/01/22 00:56:20 [clock.main:3] Streaming loop starts in auto-sync mode
2022/01/22 00:56:20 [clock.main:3] Delegating synchronisation to CPU clock
2022/01/22 00:56:20 [clock:4] Main phase starts.
2022/01/22 00:56:20 [threads:4] Created thread "generic queue #1" (1 total).
2022/01/22 00:56:20 [threads:4] Created thread "generic queue #2" (2 total).
2022/01/22 00:56:20 [threads:4] Created thread "non-blocking queue #1" (3 total).
2022/01/22 00:56:20 [threads:4] Created thread "non-blocking queue #2" (4 total).
2022/01/22 00:56:20 [list.m3u:5] Next song will be "./5.mp4".
2022/01/22 00:56:20 [request:5] Resolving request [[./5.mp4]].
2022/01/22 00:56:20 [request:6] Resolve step ./5.mp4 in [[./5.mp4]].
2022/01/22 00:56:20 [decoder.ogg:4] Unsupported file extension for "./5.mp4"!
2022/01/22 00:56:20 [decoder:4] Available decoders: FFMPEG (priority: 10)
[NULL @ 0x7fefce808c00] Opening './5.mp4' for reading
[file @ 0x7fefc8005280] Setting default whitelist 'file,crypto,data'
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Format mov,mp4,m4a,3gp,3g2,mj2 probed with size=2048 and score=100
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] ISO: File Type Major Brand: mp42
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 0, edit list 0 - media time: 0, duration: 12266254
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 1, edit list 0 - media time: 0, duration: 19626006
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Before avformat_find_stream_info() pos: 171529 bytes read:189113 seeks:0 nb_streams:2
[h264 @ 0x7fefc701da00] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 5(IDR), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] Format yuv420p chosen by get_format().
[h264 @ 0x7fefc701da00] Reinit context to 1920x1088, pix_fmt: yuv420p
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
2022/01/22 00:56:20 [list.m3u:5] Queue is empty!
2022/01/22 00:56:20 [list.m3u:5] Failed to prepare track: no file.
2022/01/22 00:56:20 [list.m3u:5] Queue is empty!
2022/01/22 00:56:20 [list.m3u:5] Failed to prepare track: no file.
2022/01/22 00:56:20 [output.url:3] Source failed (no more tracks) stopping output...
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefc701da00] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefc701da00] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] All info found
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] After avformat_find_stream_info() pos: 344280 bytes read:355384 seeks:0 frames:11
2022/01/22 00:56:20 [decoder.ffmpeg:4] ffmpeg recognizes ./5.mp4 as: audio: {codec: aac, 48000Hz, 2 channel(s)}, video: {codec: h264, 1920x1080, yuv420p} and content-type: {audio=ffmpeg.audio.copy(sample_rate=48000,sample_format=fltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=yuv420p,aspect_ratio=1/1,height=1080,width=1920,codec="h264"),midi=none}.
[AVIOContext @ 0x7fefc80053c0] Statistics: 355384 bytes read, 0 seeks
[NULL @ 0x7fefce808c00] Opening './5.mp4' for reading
[file @ 0x7fefc80052c0] Setting default whitelist 'file,crypto,data'
2022/01/22 00:56:20 [decoder:4] Selected decoder FFMPEG for file "./5.mp4" with expected kind {audio=ffmpeg.audio.copy(sample_rate=48000,sample_format=fltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=yuv420p,aspect_ratio=1/1,height=1080,width=1920,codec="h264"),midi=none} and detected content {audio=ffmpeg.audio.copy(sample_rate=48000,sample_format=fltp,channel_layout="stereo",codec="aac"),video=ffmpeg.video.copy(pixel_format=yuv420p,aspect_ratio=1/1,height=1080,width=1920,codec="h264"),midi=none}
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Format mov,mp4,m4a,3gp,3g2,mj2 probed with size=2048 and score=100
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] ISO: File Type Major Brand: mp42
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 0, edit list 0 - media time: 0, duration: 12266254
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 1, edit list 0 - media time: 0, duration: 19626006
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Before avformat_find_stream_info() pos: 171529 bytes read:189113 seeks:0 nb_streams:2
[h264 @ 0x7fefce819800] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 5(IDR), nal_ref_idc: 3
[h264 @ 0x7fefce819800] Format yuv420p chosen by get_format().
[h264 @ 0x7fefce819800] Reinit context to 1920x1088, pix_fmt: yuv420p
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
2022/01/22 00:56:20 [list.m3u:5] Queue is empty!
2022/01/22 00:56:20 [list.m3u:5] Failed to prepare track: no file.
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] All info found
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] After avformat_find_stream_info() pos: 344280 bytes read:355384 seeks:0 frames:11
[AVIOContext @ 0x7fefc8005400] Statistics: 355384 bytes read, 0 seeks
2022/01/22 00:56:20 [decoder.ogg:4] Unsupported file extension for "./5.mp4"!
2022/01/22 00:56:20 [decoder.taglib:4] Unsupported file extension for "./5.mp4"!
2022/01/22 00:56:20 [decoder.id3v2:4] Unsupported file extension for "./5.mp4"!
2022/01/22 00:56:20 [request:5] Resolved to [[./5.mp4]].
2022/01/22 00:56:20 [request:5] Resolving request [[./5.mp4]].
2022/01/22 00:56:20 [request:5] Resolved to [[./5.mp4]].
2022/01/22 00:56:20 [list.m3u:4] Queued 1 requests
2022/01/22 00:56:20 [list.m3u:4] Remaining 0 requests
[NULL @ 0x7fefce808c00] Opening './5.mp4' for reading
[file @ 0x7fefc8005300] Setting default whitelist 'file,crypto,data'
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Format mov,mp4,m4a,3gp,3g2,mj2 probed with size=2048 and score=100
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] ISO: File Type Major Brand: mp42
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 0, edit list 0 - media time: 0, duration: 12266254
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Unknown dref type 0x206c7275 size 12
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Processing st: 1, edit list 0 - media time: 0, duration: 19626006
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce808c00] Before avformat_find_stream_info() pos: 171529 bytes read:189113 seeks:0 nb_streams:2
[h264 @ 0x7fefce819800] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 7(SPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 8(PPS), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 5(IDR), nal_ref_idc: 3
[h264 @ 0x7fefce819800] Format yuv420p chosen by get_format().
[h264 @ 0x7fefce819800] Reinit context to 1920x1088, pix_fmt: yuv420p
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[h264 @ 0x7fefce819800] nal_unit_type: 9(AUD), nal_ref_idc: 0
[h264 @ 0x7fefce819800] nal_unit_type: 1(Coded slice of a non-IDR picture), nal_ref_idc: 3
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce013c00] All info found
[mov,mp4,m4a,3gp,3g2,mj2 @ 0x7fefce013c00] After avformat_find_stream_info() pos: 344280 bytes read:355384 seeks:0 frames:11
[rtmp @ 0x7fefc6e0e600] No default whitelist set
2022/01/22 00:56:20 [list.m3u:3] Prepared "./5.mp4" (RID 1).
[tcp @ 0x7fefc6e0e6c0] No default whitelist set
[tcp @ 0x7fefc6e0e6c0] Original list of addresses:
[tcp @ 0x7fefc6e0e6c0] Address ::1 port 1935
[tcp @ 0x7fefc6e0e6c0] Address 127.0.0.1 port 1935
[tcp @ 0x7fefc6e0e6c0] Interleaved list of addresses:
[tcp @ 0x7fefc6e0e6c0] Address ::1 port 1935
[tcp @ 0x7fefc6e0e6c0] Address 127.0.0.1 port 1935
[tcp @ 0x7fefc6e0e6c0] Starting connection attempt to ::1 port 1935
[tcp @ 0x7fefc6e0e6c0] Successfully connected to ::1 port 1935
[rtmp @ 0x7fefc6e0e600] Handshaking...
[rtmp @ 0x7fefc6e0e600] Type answer 3
[rtmp @ 0x7fefc6e0e600] Server version 13.14.10.13
[rtmp @ 0x7fefc6e0e600] Proto = rtmp, path = /live, app = live, fname =
[rtmp @ 0x7fefc6e0e600] Window acknowledgement size = 5000000
[rtmp @ 0x7fefc6e0e600] Max sent, unacked = 5000000
[rtmp @ 0x7fefc6e0e600] New incoming chunk size = 4096
[rtmp @ 0x7fefc6e0e600] Releasing stream...
[rtmp @ 0x7fefc6e0e600] FCPublish stream...
[rtmp @ 0x7fefc6e0e600] Creating stream...
[rtmp @ 0x7fefc6e0e600] Sending publish command for ''
[rtmp @ 0x7fefc6e0e600] Server error: Already publishing
2022/01/22 00:56:20 [clock.main:4] Source output.url failed while streaming: Avutil.Error(Operation not permitted)!
2022/01/22 00:56:20 [clock.main:4] Raised by primitive operation at Av.open_output in file "av/av.ml", line 246, characters 20-77
2022/01/22 00:56:20 [clock.main:4] Called from Ffmpeg_encoder_common.encoder.make in file "encoder/ffmpeg_encoder_common.ml", line 97, characters 22-62
2022/01/22 00:56:20 [clock.main:4] Called from Ffmpeg_encoder_common.encoder in file "encoder/ffmpeg_encoder_common.ml", line 115, characters 20-29
2022/01/22 00:56:20 [clock.main:4] Called from Pipe_output.base#start in file "outputs/pipe_output.ml", line 63, characters 22-32
2022/01/22 00:56:20 [clock.main:4] Called from Start_stop.base#transition_to in file "tools/start_stop.ml", line 50, characters 12-22
2022/01/22 00:56:20 [clock.main:4] Called from Output.output#output in file "outputs/output.ml", line 154, characters 8-41
2022/01/22 00:56:20 [clock.main:4] Called from Clock.clock#end_tick.(fun) in file "clock.ml", line 299, characters 14-22
[AVIOContext @ 0x7fefc9b04a40] Statistics: 355384 bytes read, 0 seeks
2022/01/22 00:56:20 [clock.main:4]
2022/01/22 00:56:20 [output.url:5] Activations changed: static=[], dynamic=[].
2022/01/22 00:56:20 [source:5] Source output.url gets down.
2022/01/22 00:56:20 [list.m3u:5] Activations changed: static=[], dynamic=[].
2022/01/22 00:56:20 [source:5] Source list.m3u gets down.
2022/01/22 00:56:20 [list.m3u:4] Waiting for feeding task to stop...
2022/01/22 00:56:20 [list.m3u:4] Finished with "./5.mp4".
2022/01/22 00:56:20 [list.m3u:4] Cleaning up request queue...
2022/01/22 00:56:20 [clock.main:3] Streaming loop stopped.
2022/01/22 00:56:20 [threads:4] Thread "clock_main" terminated (0 remaining).
2022/01/22 00:56:20 [main:3] Shutdown started!
2022/01/22 00:56:20 [lifecycle:5] At stage: "Liquidsoap core shutdown"
2022/01/22 00:56:20 [main:3] Waiting for main threads to terminate...
2022/01/22 00:56:20 [main:3] Main threads terminated.
2022/01/22 00:56:20 [lifecycle:5] At stage: "Liquidsoap scheduler shutdown"
2022/01/22 00:56:20 [threads:3] Shutting down scheduler...
2022/01/22 00:56:20 [threads:4] Thread "generic queue #1" terminated (3 remaining).
2022/01/22 00:56:20 [threads:4] Thread "non-blocking queue #2" terminated (2 remaining).
2022/01/22 00:56:20 [threads:4] Thread "non-blocking queue #1" terminated (1 remaining).
2022/01/22 00:56:20 [threads:4] Thread "generic queue #2" terminated (0 remaining).
2022/01/22 00:56:20 [threads:3] Scheduler shut down.
[AVIOContext @ 0x7fefc6f0be40] Statistics: 0 seeks, 0 writeouts
[rtmp @ 0x7fefc8004980] UnPublishing stream...
[rtmp @ 0x7fefc8004980] Deleting stream...
2022/01/22 00:56:20 [lifecycle:5] At stage: "Liquidsoap final cleanup"
2022/01/22 00:56:20 [main:3] Cleaning downloaded files...
2022/01/22 00:56:20 [main:3] Freeing memory...
toots commented 2 years ago

Thanks. I think I see what's going on here. The operator's logic is to connect immediately upon starting. However, the playlist files take a minute to be ready, leading to the operator briefly going down and then reconnecting when the first file is available.

I'm gonna fix that in the code. Meanwhile, I'd suggest to add a static single as initial fallback. This should make your output infallible, thus making sure that it never goes down:

static = single("/path/to/file")
source = playlist(reload_mode="watch", mode="normal", "list.m3u")

source = fallback(track_sensitive=false, [source, static])

enc=%ffmpeg(
  format="flv",
  %audio.copy,
  %video.copy)

output.url(
  url="rtmp://localhost:1935/live",
  enc,
  source)

As usual with copy content, make sure all files, static and playlist content, have compatible content (same encoding format, video size, samplerate etc..)

WitzHsiao commented 2 years ago

@toots great, the workaround works. but I found a weird issue. The video and audio is out of sync after streaming a while. Do you have any idea about this?

toots commented 2 years ago

Hmm. If the stream has a slightly different duration for audio and video that could happen. FFmpeg has a notion of presentation timestamp that can be used to work around that I believe. I'm down to look into it but, first, do you know if the issue occurs with the ffmpeg CLI?

WitzHsiao commented 2 years ago

@toots my ffmpeg command ffmpeg -v debug -re -f concat -safe 0 -i ./list.txt -c copy -f flv rtmp://localhost:1935/live works with no issue

toots commented 2 years ago

Thanks. I think I have some ideas about how to fix, will get back to you very soon.

toots commented 2 years ago

Are you able to test on a branch? This one has a potential fix: https://github.com/savonet/liquidsoap/pull/2192. There should be some builds of it here: https://github.com/savonet/liquidsoap/actions/runs/1767397547

toots commented 2 years ago

Edited the build make sure to pick the last one whenever you get to it.

toots commented 2 years ago

Hey! Any chance to test this? I think it should guarantee that all streams from the same copied muxed stream are always kept in sync. It becomes a little trickier if you are decoding one stream and keeping the other one encoded but that's something I'll see about next.

I'd like to move forward with 2.0.3 soon and include this fix so I'll prolly merge it soon if I don't hear back.

toots commented 2 years ago

PR merged, marking this as fixed. Please re-open or submit a new issue if needed.

WitzHsiao commented 2 years ago

@toots sorry for reply late. I just test it with Liquidsoap 2.0.3+dev but still out of sync after streaming a while :(

toots commented 2 years ago

Thanks for checking @WitzHsiao. Just to make sure:

WitzHsiao commented 2 years ago

  1. 2022/02/05 03:17:23 >>> LOG START 2022/02/05 03:17:21 [main:3] Liquidsoap 2.0.3+dev 2022/02/05 03:17:21 [main:3] Using: bytes=[distributed with OCaml 4.02 or above] pcre=7.5.0 sedlex=2.5 menhirLib=20211128 curl=0.9.2 dtools=0.4.4 duppy=0.9.2 cry=0. 6.5 mm=0.7.4 ogg=0.7.0 ogg.decoder=0.7.0 vorbis=0.8.0 vorbis.decoder=0.8.0 mad=0.5.1 dynlink=[distributed with Ocaml] lame=0.3.5 ffmpeg=1.1.1 samplerate=0.1.6 tagli b=0.3.8 camomile=1.0.2

  2. Yes, as I mentioned above, I just play a playlist with liquidsoap using output.url to my rtmp server and rtmp server push to youtube, then I can check on my youtube account after playing for a while.

toots commented 2 years ago

Thanks. I'm gonna look at this very shortly.

toots commented 2 years ago

I've started a script to reproduce, will report shortly.

toots commented 2 years ago

Well it turned out my previous fix was incomplete.. 🤦

I've been able to reproduce, fix and confirm the fix locally now. Thanks for your patience. Fix committed to main and v2.0.4-preview