search

ossrs / srs

SRS is a simple, high-efficiency, real-time media server supporting RTMP, WebRTC, HLS, HTTP-FLV, HTTP-TS, SRT, MPEG-DASH, and GB28181.
https://ossrs.io
MIT License
25.7k stars 5.38k forks source link

Edge: FFprobe may get stuck when pulling stream from edge. #2594

Open retamia opened 3 years ago

retamia commented 3 years ago

Description'

Please ensure that the markdown structure is maintained.

The first time using exec.Command in Go to execute FFprobe, and then executing FFmpeg, while using goroutines to read FFmpeg's StdoutPipe and StderrPipe, there is a probability of causing the streaming to freeze. If executing ffmpeg -i rtmp address in the terminal, the streaming freeze issue is automatically resolved. This phenomenon occurs when pulling streams from the edge vhost, but there is no such issue when pushing streams to the vhost.

Metadata:
  width                 960.00
  height                720.00
  videodatarate         293.72
  framerate             29.92
  videocodecid          7.00
  audiodatarate         62.64
  audiosamplerate       22050.00
  audiosamplesize       16.00
  stereo                TRUE
  audiocodecid          10.00
  major_brand           isom
  minor_version         512
  compatible_brands     isomiso2avc1mp41
  encoder               Lavf58.76.100
  filesize              0.00
  server                SRS/5.0.11(Leo)
  server_version        5.0.11
[h264 @ 0x7fd03c809400] co located POCs unavailable
Input #0, flv, from 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com':
  Metadata:
    major_brand     : isom
    minor_version   : 512
    compatible_brands: isomiso2avc1mp41
    encoder         : Lavf58.76.100
    server          : SRS/5.0.11(Leo)
    server_version  : 5.0.11
  Duration: N/A, start: 0.055000, bitrate: 364 kb/s
  Stream #0:0: Audio: aac (LC), 22050 Hz, stereo, fltp, 64 kb/s
  Stream #0:1: Video: h264 (High), yuv420p(progressive), 960x720, 300 kb/s, 29.92 fps, 29.92 tbr, 1k tbn, 59.83 tbc
Metadata:
  width                 960.00
  height                720.00
  videodatarate         293.72
  framerate             29.92
  videocodecid          7.00
  audiodatarate         62.64
  audiosamplerate       22050.00
  audiosamplesize       16.00
  stereo                TRUE
  audiocodecid          10.00
  major_brand           isom
  minor_version         512
  compatible_brands     isomiso2avc1mp41
  encoder               Lavf58.76.100
  filesize              0.00
  server                SRS/5.0.11(Leo)
  server_version        5.0.11
[h264 @ 0x7fbb2b81aa00] co located POCs unavailable
Input #0, flv, from 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com':
  Metadata:
    major_brand     : isom
    minor_version   : 512
    compatible_brands: isomiso2avc1mp41
    encoder         : Lavf58.76.100
    server          : SRS/5.0.11(Leo)
    server_version  : 5.0.11
  Duration: N/A, start: 0.056000, bitrate: 364 kb/s
  Stream #0:0: Audio: aac (LC), 22050 Hz, stereo, fltp, 64 kb/s
  Stream #0:1: Video: h264 (High), yuv420p(progressive), 960x720, 300 kb/s, 29.92 fps, 29.92 tbr, 1k tbn, 59.83 tbc
Stream mapping:
  Stream #0:1 -> #0:0 (h264 (native) -> h264 (libx264))
  Stream #0:0 -> #0:1 (copy)
