search

arut / nginx-rtmp-module

NGINX-based Media Streaming Server
http://nginx-rtmp.blogspot.com
BSD 2-Clause "Simplified" License
13.45k stars 3.51k forks source link

exec ffmpeg not working when stream is relayed #1320

Open jubeiargh opened 6 years ago

jubeiargh commented 6 years ago

Hi,

I am trying to stream over my obs software to my first nginx application, do a on_publish callback and check if the streaming key is valid. Then redirect to the next application which is supposed to start ffmpeg and push this to the dash and hls applications. Here is my nginx config:

user  root;
worker_processes 1;

 error_log  logs/error.log info;
#error_log  logs/error.log  notice;
#error_log  logs/error.log  info;

#pid        logs/nginx.pid;

events {
   worker_connections  1024;
}

rtmp {

server {
    listen 1935; # Listen on standard RTMP port
    chunk_size 4000;

    application live{
        live on;
        allow publish all;
        allow play 127.0.0.1;
        deny play all;
        on_publish http://localhost:3001/on_publish;

    }

    application record {
        live on;
        meta copy;
        exec /usr/bin/ffmpeg -i rtmp://127.0.0.1/$app/$name
            -b:a 128k -c:a aac -c:v libx264 -b:v 512K
            -f flv rtmp://127.0.0.1/dash/$name_dash;

        on_publish_done http://localhost:3001/on_publish_done;

    }
    application dash {
        live on;

        dash on;
        dash_path /home/ali/nodejs/DashJSTest/dashjstest/public/dash;
        dash_nested on;
        dash_cleanup on;
    }
}
}

My redirect from http://localhost:3001/on_publish is handled by nodejs and express like this:

... res.writeHead(301, { 'Location': 'rtmp://127.0.0.1:1935/record/foo'} ); res.end(); ...

If I stream to application record it is working, but this way i cant change the name of the stream. I tested a custom bash if exec is actually being executed and yes it is. So my problem is that exec ffmpeg doesnt transcode if the stream is send to /live but if sent to /record it is transcoding.

Here is my notice log of nginx:

