search

sergey-dryabzhinsky / nginx-rtmp-module

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

Infinite loop during relay close #201

Open rkearsley opened 7 years ago

rkearsley commented 7 years ago

Hello Thanks for continuing with this project, its's much appreciated!

I've discovered this problem where the worker process will freeze at 100% cpu

From gdb bt of stalled worker:

0x00000000004ac316 in ngx_rtmp_relay_close (s=s@entry=0x1cdc3c0) at ../../../../nginx-rtmp-module/ngx_rtmp_relay_module.c:1572 1572 for (cctx = &ctx->publish->play; cctx; cctx = &(cctx)->next, ++n); (gdb) bt

0 0x00000000004ac316 in ngx_rtmp_relay_close (s=s@entry=0x1cdc3c0) at ../../../../nginx-rtmp-module/ngx_rtmp_relay_module.c:1572

1 0x00000000004ac5ad in ngx_rtmp_relay_close_stream (s=0x1cdc3c0, v=0x723750 ) at ../../../../nginx-rtmp-module/ngx_rtmp_relay_module.c:1626

2 0x00000000004af185 in ngx_rtmp_exec_close_stream (s=0x1cdc3c0, v=0x723750 ) at ../../../../nginx-rtmp-module/ngx_rtmp_exec_module.c:1306

3 0x00000000004b2552 in ngx_rtmp_notify_close_stream (s=0x1cdc3c0, v=0x723750 ) at ../../../../nginx-rtmp-module/ngx_rtmp_notify_module.c:1861

4 0x00000000004b7ea5 in ngx_rtmp_hls_close_stream (s=0x1cdc3c0, v=0x723750 ) at ../../../../nginx-rtmp-module/hls/ngx_rtmp_hls_module.c:1628

5 0x00000000004bbaa6 in ngx_rtmp_dash_close_stream (s=0x1cdc3c0, v=0x723750 ) at ../../../../nginx-rtmp-module/dash/ngx_rtmp_dash_module.c:1041

6 0x000000000049afee in ngx_rtmp_cmd_close_stream_init (s=0x1cdc3c0, h=, in=) at ../../../../nginx-rtmp-module/ngx_rtmp_cmd_module.c:416

7 0x0000000000499df6 in ngx_rtmp_amf_message_handler (s=0x1cdc3c0, h=0x1ccb510, in=0x1ccc410) at ../../../../nginx-rtmp-module/ngx_rtmp_receive.c:437

8 0x000000000049553d in ngx_rtmp_receive_message (s=s@entry=0x1cdc3c0, h=h@entry=0x1ccb510, in=in@entry=0x1ccc410) at ../../../../nginx-rtmp-module/ngx_rtmp_handler.c:803

9 0x0000000000495d26 in ngx_rtmp_recv (rev=) at ../../../../nginx-rtmp-module/ngx_rtmp_handler.c:464

10 0x0000000000439c10 in ngx_epoll_process_events (cycle=0x1a0cf70, timer=, flags=) at src/event/modules/ngx_epoll_module.c:822

11 0x000000000043027a in ngx_process_events_and_timers (cycle=cycle@entry=0x1a0cf70) at src/event/ngx_event.c:242

12 0x00000000004377c2 in ngx_worker_process_cycle (cycle=cycle@entry=0x1a0cf70, data=data@entry=0x0) at src/os/unix/ngx_process_cycle.c:753

13 0x00000000004360d1 in ngx_spawn_process (cycle=cycle@entry=0x1a0cf70, proc=0x43771f , data=0x0, name=0x4c60bf "worker process", respawn=respawn@entry=0)

at src/os/unix/ngx_process.c:198

14 0x00000000004387d0 in ngx_reap_children (cycle=0x1a0cf70) at src/os/unix/ngx_process_cycle.c:621

15 ngx_master_process_cycle (cycle=cycle@entry=0x1a0cf70) at src/os/unix/ngx_process_cycle.c:174

16 0x0000000000412ce1 in main (argc=, argv=) at src/core/nginx.c:367

From debug log at time of event:

2016/11/28 16:15:28 [debug] 55481#0: 399 recv: fd:23 146 of 146 2016/11/28 16:15:28 [debug] 55481#0: 399 RTMP bheader fmt=1 csid=8 2016/11/28 16:15:28 [debug] 55481#0: 399 RTMP mheader fmt=1 amf_cmd (20) time=5585+9121 mlen=164 len=0 msid=1 2016/11/28 16:15:28 [debug] 55481#0: 399 reusing formerly read data: 10 2016/11/28 16:15:28 [debug] 55481#0: 399 RTMP bheader fmt=3 csid=8 2016/11/28 16:15:28 [debug] 55481#0: 399 RTMP mheader fmt=3 amf_cmd (20) time=5585+9121 mlen=164 len=128 msid=1 2016/11/28 16:15:28 [debug] 55481#0: 399 recv: fd:23 27 of 136 2016/11/28 16:15:28 [debug] 55481#0: 399 RTMP recv amf_cmd (20) csid=8 timestamp=14706 mlen=164 msid=1 nbufs=2 2016/11/28 16:15:28 [debug] 55481#0: 399 nhandlers: 1 2016/11/28 16:15:28 [debug] 55481#0: 399 calling handler 0 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 02 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 05 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (5) 70 6C 61 79 32 'play2' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF func 'play2' passed to handler 0/1 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 00 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (8) 00 00 00 00 00 00 00 00 '????????' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 05 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 03 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 03 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (3) 6C 65 6E 'len' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 00 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (8) BF F0 00 00 00 00 00 00 '????????' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 06 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (6) 6F 66 66 73 65 74 'offset' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 00 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (8) 40 B2 7A E2 0C 49 BA 5E '@?z??I?^' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 0A '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (10) 74 72 61 6E 73 69 74 69 6F 6E 'transition' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 02 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 06 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (6) XX XX XX XX XX XX '??????' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 0A '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (10) 73 74 72 65 61 6D 4E 61 6D 65 'streamName' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 02 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 2B '?+' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (43) removed 'removed' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 05 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (5) 73 74 61 72 74 'start' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 00 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (8) BF F0 00 00 00 00 00 00 '????????' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 0D '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (10) 6F 6C 64 53 74 72 65 61 6D 4E 'oldStreamN' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (3) XX XX XX '???' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 05 '?' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (2) 00 00 '??' 2016/11/28 16:15:28 [debug] 55481#0: 399 AMF read (1) 09 '?' 2016/11/28 16:15:28 [info] 55481#0: 399 play2: name='removed' args='' start=-1, client: 1.2.3.4, server: 4.5.6.7:1935 2016/11/28 16:15:28 [info] 55481#0: 399 notify: play_done '127.0.0.1:1980/rtmp-auth', client: 1.2.3.4, server: 4.5.6.7:1935 2016/11/28 16:15:28 [debug] 55481#0: posix_memalign: 000000000150CF80:4096 @16 2016/11/28 16:15:28 [debug] 55481#0: stream socket 24 2016/11/28 16:15:28 [debug] 55481#0: epoll add connection: fd:24 ev:80002005 2016/11/28 16:15:28 [debug] 55481#0: connect to 127.0.0.1, fd:24 #415 2016/11/28 16:15:28 [debug] 55481#0: 399 notify: create request: begin 2016/11/28 16:15:28 [debug] 55481#0: 399 notify: create request: netcall format session 2016/11/28 16:15:28 [debug] 55481#0: 399 notify: create request: swap formated args 2016/11/28 16:15:28 [debug] 55481#0: 399 notify: create request: netcall format request 2016/11/28 16:15:28 [debug] 55481#0: *399 relay: play disconnect app='' name='0c5caa30217ed1ef605f23290f6a3727'

Any help much appreciated!

Thanks Richard

sergey-dryabzhinsky commented 7 years ago

Can you check code from latest dev branch?

rkearsley commented 7 years ago

Hi I'm struggling to reproduce the error reliably, it is very rare. Is the code in dev branch supposed to fix this loop, or just provide more debug log info?

Thanks

notmark commented 7 years ago

+1

ethernetweb commented 7 years ago

Could this be related to issue #212 also?