Press [q] to stop, [?] for help
[h264 @ 0x7fbb2d008200] co located POCs unavailable
[h264 @ 0x7fbb2d021a00] co located POCs unavailable
[h264 @ 0x7fbb2d022c00] mmco: unref short failure
RTMP_ReadPacket, failed to read RTMP packet header
[libx264 @ 0x7fbb2b831200] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 0x7fbb2b831200] profile High, level 3.1, 4:2:0, 8-bit
[libx264 @ 0x7fbb2b831200] 264 - core 163 r3060 5db6aa6 - H.264/MPEG-4 AVC codec - Copyleft 2003-2021 - http://www.videolan.org/x264.html - options: cabac=1 ref=1 deblock=1:0:0 analyse=0x3:0x113 me=hex subme=2 psy=1 psy_rd=1.00:0.00 mixed_ref=0 me_range=16 chroma_me=1 trellis=0 8x8dct=1 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=0 threads=8 lookahead_threads=2 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=3 b_pyramid=2 b_adapt=1 b_bias=0 direct=1 weightb=1 open_gop=0 weightp=1 keyint=60 keyint_min=6 scenecut=40 intra_refresh=0 rc_lookahead=10 rc=crf mbtree=1 crf=23.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 ip_ratio=1.40 aq=1:1.00

Output #0, flv, to 'rtmp://192.168.1.143:1935/test/lmt_trans?vhost=test-push.live.com':
  Metadata:
    major_brand     : isom
    minor_version   : 512
    compatible_brands: isomiso2avc1mp41
    server_version  : 5.0.11
    server          : SRS/5.0.11(Leo)
    encoder         : Lavf58.76.100
  Stream #0:0: Video: h264 ([7][0][0][0] / 0x0007), yuv420p, 960x720, q=2-31, 29.92 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libx264
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
  Stream #0:1: Audio: aac (LC) ([10][0][0][0] / 0x000A), 22050 Hz, stereo, fltp, 64 kb/s
