Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
retamia opened this issue Sep 10, 2021 · 9 comments
Open

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

retamia opened this issue Sep 10, 2021 · 9 comments
Assignees
Labels
Bug It might be a bug. Codec HEVC, FFmpeg for ingesting, trascoding or codec. Enhancement Improvement or enhancement. TransByAI Translated by AI/GPT.
Milestone

Comments

@retamia
Copy link
Contributor

retamia commented Sep 10, 2021

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
  1. 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

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

This comment has been minimized.

@retamia
Copy link
Contributor Author

retamia commented Sep 10, 2021

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
Copy link
Member

winlinvip commented Sep 11, 2021

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

@winlinvip winlinvip self-assigned this Sep 11, 2021
@winlinvip winlinvip added the Codec HEVC, FFmpeg for ingesting, trascoding or codec. label Sep 11, 2021
@retamia
Copy link
Contributor Author

retamia commented Sep 16, 2021

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
Copy link
Contributor Author

retamia commented Nov 17, 2021

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

@retamia retamia closed this as completed Nov 17, 2021
@ossrs ossrs deleted a comment from TanessaW Dec 21, 2021
@ossrs ossrs deleted a comment from TanessaW Dec 21, 2021
@ossrs ossrs deleted a comment from wangjunjx8868 Dec 21, 2021
@ossrs ossrs locked as too heated and limited conversation to collaborators Dec 21, 2021
@winlinvip
Copy link
Member

winlinvip commented Dec 21, 2021

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
Copy link
Member

winlinvip commented Dec 21, 2021

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

@winlinvip winlinvip reopened this Dec 21, 2021
@ossrs ossrs unlocked this conversation Dec 21, 2021
@winlinvip winlinvip changed the title 在Go里面执行FFprobe FFmpeg,从边缘地址拉流再推流会导致推流超时。 Edge: FFprobe FFmpeg,从边缘地址拉流再推流可能会卡住 Dec 21, 2021
@winlinvip winlinvip added Bug It might be a bug. Enhancement Improvement or enhancement. labels Dec 21, 2021
@winlinvip winlinvip added this to the 5.0 milestone Dec 21, 2021
@winlinvip winlinvip changed the title Edge: FFprobe FFmpeg,从边缘地址拉流再推流可能会卡住 Edge: FFprobe从边缘地址拉流再推流,可能会卡住 Dec 21, 2021
@jinleileiking

This comment has been minimized.

@winlinvip winlinvip reopened this Jan 2, 2023
@winlinvip winlinvip changed the title Edge: FFprobe从边缘地址拉流再推流,可能会卡住 Edge: Stuck in edge init state when play and publish simultaneously. FFprobe从边缘地址拉流再推流,可能会卡住 Jan 2, 2023
@winlinvip winlinvip modified the milestones: 5.0, 6.0 Jan 2, 2023
@winlinvip winlinvip changed the title Edge: Stuck in edge init state when play and publish simultaneously. FFprobe从边缘地址拉流再推流,可能会卡住 Edge: Stuck in edge init state when play and publish simultaneously. FFprobe may get stuck when pulling stream from edge address and then pushing it. Jul 28, 2023
@winlinvip winlinvip added the TransByAI Translated by AI/GPT. label Jul 28, 2023
@winlinvip winlinvip changed the title Edge: Stuck in edge init state when play and publish simultaneously. FFprobe may get stuck when pulling stream from edge address and then pushing it. Edge: FFprobe may get stuck when pulling stream from edge. Apr 26, 2024
@winlinvip
Copy link
Member

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug It might be a bug. Codec HEVC, FFmpeg for ingesting, trascoding or codec. Enhancement Improvement or enhancement. TransByAI Translated by AI/GPT.
Projects
None yet
Development

No branches or pull requests

3 participants