2018/09/27 01:07:43 [info] 13861#0: 1 client connected '192.168.178.42' 2018/09/27 01:07:43 [info] 13861#0: 1 connect: app='live' args='' flashver='FMLE/3.0 (compatible; FMSc/1.0)' swf_url='rtmp://192.168.178.67/live' tc_url='rtmp://192.168.178.67/live' page_url='' acodecs=0 vcodecs=0 object_encoding=0, client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 createStream, client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 publish: name='key123' args='' type=live silent=0, client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 notify: publish 'localhost:3001/on_publish', client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 notify: publish redirect received, client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 notify: push 'key123' to 'rtmp://127.0.0.1:1935/record/5ba90035c5a18e111395707e', client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 relay: create push name='key123' app='' playpath='' url='127.0.0.1:1935/record/5ba90035c5a18e111395707e', client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 4 client connected '127.0.0.1' 2018/09/27 01:07:43 [info] 13861#0: 1 relay: got metadata from @setDataFrame invocation from publisher., client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 1 relay: not sending metadata from @setDataFrame invocation from publisher to 127.0.0.1:1935/record/5ba90035c5a18e111395707e/record/5ba90035c5a18e111395707e, client: 192.168.178.42, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 4 connect: app='record' args='' flashver='LNX.11,1,102,55' swf_url='' tc_url='rtmp://127.0.0.1:1935/record' page_url='' acodecs=3575 vcodecs=252 object_encoding=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 4 createStream, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 4 publish: name='5ba90035c5a18e111395707e' args='' type=live silent=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 4 exec: starting managed child '/usr/bin/ffmpeg', client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 3 relay: sending metadata from NetStream.Publish.Start from player, client: 127.0.0.1:1935/record/5ba90035c5a18e111395707e, server: ngx-relay 2018/09/27 01:07:43 [info] 13861#0: 3 relay: data frame from codec context: width=1280 height=720 duration=0 frame_rate=0 video_codec_id=94 audio_codec_id=94621605283744, client: 127.0.0.1:1935/record/5ba90035c5a18e111395707e, server: ngx-relay 2018/09/27 01:07:43 [info] 13861#0: 3 relay: sending @setDataFrame, client: 127.0.0.1:1935/record/5ba90035c5a18e111395707e, server: ngx-relay 2018/09/27 01:07:43 [info] 13861#0: 4 relay: got metadata from @setDataFrame invocation from publisher., client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 5 client connected '127.0.0.1' 2018/09/27 01:07:43 [info] 13861#0: 5 connect: app='record' args='' flashver='LNX 9,0,124,2' swf_url='' tc_url='rtmp://127.0.0.1:1935/record' page_url='' acodecs=4071 vcodecs=252 object_encoding=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 5 createStream, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:43 [info] 13861#0: 5 play: name='5ba90035c5a18e111395707e' args='' start=-2000 duration=0 reset=0 silent=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [info] 13861#0: 5 recv() failed (104: Connection reset by peer), client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [info] 13861#0: 5 disconnect, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [info] 13861#0: 5 deleteStream, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [info] 13861#0: 4 exec: child 13868 exited; ignoring, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [info] 13861#0: 4 exec: terminating child 13868, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:44 [notice] 13861#0: signal 17 (SIGCHLD) received from 13868 2018/09/27 01:07:44 [notice] 13861#0: unknown process 13868 exited with code 1 2018/09/27 01:07:44 [info] 13861#0: epoll_wait() failed (4: Interrupted system call) 2018/09/27 01:07:49 [info] 13861#0: 4 exec: starting managed child '/usr/bin/ffmpeg', client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 client connected '127.0.0.1' 2018/09/27 01:07:49 [info] 13861#0: 6 connect: app='record' args='' flashver='LNX 9,0,124,2' swf_url='' tc_url='rtmp://127.0.0.1:1935/record' page_url='' acodecs=4071 vcodecs=252 object_encoding=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 createStream, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 play: name='5ba90035c5a18e111395707e' args='' start=-2000 duration=0 reset=0 silent=0, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 recv() failed (104: Connection reset by peer), client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 disconnect, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 6 deleteStream, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 4 exec: child 13869 exited; ignoring, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [info] 13861#0: 4 exec: terminating child 13869, client: 127.0.0.1, server: 0.0.0.0:1935 2018/09/27 01:07:49 [notice] 13861#0: signal 17 (SIGCHLD) received from 13869 2018/09/27 01:07:49 [notice] 13861#0: unknown process 13869 exited with code 1 2018/09/27 01:07:49 [info] 13861#0: epoll_wait() failed (4: Interrupted system call)

and here some debug log:

2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: fd:10 16 of 4114 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP bheader fmt=1 csid=4 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP mheader fmt=1 audio (8) time=30599+14 mlen=8 len=0 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP recv audio (8) csid=4 timestamp=30613 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 1 nhandlers: 5 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 0 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 1 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 2 2018/09/27 01:06:59 [debug] 13829#0: 1 live: audio packet timestamp=30613 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP prep audio (8) fmt=1 csid=6 timestamp=23 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 3 live: rel audio packet delta=23 2018/09/27 01:06:59 [debug] 13829#0: 3 RTMP send nmsg=1, priority=0 #199 2018/09/27 01:06:59 [debug] 13829#0: 3 send: fd:12 16 of 16 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 3 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 4 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 24 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 864 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:11 ev:0001 d:00007F45E5D7D2E1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: fd:11 16 of 4018 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP bheader fmt=1 csid=6 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP mheader fmt=1 audio (8) time=30590+23 mlen=8 len=0 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP recv audio (8) csid=6 timestamp=30613 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 4 nhandlers: 5 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 0 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 1 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 2 2018/09/27 01:06:59 [debug] 13829#0: 4 live: audio packet timestamp=30613 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP prep audio (8) fmt=1 csid=6 timestamp=23 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 3 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 4 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 0 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 864 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:10 ev:0001 d:00007F45E5D7D1F0 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: fd:10 4114 of 4114 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP bheader fmt=1 csid=4 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP mheader fmt=1 video (9) time=30613+20 mlen=5272 len=0 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 1 reusing formerly read data: 10 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP bheader fmt=3 csid=4 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP mheader fmt=3 video (9) time=30613+20 mlen=5272 len=4096 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: fd:10 1167 of 4104 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP recv video (9) csid=4 timestamp=30633 mlen=5272 msid=1 nbufs=2 2018/09/27 01:06:59 [debug] 13829#0: 1 nhandlers: 5 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 0 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 1 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 2 2018/09/27 01:06:59 [debug] 13829#0: 1 live: video packet timestamp=30633 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP prep video (9) fmt=1 csid=7 timestamp=34 mlen=5272 msid=1 nbufs=2 2018/09/27 01:06:59 [debug] 13829#0: 3 live: rel video packet delta=34 2018/09/27 01:06:59 [debug] 13829#0: 3 RTMP send nmsg=1, priority=2 #200 2018/09/27 01:06:59 [debug] 13829#0: 3 send: fd:12 4008 of 4008 2018/09/27 01:06:59 [debug] 13829#0: 3 send: fd:12 1273 of 1273 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 3 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 4 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 8 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 856 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:11 ev:0001 d:00007F45E5D7D2E1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: fd:11 4008 of 4018 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP bheader fmt=1 csid=7 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP mheader fmt=1 video (9) time=30599+34 mlen=5272 len=0 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 0 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 856 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:11 ev:0001 d:00007F45E5D7D2E1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: fd:11 1273 of 4018 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP bheader fmt=3 csid=7 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP mheader fmt=3 video (9) time=30599+34 mlen=5272 len=4000 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP recv video (9) csid=7 timestamp=30633 mlen=5272 msid=1 nbufs=2 2018/09/27 01:06:59 [debug] 13829#0: 4 nhandlers: 5 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 0 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 1 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 2 2018/09/27 01:06:59 [debug] 13829#0: 4 live: video packet timestamp=30633 2018/09/27 01:06:59 [debug] 13829#0: 4 RTMP prep video (9) fmt=1 csid=7 timestamp=34 mlen=5272 msid=1 nbufs=2 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 3 2018/09/27 01:06:59 [debug] 13829#0: 4 calling handler 4 2018/09/27 01:06:59 [debug] 13829#0: 4 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 0 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 856 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:10 ev:0001 d:00007F45E5D7D1F0 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:1 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: fd:10 16 of 4114 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP bheader fmt=1 csid=4 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP mheader fmt=1 audio (8) time=30633+3 mlen=8 len=0 msid=1 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP recv audio (8) csid=4 timestamp=30636 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 1 nhandlers: 5 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 0 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 1 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 2 2018/09/27 01:06:59 [debug] 13829#0: 1 live: audio packet timestamp=30636 2018/09/27 01:06:59 [debug] 13829#0: 1 RTMP prep audio (8) fmt=1 csid=6 timestamp=23 mlen=8 msid=1 nbufs=1 2018/09/27 01:06:59 [debug] 13829#0: 3 live: rel audio packet delta=23 2018/09/27 01:06:59 [debug] 13829#0: 3 RTMP send nmsg=1, priority=0 #201 2018/09/27 01:06:59 [debug] 13829#0: 3 send: fd:12 16 of 16 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 3 2018/09/27 01:06:59 [debug] 13829#0: 1 calling handler 4 2018/09/27 01:06:59 [debug] 13829#0: 1 recv: eof:0, avail:0 2018/09/27 01:06:59 [debug] 13829#0: timer delta: 12 2018/09/27 01:06:59 [debug] 13829#0: worker cycle 2018/09/27 01:06:59 [debug] 13829#0: epoll timer: 844 2018/09/27 01:06:59 [debug] 13829#0: epoll: fd:11 ev:0001 d:00007F45E5D7D2E1 2018/09/27 01:06:59 [debug] 13829#0: *4 recv: eof:0, avail:1

I appreciate any help! Thank you.

mkrn commented 5 years ago

Got the same problem, any solutions?

TalkVideo commented 5 years ago

Same problem. No solution. Yet.

TalkVideo commented 5 years ago

See other recent posts about exec not working. There is a problem.

lzqdename commented 3 years ago

Same problem. No solution. Yet.

lzqdename commented 3 years ago

exec_static /usr/bin/sh shelll_script_file_name; It works, I have test it!