frame=    0 fps=0.0 q=0.0 size=       1kB time=00:00:01.67 bitrate=   2.6kbits/s speed=0.0557x    
WriteN, RTMP send error 32 (136 bytes)
WriteN, RTMP send error 32 (69 bytes)
WriteN, RTMP send error 9 (42 bytes)
[flv @ 0x7fbb2b89fa00] Failed to update header with correct duration.
[flv @ 0x7fbb2b89fa00] Failed to update header with correct filesize.
Error writing trailer of rtmp://192.168.1.143:1935/test/lmt_trans?vhost=test-push.live.com: Operation not permitted
frame=    0 fps=0.0 q=0.0 Lsize=       1kB time=00:00:01.67 bitrate=   2.6kbits/s speed=0.0556x
  1. SRS version: 5.0.11
  2. The log of SRS is as follows: 
    [2021-09-10 15:12:51.935][Trace][88004][2d21q950] RTMP client ip=127.0.0.1:63840, fd=10
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] simple handshake success.
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] connect app, tcUrl=rtmp://test-push.live.com/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-push.live.com, port=1935, app=test, args=null
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] client identified, type=fmle-publish, vhost=test-push.live.com, app=test, stream=lmt, param=, duration=0ms
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] connected stream, tcUrl=rtmp://test-push.live.com/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-push.live.com, port=1935, app=test, stream=lmt, param=, args=null
[2021-09-10 15:12:51.935][Trace][88004][2d21q950] source url=test-push.live.com/test/lmt, ip=127.0.0.1, cache=0, is_edge=0, source_id=/e84u8820
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] ignore disabled exec for vhost=test-push.live.com
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] set fd=10 TCP_NODELAY 0=>4
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] start publish mr=0/350, p1stpt=20000, pnt=5000, tcp_nodelay=1
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] got metadata, width=960, height=720, vcodec=7, acodec=10
[2021-09-10 15:12:51.936][Warn][88004][2d21q950][35] drop for reduce sh metadata, size=388
[2021-09-10 15:12:51.936][Warn][88004][2d21q950][35] drop for reduce sh video, size=51
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] 51B video sh,  codec(7, profile=High, level=3.1, 960x720, 0kbps, 0.0fps, 0.0s)
[2021-09-10 15:12:51.936][Warn][88004][2d21q950][35] drop for reduce sh audio, size=4
[2021-09-10 15:12:51.936][Trace][88004][2d21q950] 4B audio sh, codec(10, profile=LC, 2channels, 0kbps, 22050HZ), flv(16bits, 2channels, 22050HZ)
[2021-09-10 15:12:51.971][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=1,0, timer=58,0,0, clock=0,15,26,3,0,0,0,0,0
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] RTMP client ip=192.168.1.143:63843, fd=13
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] simple handshake success.
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] connect app, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=192.168.1.143, port=1935, app=test, args=null
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] ignore AMF0/AMF3 command message.
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] client identified, type=rtmp-play, vhost=test-play.live.com, app=test, stream=lmt, param=?vhost=test-play.live.com, duration=-1ms
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] connected stream, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-play.live.com, port=1935, app=test, stream=lmt, param=?vhost=test-play.live.com, args=null
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] source url=test-play.live.com/test/lmt, ip=192.168.1.143, cache=1, is_edge=1, source_id=/h027yo79
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] ignore disabled exec for vhost=test-play.live.com
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] dispatch cached gop success. count=0, duration=-1
[2021-09-10 15:12:54.651][Trace][88004][ynn608y4] create consumer, active=1, queue_size=0.00, jitter=30000000
[2021-09-10 15:12:54.652][Trace][88004][ynn608y4] set fd=13, SO_SNDBUF=146988=>87500, buffer=350ms
[2021-09-10 15:12:54.652][Trace][88004][ynn608y4] start play smi=0ms, mw_sleep=350, mw_msgs=8, realtime=0, tcp_nodelay=0
[2021-09-10 15:12:54.652][Trace][88004][ynn608y4] update source_id=7kb65c8q/h027yo79
[2021-09-10 15:12:54.652][Trace][88004][60609ab5] RTMP client ip=192.168.1.143:63844, fd=15
[2021-09-10 15:12:54.654][Trace][88004][7kb65c8q] complex handshake success.
[2021-09-10 15:12:54.654][Trace][88004][7kb65c8q] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] complex handshake success
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] connect app, tcUrl=rtmp://test-push.live.com/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-push.live.com, port=1935, app=test, args=(obj)
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] edge-srs ip=192.168.1.143, version=5.0.11, pid=88004, id=0
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:54.654][Trace][88004][7kb65c8q] connected, version=5.0.11.0, ip=192.168.1.143, pid=88004, id=0, dsu=1
[2021-09-10 15:12:54.654][Trace][88004][7kb65c8q] edge-pull publish url rtmp://192.168.1.143:1935/test/lmt?&vhost=test-push.live.com, stream=lmt as lmt?
[2021-09-10 15:12:54.654][Trace][88004][7kb65c8q] edge change from 100 to state 101 (pull).
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] client identified, type=rtmp-play, vhost=test-push.live.com, app=test, stream=lmt, param=?, duration=-1ms
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] connected stream, tcUrl=rtmp://test-push.live.com/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-push.live.com, port=1935, app=test, stream=lmt, param=?, args=(obj)
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] source url=test-push.live.com/test/lmt, ip=192.168.1.143, cache=0, is_edge=0, source_id=2d21q950/e84u8820
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] set fd=15 TCP_NODELAY 0=>4
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] dispatch cached gop success. count=0, duration=-1
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] create consumer, active=1, queue_size=0.00, jitter=10000000
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] set fd=15, SO_SNDBUF=146988=>25000, buffer=100ms
[2021-09-10 15:12:54.654][Trace][88004][60609ab5] start play smi=0ms, mw_sleep=100, mw_msgs=0, realtime=1, tcp_nodelay=1
[2021-09-10 15:12:54.655][Trace][88004][7kb65c8q] got metadata, width=960, height=720, vcodec=7, acodec=10
[2021-09-10 15:12:54.655][Trace][88004][7kb65c8q] 4B audio sh, codec(10, profile=LC, 2channels, 0kbps, 22050HZ), flv(16bits, 2channels, 22050HZ)
[2021-09-10 15:12:54.655][Trace][88004][7kb65c8q] 51B video sh,  codec(7, profile=High, level=3.1, 960x720, 0kbps, 0.0fps, 0.0s)
[2021-09-10 15:12:56.395][Warn][88004][7kb65c8q][4] origin disconnected, retry, error code=1007 : recv message : recv interlaced message : read basic header : basic header requires 1 bytes : read bytes : read
thread [88004][7kb65c8q]: ingest() [/Users/retamia/Workspace/live/srs/trunk/src/app/srs_app_edge.cpp:586][errno=4]
thread [88004][7kb65c8q]: recv_message() [/Users/retamia/Workspace/live/srs/trunk/src/protocol/srs_rtmp_stack.cpp:372][errno=4]
thread [88004][7kb65c8q]: recv_interlaced_message() [/Users/retamia/Workspace/live/srs/trunk/src/protocol/srs_rtmp_stack.cpp:859][errno=4]
thread [88004][7kb65c8q]: read_basic_header() [/Users/retamia/Workspace/live/srs/trunk/src/protocol/srs_rtmp_stack.cpp:954][errno=4]
thread [88004][7kb65c8q]: grow() [/Users/retamia/Workspace/live/srs/trunk/src/protocol/srs_protocol_stream.cpp:162][errno=4]
thread [88004][7kb65c8q]: read() [/Users/retamia/Workspace/live/srs/trunk/src/protocol/srs_service_st.cpp:522][errno=4]
[2021-09-10 15:12:56.453][Trace][88004][3p746922] RTMP client ip=192.168.1.143:63845, fd=16
[2021-09-10 15:12:56.453][Trace][88004][3p746922] simple handshake success.
[2021-09-10 15:12:56.453][Trace][88004][3p746922] connect app, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=192.168.1.143, port=1935, app=test, args=null
[2021-09-10 15:12:56.453][Trace][88004][3p746922] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:56.454][Trace][88004][3p746922] ignore AMF0/AMF3 command message.
[2021-09-10 15:12:56.454][Trace][88004][3p746922] client identified, type=rtmp-play, vhost=test-play.live.com, app=test, stream=lmt, param=?vhost=test-play.live.com, duration=-1ms
[2021-09-10 15:12:56.454][Trace][88004][3p746922] connected stream, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-play.live.com, port=1935, app=test, stream=lmt, param=?vhost=test-play.live.com, args=null
[2021-09-10 15:12:56.454][Trace][88004][3p746922] source url=test-play.live.com/test/lmt, ip=192.168.1.143, cache=1, is_edge=1, source_id=7kb65c8q/h027yo79
[2021-09-10 15:12:56.454][Trace][88004][3p746922] dispatch cached gop success. count=88, duration=1761
[2021-09-10 15:12:56.454][Trace][88004][3p746922] create consumer, active=1, queue_size=0.00, jitter=30000000
[2021-09-10 15:12:56.454][Trace][88004][3p746922] set fd=16, SO_SNDBUF=146988=>87500, buffer=350ms
[2021-09-10 15:12:56.454][Trace][88004][3p746922] start play smi=0ms, mw_sleep=350, mw_msgs=8, realtime=0, tcp_nodelay=0
[2021-09-10 15:12:56.463][Trace][88004][50iq68w7] RTMP client ip=192.168.1.143:63846, fd=17
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] simple handshake success.
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] connect app, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=192.168.1.143, port=1935, app=test, args=null
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] protocol in.buffer=0, in.ack=0, out.ack=0, in.chunk=128, out.chunk=128
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] client identified, type=fmle-publish, vhost=test-push.live.com, app=test, stream=lmt_trans, param=?vhost=test-push.live.com, duration=0ms
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] connected stream, tcUrl=rtmp://192.168.1.143:1935/test, pageUrl=, swfUrl=, schema=rtmp, vhost=test-push.live.com, port=1935, app=test, stream=lmt_trans, param=?vhost=test-push.live.com, args=null
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] source url=test-push.live.com/test/lmt_trans, ip=192.168.1.143, cache=0, is_edge=0, source_id=/6md242b4
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] ignore disabled exec for vhost=test-push.live.com
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] set fd=17 TCP_NODELAY 0=>4
[2021-09-10 15:12:56.464][Trace][88004][50iq68w7] start publish mr=0/350, p1stpt=20000, pnt=5000, tcp_nodelay=1
[2021-09-10 15:12:56.972][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=1,0, timer=58,0,0, clock=0,15,26,3,0,0,0,0,0
[2021-09-10 15:12:59.395][Trace][88004][ynn608y4] cleanup when unpublish
[2021-09-10 15:12:59.395][Trace][88004][ynn608y4] edge change from 101 to 300 then 0 (init).
[2021-09-10 15:12:59.395][Trace][88004][ynn608y4] TCP: before dispose resource(RtmpConn)(0x7fd1e470b9a0), conns=5, zombies=0, ign=0, inz=0, ind=0
[2021-09-10 15:12:59.395][Warn][88004][ynn608y4][4] client disconnect peer. ret=1009
[2021-09-10 15:12:59.395][Trace][88004][280232j3] TCP: clear zombies=1 resources, conns=5, removing=0, unsubs=0
[2021-09-10 15:12:59.395][Trace][88004][ynn608y4] TCP: disposing #0 resource(RtmpConn)(0x7fd1e470b9a0), conns=5, disposing=1, zombies=0
[2021-09-10 15:12:59.395][Trace][88004][60609ab5] TCP: before dispose resource(RtmpConn)(0x7fd1e4718b50), conns=4, zombies=0, ign=0, inz=0, ind=0
[2021-09-10 15:12:59.395][Warn][88004][60609ab5][32] client disconnect peer. ret=1009
[2021-09-10 15:12:59.395][Trace][88004][280232j3] TCP: clear zombies=1 resources, conns=4, removing=0, unsubs=0
[2021-09-10 15:12:59.395][Trace][88004][60609ab5] TCP: disposing #0 resource(RtmpConn)(0x7fd1e4718b50), conns=4, disposing=1, zombies=0
[2021-09-10 15:13:01.972][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=11,2, timer=59,0,0, clock=0,19,25,1,0,0,0,0,0, free=1, objs=(pkt:0,raw:0,fua:0,msg:80,oth:0,buf:0)
[2021-09-10 15:13:06.974][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=11,2, timer=59,0,0, clock=0,19,25,1,0,0,0,0,0, free=1, objs=(pkt:0,raw:0,fua:0,msg:80,oth:0,buf:0)
[2021-09-10 15:13:11.975][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=1,0, timer=59,0,0, clock=0,24,22,1,0,0,0,0,0, objs=(pkt:0,raw:0,fua:0,msg:51,oth:0,buf:0)
[2021-09-10 15:13:16.465][Trace][88004][50iq68w7] cleanup when unpublish
[2021-09-10 15:13:16.465][Trace][88004][50iq68w7] TCP: before dispose resource(RtmpConn)(0x7fd1e5b210b0), conns=3, zombies=0, ign=0, inz=0, ind=0
[2021-09-10 15:13:16.465][Error][88004][50iq68w7][4] serve error code=1011 : service cycle : rtmp: stream service : rtmp: publish timeout 20000ms, nb_msgs=0
thread [88004][50iq68w7]: do_cycle() [/Users/retamia/Workspace/live/srs/trunk/src/app/srs_app_rtmp_conn.cpp:217][errno=4]
thread [88004][50iq68w7]: service_cycle() [/Users/retamia/Workspace/live/srs/trunk/src/app/srs_app_rtmp_conn.cpp:414][errno=4]
thread [88004][50iq68w7]: do_publishing() [/Users/retamia/Workspace/live/srs/trunk/src/app/srs_app_rtmp_conn.cpp:916][errno=101](Interrupted system call)
[2021-09-10 15:13:16.465][Trace][88004][280232j3] TCP: clear zombies=1 resources, conns=3, removing=0, unsubs=0
[2021-09-10 15:13:16.465][Trace][88004][50iq68w7] TCP: disposing #0 resource(RtmpConn)(0x7fd1e5b210b0), conns=3, disposing=1, zombies=0
[2021-09-10 15:13:16.938][Trace][88004][2d21q950] <- CPB time=19997459, okbps=1,0,0, ikbps=368,0,0, mr=0/350, p1stpt=20000, pnt=5000
[2021-09-10 15:13:16.975][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=1,0, timer=59,0,0, clock=0,24,22,1,0,0,0,0,0, objs=(pkt:0,raw:0,fua:0,msg:51,oth:0,buf:0)
[2021-09-10 15:13:21.975][Trace][88004][04708784] Hybrid cpu=0.00%,0MB, cid=2,1, timer=60,0,0, clock=0,21,24,1,0,0,0,0,0, free=1, objs=(pkt:0,raw:0,fua:0,msg:51,oth:0,buf:0)
[2021-09-10 15:13:26.502][Trace][88004][3p746922] -> PLA time=0, msgs=0, okbps=21,21,0, ikbps=0,0,0, mw=350/8
[2021-09-10 15:13:26.852][Trace][88004][3p746922] -> PLA time=30049702, msgs=0, okbps=21,21,0, ikbps=0,0,0, mw=350/8
[2021-09-10 15:13:26.852][Trace][88004][3p746922] TCP: before dispose resource(RtmpConn)(0x7fd1e5e146e0), conns=2, zombies=0, ign=0, inz=0, ind=0
  3. The configuration of SRS is as follows: 
    
listen              1935;
max_connections     1024;
daemon              off;
srs_log_tank        console;

http_server { enabled on; listen 8080; dir ./objs/nginx/html; }

http_api { enabled on; listen 1985; }

vhost test-push.live.com {

tcp_nodelay     on;
min_latency     on;

play {
    reduce_sequence_header on;
    atc on;
    atc_auto on;
    gop_cache       off;
    queue_length    10;
    mw_latency      100;

}

publish { mr off; }

cluster {
    mode       local;
    coworkers  192.168.1.143:1935;
}

}

vhost test-play.live.com {

cluster {
    mode       remote;
    origin     192.168.1.143:1935;
    vhost      test-push.live.com;
}

http_remux {
    enabled     on;
    mount       [vhost]/[app]/[stream].flv;
    hstrs       on;
}

}


**Replay**

**1. Push the stream in the terminal using ffmpeg -re -stream_loop -1 -i ~/Documents/live_test.mp4 -c copy -f flv rtmp://test-push.live.com/test/lmt**

**2. Execute the following command using Go's exec.Command**
```shell
ffprobe -hide_banner -rw_timeout 10000000 -of json -show_entries 'format:stream' -i 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com'

3. Then, execute the following command using exec.Command and start a goroutine to read data from StdoutPipe and StderrPipe

ffmpeg -hide_banner -rw_timeout 10000000 -i 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com' -c:a copy -c:v libx264 -g 60 -preset veryfast -threads 8 -f flv -y 'rtmp://192.168.1.143:1935/test/lmt_trans?vhost=test-push.live.com'

4. The streaming gets stuck, and the SRS log shows "publish timeout", which can be reproduced with a certain probability. If it cannot be reproduced, you need to close the streaming and go process, and then start again from step 1.

Expected Behavior (Expect)

Able to stream normally.

TRANS_BY_GPT3

retamia commented 3 years ago

By the way, there is another issue here. If the vhost field is configured in the test-play.live.com vhost, and the rtmp address also includes the vhost parameter, it will cause the vhost field in the configuration to be ineffective. This part needs to be modified in the code. If the vhost field is configured in the vhost, when generating the srs_generate_rtmp_url, the vhost in the query should be removed. Otherwise, the generated URL will still be test-play.live.com, but according to the configuration, it should be test-push.live.com.

TRANS_BY_GPT3

retamia commented 3 years ago

Test code for Go

package main

import (
  "bufio"
  "bytes"
  "errors"
  "io"
  "os/exec"
  "syscall"
)

func processCmdPipeOut(pstdout *[]byte, pout io.ReadCloser, endpipe chan bool) {
  r := bufio.NewReader(pout)
  for {
    //data, err := r.ReadBytes('\r')
    data := []byte{}
    var c byte
    var e error
    for {
      c, e = r.ReadByte()
      if e != nil {
        break
      }
      data = append(data, c)
      if c == '\r' || c == '\n' {
        break
      }
    }
    if len(data) > 0 {
      print(string(data))
      *pstdout = append(*pstdout, data...)
    }
    if e != nil {
      break
    }
  }
  endpipe <- true
}

func RunCmdWithCallback(cmdline string) ([]byte, error) {
  var stdout, stderr []byte
  var err error = nil
  cmd := exec.Command("/bin/sh", "-c", cmdline)
  cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}

  pout, err0 := cmd.StdoutPipe()
  perr, err1 := cmd.StderrPipe()
  if err0 != nil || err1 != nil {
    return nil, errors.New("pipe error")
  }
  chnum := 2
  endpipe := make(chan bool, chnum)
  defer close(endpipe)
  cmd.Start()

  // read data from StdoutPipe
  go processCmdPipeOut(&stdout, pout, endpipe)
  // read data from StderrPipe
  go processCmdPipeOut(&stderr, perr, endpipe)

  err = cmd.Wait()
  for i := 0; i < chnum; i++ {
    <-endpipe
  }
  return append(stdout, stderr...), err
}

func RunCmd2(cmdline string) ([]byte, []byte, error) {
  cmd := exec.Command("/bin/sh", "-c", cmdline)
  cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
  wo := bytes.NewBuffer(nil)
  we := bytes.NewBuffer(nil)
  cmd.Stdout = wo
  cmd.Stderr = we
  err := cmd.Run()

  stdout := wo.Bytes()
  stderr := we.Bytes()
  return stdout, stderr, err
}

func main() {

  ffprobeCmd := "ffprobe -hide_banner -rw_timeout 10000000 -of json -show_entries 'format:stream' -i 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com'"
  sout, serr, _ := RunCmd2(ffprobeCmd)
  println(string(sout))
  println(string(serr))

  ffmpegCmd := "ffmpeg -hide_banner -rw_timeout 10000000 -i 'rtmp://192.168.1.143:1935/test/lmt?vhost=test-play.live.com' -c:a copy -c:v libx264 -g 60 -preset veryfast -threads 8 -f flv -y 'rtmp://192.168.1.143:1935/test/lmt_trans?vhost=test-push.live.com'"
  RunCmdWithCallback(ffmpegCmd)
}

TRANS_BY_GPT3

winlinvip commented 3 years ago

After taking a look, I didn't understand why the publish timeout occurred. Can you find the minimal reproducible path? For example, does this issue exist with a single SRS?

TRANS_BY_GPT3

retamia commented 3 years ago

I looked at it but didn't understand why there is a publish timeout. Can you find the minimum reproducible path? For example, does this problem occur with a single SRS?

I haven't found a better way to reproduce it yet. I suspect it may be a problem with the code in the Go coroutine that retrieves the StdoutPipe data, causing the log call in ffmpeg to block. I fixed it by modifying the Go code. However, it's also strange that this issue only occurs with RTMP, and there is no such phenomenon when using HTTP-FLV to pull the stream.

TRANS_BY_GPT3

retamia commented 2 years ago

Temporary solution found. It is the same phenomenon as this issue.

In the GO code, after ffprobe, ffmpeg is immediately called. When ffprobe's connection is disconnected, the edge has not yet completed the logic of on_all_client_stop, causing ffmpeg's connection to come up. The SRS edge status is still "init", which will cause ffmpeg to hang.

TRANS_BY_GPT3

winlinvip commented 2 years ago

Please do not comment randomly in the Issue, and do not go off-topic. Each Issue should only address one problem, otherwise it will be deleted directly. Before submitting an Issue, be sure to read FAQ #2716.

TRANS_BY_GPT3

winlinvip commented 2 years ago

Temporary solution found. It is the same phenomenon as this issue. After ffprobe in the GO code, ffmpeg is immediately called. When ffprobe's connection is disconnected, the edge has not yet completed the logic of on_all_client_stop, causing ffmpeg's connection to come up. The srs edge status is still init, which will cause ffmpeg to hang.

First of all, kudos to you. The cause of the issue has been identified. It seems that it would be better to return an error in this situation. When in an intermediate state, returning an error to the client can prevent it from getting stuck.

TRANS_BY_GPT3

jinleileiking commented 2 years ago

Please do not comment randomly in the Issue, do not digress. Each Issue should only address one problem, otherwise it will be deleted directly. Before raising an Issue, be sure to read FAQ #2716.

GitHub has a feature to collapse comments.

TRANS_BY_GPT3

winlinvip commented 6 months ago

To fix the incorrect state of edge, we should refine the state machine of source, changing between publishing and unpublishing like DB transaction.