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

Problem with new Nginx version 1.10.0 #127

Open sceptic30 opened 8 years ago

sceptic30 commented 8 years ago

I think it seems to be a problem with the new stable version of nginx-1.10.0. Here is the error.log

2016/05/03 08:02:18 [info] 22282#0: 5 client connected '192.168.10.2' 2016/05/03 08:02:18 [info] 22282#0: 5 connect: app='live' args='' flashver='WIN 21,0,0,213' swf_url='http://192.168.10.1/RtmpPublisher.swf' tc_url='rtmp://192.168.10.1/live' page_url='http://192.168.10.1/publisher.php' acodecs=3575 vcodecs=252 object_encoding=3, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/03 08:02:18 [info] 22282#0: 5 createStream, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/03 08:02:18 [info] 22282#0: 5 publish: name='Nick' args='' type=append silent=0, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/03 08:02:19 [notice] 22281#0: signal 17 (SIGCHLD) received 2016/05/03 08:02:19 [notice] 22281#0: signal 17 (SIGCHLD) received 2016/05/03 08:02:19 [alert] 22281#0: worker process 22282 exited on signal 11 (core dumped) 2016/05/03 08:02:19 [alert] 22281#0: worker process 22282 exited on signal 11 (core dumped) 2016/05/03 08:02:19 [alert] 22281#0: worker process 22282 exited on signal 11 (core dumped) 2016/05/03 08:02:19 [notice] 22281#0: start worker process 22294 2016/05/03 08:02:19 [notice] 22281#0: start worker process 22294 2016/05/03 08:02:19 [notice] 22281#0: signal 29 (SIGIO) received 2016/05/03 08:02:19 [notice] 22281#0: signal 29 (SIGIO) received

All configs remained the same, only compiled executable changed. Compilation finished normally, but as soon as i try to broadcast the above message appeared in the log, and of course no video data submission.

ArhiChief commented 8 years ago

Had same log with previous versions of nginx when using more than one worker in nginx config. There is still a problem with multiworker in nginx-rtmp-module.

RocFang commented 8 years ago

There are lots of problem in multi worker situation. So unless you can dive into the code, never try multi worker configuration in production env.

sceptic30 commented 8 years ago

@RocFang @ArhiChief @sergey-dryabzhinsky I receive the same error even on 1 worker. Very weird

misiek08 commented 8 years ago

Are you able to build module with debug flag and post backtrace with debug log here? Include config too. I have a theory about that kind of problems but not enough data for now.

I'm not updating my servers since 1.9.7.4 because it's stable and currently openresty stopped at this version and I need Lua.

sceptic30 commented 8 years ago

@misiek08 this is the first time i encounter this sort of error, so im noob. Can you please tell me how exactly i will do that?i configured like this: ./configure --prefix=/opt/nginx --with-debug --add-module=/build/nginx-rtmp-module --with-http_geoip_module --with-http_v2_module --with-http_realip_module --with-http_gzip_static_module --with-http_stub_status_module --with-http_ssl_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_gunzip_module --with-http_random_index_module --with-http_secure_link_module --with-http_auth_request_module --with-mail --with-mail_ssl_module --with-file-aio --with-ipv6 --with-stream What i should do next? Im on Centos 6.7

misiek08 commented 8 years ago

Ok, you have required flag in configure. You need to add debug messages into log (http://nginx.org/en/docs/debugging_log.html). It should be enough for now.

Dumping backtrace requires running under debugger, so we will stay away from this for now.

sceptic30 commented 8 years ago

@misiek08 here you go. (very sorry for the huge post, wish there was a spoiler function like on some forums). nginx.conf

user  webmaster;
worker_processes  4;
error_log  logs/error.log;
error_log  logs/error.log notice;
error_log  logs/debug.log debug;
error_log  logs/error.log info;
pid        logs/nginx.pid;
events {
worker_connections  1024;
}
http {
    server_tokens off;
    rewrite_log on;
    fastcgi_intercept_errors on;
    sendfile    off;
    tcp_nopush  on;
    tcp_nodelay on;
    keepalive_timeout  30;
    types_hash_bucket_size 64;
    client_max_body_size 100m;
    server_names_hash_bucket_size 128;
    set_real_ip_from  192.168.10.1;
    real_ip_header    X-Forwarded-For;
    real_ip_recursive on;
    include     mime.types;
    default_type  application/octet-stream;
    index  index.php index.html index.htm;
    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';
    #access_log  logs/access.log  main;
include domain.conf;
}
include video.conf;

video.conf

rtmp_auto_push on;
rtmp_auto_push_reconnect 5s;
rtmp_socket_dir /tmp/rtmp-sockets;
rtmp {
    server {
        listen 1935;
        allow publish 192.168.10.1;
        allow play all;
        publish_time_fix off;
        chunk_size 4096;
        meta copy;
        sync 10ms;
        play_restart on;
        publish_notify on;
        buflen 0s;
            application live {
            live on;
            interleave on;
            record manual;
            record_path /opt/nginx/video_recordings;
            record_unique on;
            exec /opt/ffmpeg/bin/ffmpeg -threads 0 -i rtmp://192.168.10.1/live/$name -vcodec copy -movflags +faststart -preset ultrafast -tune zerolatency -g 10 -acodec libfdk_aac -ar 44100 -ac 2 -f flv rtmp://192.168.10.1/cam/$name -vcodec libx264 -profile:v baseline -level 3.0 -s 640x320 -movflags +faststart -preset ultrafast -tune zerolatency -g 10 -pix_fmt yuv420p -acodec libfdk_aac -ar 44100 -ac 1 -f flv rtmp://192.168.10.1/mobile/$name;
        }
        application cam {
        live on;
        }
        application mobile {
            live on;
            hls on;
            hls_nested on;
            hls_path /tmp/HLS/mobile;
            hls_fragment 3s;
            hls_playlist_length 4s;
        }
    }
}

I placed the debug log in google drive, was too big to fit in a post https://drive.google.com/open?id=0ByzeJblC78nqcGd5dEEycS1sb0E

chriswiggins commented 8 years ago

@sceptic30 your worker_processes is 4 at the very top of your config. This is multiple workers. Change this to 1 and see if the problem still exists?

On 5/05/2016, at 6:49 AM, sceptic30 notifications@github.com<mailto:notifications@github.com> wrote:

@misiek08https://github.com/misiek08 here you go. (very sorry for the huge post, wish there was a spoiler function like on some forums). nginx.conf

user webmaster; worker_processes 4; error_log logs/error.log; error_log logs/error.log notice; error_log logs/debug.log debug; error_log logs/error.log info; pid logs/nginx.pid; events { worker_connections 1024; } http { server_tokens off; rewrite_log on; fastcgi_intercept_errors on; sendfile off; tcp_nopush on; tcp_nodelay on; keepalive_timeout 30; types_hash_bucket_size 64; client_max_body_size 100m; server_names_hash_bucket_size 128; set_real_ip_from 192.168.10.1; real_ip_header X-Forwarded-For; real_ip_recursive on; include mime.types; default_type application/octet-stream; index index.php index.html index.htm; log_format main '$remote_addr - $remote_user [$time_local] "$request" ' '$status $body_bytes_sent "$http_referer" ' '"$http_user_agent" "$http_x_forwarded_for"';

access_log logs/access.log main;

include domain.conf; } include video.conf;

video.conf

rtmp_auto_push on; rtmp_auto_push_reconnect 5s; rtmp_socket_dir /tmp/rtmp-sockets; rtmp { server { listen 1935; allow publish 192.168.10.1; allow play all; publish_time_fix off; chunk_size 4096; meta copy; sync 10ms; play_restart on; publish_notify on; buflen 0s; application live { live on; interleave on; record manual; record_path /opt/nginx/video_recordings; record_unique on; exec /opt/ffmpeg/bin/ffmpeg -threads 0 -i rtmp://192.168.10.1/live/$name -vcodec copy -movflags +faststart -preset ultrafast -tune zerolatency -g 10 -acodec libfdk_aac -ar 44100 -ac 2 -f flv rtmp://192.168.10.1/cam/$name -vcodec libx264 -profile:v baseline -level 3.0 -s 640x320 -movflags +faststart -preset ultrafast -tune zerolatency -g 10 -pix_fmt yuv420p -acodec libfdk_aac -ar 44100 -ac 1 -f flv rtmp://192.168.10.1/mobile/$name; } application cam { live on; } application mobile { live on; hls on; hls_nested on; hls_path /tmp/HLS/mobile; hls_fragment 3s; hls_playlist_length 4s; } } }

and lastly, the HUGE debug log

2016/05/04 21:15:59 [debug] 9503#0: bind() 0.0.0.0:81 #8 2016/05/04 21:15:59 [debug] 9503#0: bind() 0.0.0.0:1935 #8 2016/05/04 21:15:59 [debug] 9503#0: counter: 00007F52A47CF080, 1 2016/05/04 21:15:59 [debug] 9510#0: bind() 0.0.0.0:81 #8 2016/05/04 21:15:59 [debug] 9510#0: bind() 0.0.0.0:1935 #9 2016/05/04 21:15:59 [notice] 9510#0: using the "epoll" event method 2016/05/04 21:15:59 [debug] 9510#0: counter: 00007F1EDA7D9080, 1 2016/05/04 21:15:59 [notice] 9510#0: nginx/1.10.0 2016/05/04 21:15:59 [notice] 9510#0: built by gcc 4.8.2 20140120 (Red Hat 4.8.2-15) (GCC) 2016/05/04 21:15:59 [notice] 9510#0: OS: Linux 2.6.32-573.26.1.el6.x86_64 2016/05/04 21:15:59 [notice] 9510#0: getrlimit(RLIMIT_NOFILE): 1024:4096 2016/05/04 21:15:59 [debug] 9511#0: write: 10, 00007FFE806AB610, 5, 0 2016/05/04 21:15:59 [debug] 9511#0: setproctitle: "nginx: master process /opt/nginx/sbin/nginx -c /opt/nginx/conf/nginx.conf" 2016/05/04 21:15:59 [notice] 9511#0: start worker processes 2016/05/04 21:15:59 [debug] 9511#0: channel 3:10 2016/05/04 21:15:59 [notice] 9511#0: start worker process 9512 2016/05/04 21:15:59 [debug] 9511#0: channel 11:12 2016/05/04 21:15:59 [notice] 9511#0: start worker process 9513 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:1 pid:9513 fd:11 to s:0 pid:9512 fd:3 2016/05/04 21:15:59 [debug] 9511#0: channel 13:14 2016/05/04 21:15:59 [notice] 9511#0: start worker process 9515 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:2 pid:9515 fd:13 to s:0 pid:9512 fd:3 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:2 pid:9515 fd:13 to s:1 pid:9513 fd:11 2016/05/04 21:15:59 [debug] 9511#0: channel 15:16 2016/05/04 21:15:59 [notice] 9511#0: start worker process 9516 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:3 pid:9516 fd:15 to s:0 pid:9512 fd:3 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:3 pid:9516 fd:15 to s:1 pid:9513 fd:11 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:3 pid:9516 fd:15 to s:2 pid:9515 fd:13 2016/05/04 21:15:59 [debug] 9511#0: channel 17:18 2016/05/04 21:15:59 [notice] 9511#0: start cache manager process 9517 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:4 pid:9517 fd:17 to s:0 pid:9512 fd:3 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:4 pid:9517 fd:17 to s:1 pid:9513 fd:11 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:4 pid:9517 fd:17 to s:2 pid:9515 fd:13 2016/05/04 21:15:59 [debug] 9511#0: pass channel s:4 pid:9517 fd:17 to s:3 pid:9516 fd:15 2016/05/04 21:15:59 [debug] 9511#0: sigsuspend 2016/05/04 21:15:59 [debug] 9513#0: notify eventfd: 14 2016/05/04 21:15:59 [debug] 9513#0: eventfd: 15 2016/05/04 21:15:59 [debug] 9513#0: malloc: 00000000018E6C40:6144 2016/05/04 21:15:59 [debug] 9513#0: malloc: 0000000001952A60:229376 2016/05/04 21:15:59 [debug] 9513#0: malloc: 000000000198AA70:98304 2016/05/04 21:15:59 [debug] 9512#0: notify eventfd: 12 2016/05/04 21:15:59 [debug] 9512#0: eventfd: 13 2016/05/04 21:15:59 [debug] 9513#0: malloc: 00000000019A2A80:98304 2016/05/04 21:15:59 [debug] 9512#0: malloc: 00000000018E6C40:6144 2016/05/04 21:15:59 [debug] 9512#0: malloc: 0000000001952A60:229376 2016/05/04 21:15:59 [debug] 9512#0: malloc: 000000000198AA70:98304 2016/05/04 21:15:59 [debug] 9512#0: malloc: 00000000019A2A80:98304 2016/05/04 21:15:59 [debug] 9515#0: notify eventfd: 16 2016/05/04 21:15:59 [debug] 9515#0: eventfd: 17 2016/05/04 21:15:59 [debug] 9515#0: malloc: 00000000018E6C40:6144 2016/05/04 21:15:59 [debug] 9515#0: malloc: 0000000001952A60:229376 2016/05/04 21:15:59 [debug] 9515#0: malloc: 000000000198AA70:98304 2016/05/04 21:15:59 [debug] 9515#0: malloc: 00000000019A2A80:98304 2016/05/04 21:15:59 [debug] 9513#0: auto_push: creating sockets 2016/05/04 21:15:59 [debug] 9512#0: auto_push: creating sockets 2016/05/04 21:15:59 [debug] 9513#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.1' 2016/05/04 21:15:59 [debug] 9512#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.0' 2016/05/04 21:15:59 [debug] 9512#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.0' 2016/05/04 21:15:59 [debug] 9513#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.1' 2016/05/04 21:15:59 [debug] 9515#0: auto_push: creating sockets 2016/05/04 21:15:59 [debug] 9515#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.2' 2016/05/04 21:15:59 [debug] 9515#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.2' 2016/05/04 21:15:59 [debug] 9513#0: epoll add event: fd:12 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9513#0: setproctitle: "nginx: worker process" 2016/05/04 21:15:59 [debug] 9513#0: worker cycle 2016/05/04 21:15:59 [debug] 9513#0: accept mutex locked 2016/05/04 21:15:59 [debug] 9513#0: epoll add event: fd:8 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9513#0: epoll add event: fd:9 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9513#0: epoll timer: -1 2016/05/04 21:15:59 [debug] 9513#0: epoll: fd:12 ev:0001 d:0000000001952C20 2016/05/04 21:15:59 [debug] 9513#0: post event 000000000198AB30 2016/05/04 21:15:59 [debug] 9513#0: timer delta: 8 2016/05/04 21:15:59 [debug] 9513#0: posted event 000000000198AB30 2016/05/04 21:15:59 [debug] 9513#0: delete posted event 000000000198AB30 2016/05/04 21:15:59 [debug] 9513#0: channel handler 2016/05/04 21:15:59 [debug] 9513#0: channel: 32 2016/05/04 21:15:59 [debug] 9513#0: channel command: 1 2016/05/04 21:15:59 [debug] 9513#0: get channel s:2 pid:9515 fd:10 2016/05/04 21:15:59 [debug] 9513#0: channel: 32 2016/05/04 21:15:59 [debug] 9513#0: channel command: 1 2016/05/04 21:15:59 [debug] 9513#0: get channel s:3 pid:9516 fd:11 2016/05/04 21:15:59 [debug] 9513#0: channel: 32 2016/05/04 21:15:59 [debug] 9513#0: channel command: 1 2016/05/04 21:15:59 [debug] 9513#0: get channel s:4 pid:9517 fd:17 2016/05/04 21:15:59 [debug] 9513#0: channel: -2 2016/05/04 21:15:59 [debug] 9513#0: worker cycle 2016/05/04 21:15:59 [debug] 9513#0: accept mutex locked 2016/05/04 21:15:59 [debug] 9513#0: epoll timer: -1 2016/05/04 21:15:59 [debug] 9512#0: epoll add event: fd:10 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9512#0: setproctitle: "nginx: worker process" 2016/05/04 21:15:59 [debug] 9512#0: worker cycle 2016/05/04 21:15:59 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9512#0: epoll timer: 500 2016/05/04 21:15:59 [debug] 9512#0: epoll: fd:10 ev:0001 d:0000000001952C20 2016/05/04 21:15:59 [debug] 9517#0: close listening 0.0.0.0:81 #8 2016/05/04 21:15:59 [debug] 9512#0: channel handler 2016/05/04 21:15:59 [debug] 9517#0: close listening 0.0.0.0:1935 #9 2016/05/04 21:15:59 [debug] 9512#0: channel: 32 2016/05/04 21:15:59 [debug] 9515#0: epoll add event: fd:14 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9512#0: channel command: 1 2016/05/04 21:15:59 [debug] 9515#0: setproctitle: "nginx: worker process" 2016/05/04 21:15:59 [debug] 9512#0: get channel s:1 pid:9513 fd:3 2016/05/04 21:15:59 [debug] 9515#0: worker cycle 2016/05/04 21:15:59 [debug] 9512#0: channel: 32 2016/05/04 21:15:59 [debug] 9512#0: channel command: 1 2016/05/04 21:15:59 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9512#0: get channel s:2 pid:9515 fd:15 2016/05/04 21:15:59 [debug] 9515#0: epoll timer: 500 2016/05/04 21:15:59 [debug] 9512#0: channel: 32 2016/05/04 21:15:59 [debug] 9512#0: channel command: 1 2016/05/04 21:15:59 [debug] 9515#0: epoll: fd:14 ev:0001 d:0000000001952C20 2016/05/04 21:15:59 [debug] 9512#0: get channel s:3 pid:9516 fd:16 2016/05/04 21:15:59 [debug] 9515#0: channel handler 2016/05/04 21:15:59 [debug] 9512#0: channel: 32 2016/05/04 21:15:59 [debug] 9512#0: channel command: 1 2016/05/04 21:15:59 [debug] 9512#0: get channel s:4 pid:9517 fd:17 2016/05/04 21:15:59 [debug] 9515#0: channel: 32 2016/05/04 21:15:59 [debug] 9512#0: channel: -2 2016/05/04 21:15:59 [debug] 9515#0: channel command: 1 2016/05/04 21:15:59 [debug] 9512#0: timer delta: 8 2016/05/04 21:15:59 [debug] 9515#0: get channel s:3 pid:9516 fd:10 2016/05/04 21:15:59 [debug] 9512#0: worker cycle 2016/05/04 21:15:59 [debug] 9515#0: channel: 32 2016/05/04 21:15:59 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9515#0: channel command: 1 2016/05/04 21:15:59 [debug] 9512#0: epoll timer: 500 2016/05/04 21:15:59 [debug] 9515#0: get channel s:4 pid:9517 fd:12 2016/05/04 21:15:59 [debug] 9515#0: channel: -2 2016/05/04 21:15:59 [debug] 9515#0: timer delta: 8 2016/05/04 21:15:59 [debug] 9515#0: worker cycle 2016/05/04 21:15:59 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9515#0: epoll timer: 500 2016/05/04 21:15:59 [debug] 9516#0: notify eventfd: 18 2016/05/04 21:15:59 [debug] 9517#0: notify eventfd: 9 2016/05/04 21:15:59 [debug] 9516#0: eventfd: 19 2016/05/04 21:15:59 [debug] 9517#0: eventfd: 19 2016/05/04 21:15:59 [debug] 9516#0: malloc: 00000000018E6C40:6144 2016/05/04 21:15:59 [debug] 9517#0: malloc: 00000000018E6C40:6144 2016/05/04 21:15:59 [debug] 9516#0: malloc: 0000000001952A60:229376 2016/05/04 21:15:59 [debug] 9517#0: malloc: 0000000001952A60:114688 2016/05/04 21:15:59 [debug] 9516#0: malloc: 000000000198AA70:98304 2016/05/04 21:15:59 [debug] 9517#0: malloc: 000000000196EA70:49152 2016/05/04 21:15:59 [debug] 9517#0: malloc: 000000000197AA80:49152 2016/05/04 21:15:59 [debug] 9516#0: malloc: 00000000019A2A80:98304 2016/05/04 21:15:59 [debug] 9517#0: epoll add event: fd:18 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9517#0: setproctitle: "nginx: cache manager process" 2016/05/04 21:15:59 [debug] 9517#0: event timer add: -1: 0:1462385759908 2016/05/04 21:15:59 [debug] 9517#0: epoll timer: 0 2016/05/04 21:15:59 [debug] 9517#0: timer delta: 9 2016/05/04 21:15:59 [debug] 9517#0: event timer del: -1: 1462385759908 2016/05/04 21:15:59 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:15:59 [debug] 9517#0: event timer add: -1: 2000:1462385761917 2016/05/04 21:15:59 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:15:59 [debug] 9516#0: auto_push: creating sockets 2016/05/04 21:15:59 [debug] 9516#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.3' 2016/05/04 21:15:59 [debug] 9516#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.3' 2016/05/04 21:15:59 [debug] 9516#0: epoll add event: fd:16 op:1 ev:00002001 2016/05/04 21:15:59 [debug] 9516#0: setproctitle: "nginx: worker process" 2016/05/04 21:15:59 [debug] 9516#0: worker cycle 2016/05/04 21:15:59 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9516#0: epoll timer: 500 2016/05/04 21:15:59 [debug] 9516#0: epoll: fd:16 ev:0001 d:0000000001952C20 2016/05/04 21:15:59 [debug] 9516#0: channel handler 2016/05/04 21:15:59 [debug] 9516#0: channel: 32 2016/05/04 21:15:59 [debug] 9516#0: channel command: 1 2016/05/04 21:15:59 [debug] 9516#0: get channel s:4 pid:9517 fd:10 2016/05/04 21:15:59 [debug] 9516#0: channel: -2 2016/05/04 21:15:59 [debug] 9516#0: timer delta: 9 2016/05/04 21:15:59 [debug] 9516#0: worker cycle 2016/05/04 21:15:59 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:15:59 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:00 [debug] 9512#0: worker cycle 2016/05/04 21:16:00 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:00 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:00 [debug] 9515#0: worker cycle 2016/05/04 21:16:00 [debug] 9516#0: worker cycle 2016/05/04 21:16:00 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:00 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:00 [debug] 9512#0: worker cycle 2016/05/04 21:16:00 [debug] 9516#0: worker cycle 2016/05/04 21:16:00 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:00 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:00 [debug] 9515#0: worker cycle 2016/05/04 21:16:00 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:00 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:01 [debug] 9512#0: worker cycle 2016/05/04 21:16:01 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:01 [debug] 9515#0: worker cycle 2016/05/04 21:16:01 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:01 [debug] 9516#0: worker cycle 2016/05/04 21:16:01 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9517#0: timer delta: 2001 2016/05/04 21:16:01 [debug] 9517#0: event timer del: -1: 1462385761917 2016/05/04 21:16:01 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:01 [debug] 9517#0: event timer add: -1: 2000:1462385763918 2016/05/04 21:16:01 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:01 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:01 [debug] 9516#0: timer delta: 500 2016/05/04 21:16:01 [debug] 9512#0: worker cycle 2016/05/04 21:16:01 [debug] 9516#0: worker cycle 2016/05/04 21:16:01 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:01 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:01 [debug] 9515#0: worker cycle 2016/05/04 21:16:01 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:01 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:02 [debug] 9516#0: worker cycle 2016/05/04 21:16:02 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:02 [debug] 9512#0: worker cycle 2016/05/04 21:16:02 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:02 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9515#0: worker cycle 2016/05/04 21:16:02 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9516#0: timer delta: 500 2016/05/04 21:16:02 [debug] 9516#0: worker cycle 2016/05/04 21:16:02 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:02 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:02 [debug] 9512#0: worker cycle 2016/05/04 21:16:02 [debug] 9515#0: worker cycle 2016/05/04 21:16:02 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:02 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:02 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9516#0: timer delta: 502 2016/05/04 21:16:03 [debug] 9516#0: worker cycle 2016/05/04 21:16:03 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:03 [debug] 9512#0: worker cycle 2016/05/04 21:16:03 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:03 [debug] 9515#0: worker cycle 2016/05/04 21:16:03 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9517#0: timer delta: 2005 2016/05/04 21:16:03 [debug] 9517#0: event timer del: -1: 1462385763918 2016/05/04 21:16:03 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:03 [debug] 9517#0: event timer add: -1: 2000:1462385765923 2016/05/04 21:16:03 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:03 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:03 [debug] 9516#0: worker cycle 2016/05/04 21:16:03 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:03 [debug] 9515#0: worker cycle 2016/05/04 21:16:03 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:03 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:03 [debug] 9512#0: worker cycle 2016/05/04 21:16:03 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:03 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:04 [debug] 9516#0: timer delta: 502 2016/05/04 21:16:04 [debug] 9515#0: worker cycle 2016/05/04 21:16:04 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:04 [debug] 9516#0: worker cycle 2016/05/04 21:16:04 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9512#0: worker cycle 2016/05/04 21:16:04 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:04 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:04 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:04 [debug] 9516#0: worker cycle 2016/05/04 21:16:04 [debug] 9512#0: worker cycle 2016/05/04 21:16:04 [debug] 9515#0: worker cycle 2016/05/04 21:16:04 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:04 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:04 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:05 [debug] 9516#0: timer delta: 500 2016/05/04 21:16:05 [debug] 9512#0: worker cycle 2016/05/04 21:16:05 [debug] 9516#0: worker cycle 2016/05/04 21:16:05 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:05 [debug] 9515#0: worker cycle 2016/05/04 21:16:05 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9517#0: timer delta: 2001 2016/05/04 21:16:05 [debug] 9517#0: event timer del: -1: 1462385765923 2016/05/04 21:16:05 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:05 [debug] 9517#0: event timer add: -1: 2000:1462385767924 2016/05/04 21:16:05 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:05 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:05 [debug] 9516#0: worker cycle 2016/05/04 21:16:05 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:05 [debug] 9515#0: worker cycle 2016/05/04 21:16:05 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:05 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9512#0: worker cycle 2016/05/04 21:16:05 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:05 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:05 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:06 [debug] 9516#0: timer delta: 501 2016/05/04 21:16:06 [debug] 9515#0: worker cycle 2016/05/04 21:16:06 [debug] 9516#0: worker cycle 2016/05/04 21:16:06 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:06 [debug] 9512#0: worker cycle 2016/05/04 21:16:06 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:9 ev:0001 d:0000000001952B40 2016/05/04 21:16:06 [debug] 9513#0: post event 000000000198AAD0 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 6657 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AAD0 2016/05/04 21:16:06 [debug] 9513#0: delete posted event 000000000198AAD0 2016/05/04 21:16:06 [debug] 9513#0: accept on 0.0.0.0:1935, ready: 0 2016/05/04 21:16:06 [debug] 9513#0: posix_memalign: 00000000018F8110:4096 @16 2016/05/04 21:16:06 [debug] 9513#0: 1 accept: 192.168.10.2:63235 fd:18 2016/05/04 21:16:06 [info] 9513#0: 1 client connected '192.168.10.2' 2016/05/04 21:16:06 [debug] 9513#0: 1 posix_memalign: 00000000018E8450:4096 @16 2016/05/04 21:16:06 [debug] 9513#0: 1 setting chunk_size=128 2016/05/04 21:16:06 [debug] 9513#0: 1 posix_memalign: 00000000018DC540:4096 @16 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: start server handshake 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: allocating buffer 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 -1 of 1537 2016/05/04 21:16:06 [debug] 9513#0: 1 recv() not ready (11: Resource temporarily unavailable) 2016/05/04 21:16:06 [debug] 9513#0: 1 event timer add: 18: 60000:1462385826573 2016/05/04 21:16:06 [debug] 9513#0: 1 epoll add event: fd:18 op:1 ev:80002001 2016/05/04 21:16:06 [debug] 9513#0: worker cycle 2016/05/04 21:16:06 [debug] 9513#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9513#0: epoll timer: 60000 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:18 ev:0001 d:0000000001952D00 2016/05/04 21:16:06 [debug] 9513#0: 1 post event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 0 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 delete posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 event timer del: 18: 1462385826573 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 1537 of 1537 2016/05/04 21:16:06 [debug] 9513#0: 1 epoll del event: fd:18 op:2 ev:00000000 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: stage 2 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: peer version=2.7.0.128 epoch=350705 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: digest found at pos=1457 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 1537 of 1537 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: stage 3 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 1536 of 1536 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: stage 4 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 -1 of 1536 2016/05/04 21:16:06 [debug] 9513#0: 1 recv() not ready (11: Resource temporarily unavailable) 2016/05/04 21:16:06 [debug] 9513#0: 1 event timer add: 18: 60000:1462385826573 2016/05/04 21:16:06 [debug] 9513#0: 1 epoll add event: fd:18 op:1 ev:80002001 2016/05/04 21:16:06 [debug] 9513#0: worker cycle 2016/05/04 21:16:06 [debug] 9513#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9513#0: epoll timer: 60000 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:18 ev:0001 d:0000000001952D00 2016/05/04 21:16:06 [debug] 9513#0: 1 post event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 4 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 delete posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 event timer del: 18: 1462385826573 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 1536 of 1536 2016/05/04 21:16:06 [debug] 9513#0: 1 epoll del event: fd:18 op:2 ev:00000000 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: stage 5 2016/05/04 21:16:06 [debug] 9513#0: 1 handshake: done 2016/05/04 21:16:06 [debug] 9513#0: 1 event timer add: 18: 60000:1462385826577 2016/05/04 21:16:06 [debug] 9513#0: 1 ping: wait 60000ms 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 146 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=0 csid=3 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=0 amf_cmd (20) time=0+0 mlen=337 len=0 msid=0 2016/05/04 21:16:06 [debug] 9513#0: 1 reusing formerly read data: 6 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=3 csid=3 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=3 amf_cmd (20) time=0+0 mlen=337 len=128 msid=0 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 140 of 140 2016/05/04 21:16:06 [debug] 9513#0: 1 reusing formerly read data: 17 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=3 csid=3 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=3 amf_cmd (20) time=0+0 mlen=337 len=256 msid=0 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 65 of 129 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=337 msid=0 nbufs=3 2016/05/04 21:16:06 [debug] 9513#0: 1 nhandlers: 1 2016/05/04 21:16:06 [debug] 9513#0: 1 calling handler 0 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 07 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (7) 63 6F 6E 6E 65 63 74 'connect' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF func 'connect' passed to handler 0/1 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 3F F0 00 00 00 00 00 00 '????????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 03 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 03 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (3) 61 70 70 'app' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 04 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (4) 6C 69 76 65 'live' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 08 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 66 6C 61 73 68 56 65 72 'flashVer' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0E '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (14) 57 49 4E 20 32 31 2C 30 2C 30 2C 32 31 33 'WIN 21,0,0,213' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 06 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (6) 73 77 66 55 72 6C 'swfUrl' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 31 '?1' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (49) 68 74 74 70 3A 2F 2F 31 39 32 2E 31 36 38 2E 31 30 2E 31 2F 6D 6F 64 65 6C 2D 61 64 6D 69 6E 2F 52 74 6D 70 50 75 62 6C 69 73 68 65 72 2E 73 77 66 'http://192.168.10.1/RtmpPublisher.swf' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 05 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (5) 74 63 55 72 6C 'tcUrl' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 18 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (24) 72 74 6D 70 3A 2F 2F 31 39 32 2E 31 36 38 2E 31 30 2E 31 2F 6C 69 76 65 'rtmp://192.168.10.1/live' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 04 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (4) 66 70 61 64 'fpad' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 01 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) XX '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0C '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (12) 63 61 70 61 62 69 6C 69 74 69 65 73 'capabilities' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 40 6D E0 00 00 00 00 00 '@m??????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0B '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (11) 61 75 64 69 6F 43 6F 64 65 63 73 'audioCodecs' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 40 AB EE 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0B '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (11) 76 69 64 65 6F 43 6F 64 65 63 73 'videoCodecs' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 40 6F 80 00 00 00 00 00 '@o??????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0D '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (13) 76 69 64 65 6F 46 75 6E 63 74 69 6F 6E 'videoFunction' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 3F F0 00 00 00 00 00 00 '????????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 07 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (7) 70 61 67 65 55 72 6C 'pageUrl' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 2D '?-' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (45) 68 74 74 70 3A 2F 2F 31 39 32 2E 31 36 38 2E 31 30 2E 31 2F 6D 6F 64 65 6C 2D 61 64 6D 69 6E 2F 70 75 62 6C 69 73 68 65 72 2E 70 68 70 'http://192.168.10.1/publisher.php' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0E '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (14) 6F 62 6A 65 63 74 45 6E 63 6F 64 69 6E 67 'objectEncoding' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 40 08 00 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 00 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 09 '?' 2016/05/04 21:16:06 [info] 9513#0: 1 connect: app='live' args='' flashver='WIN 21,0,0,213' swf_url='http://192.168.10.1/RtmpPublisher.swf' tc_url='rtmp://192.168.10.1/live' page_url='http://192.168.10.1/publisher.php' acodecs=3575 vcodecs=252 object_encoding=3, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/04 21:16:06 [debug] 9513#0: 1 create: ack_size=5000000 2016/05/04 21:16:06 [debug] 9513#0: malloc: 00000000018DD550:4214 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP prep ack_size (5) fmt=0 csid=2 timestamp=0 mlen=4 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP send nmsg=1, priority=0 #1 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 16 of 16 2016/05/04 21:16:06 [debug] 9513#0: 1 create: bandwidth ack_size=5000000 limit=2 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP prep bandwidth (6) fmt=0 csid=2 timestamp=0 mlen=5 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP send nmsg=1, priority=0 #2 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 17 of 17 2016/05/04 21:16:06 [debug] 9513#0: 1 chunk_size=4096 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP prep chunk_size (1) fmt=0 csid=2 timestamp=0 mlen=4 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP send nmsg=1, priority=0 #3 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 16 of 16 2016/05/04 21:16:06 [debug] 9513#0: 1 create: amf nelts=4 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 07 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (7) 5F 72 65 73 75 6C 74 '_result' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (8) 3F F0 00 00 00 00 00 00 '????????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 03 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 06 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (6) 66 6D 73 56 65 72 'fmsVer' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 0D '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (13) 46 4D 53 2F 33 2C 30 2C 31 2C 31 32 33 'FMS/3,0,1,123' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 0C '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (12) 63 61 70 61 62 69 6C 69 74 69 65 73 'capabilities' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (8) 40 3F 00 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 00 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 09 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 03 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 05 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (5) 6C 65 76 65 6C 'level' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 06 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (6) 73 74 61 74 75 73 'status' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 04 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (4) 63 6F 64 65 'code' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 1D '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (29) 4E 65 74 43 6F 6E 6E 65 63 74 69 6F 6E 2E 43 6F 6E 6E 65 63 74 2E 53 75 63 63 65 73 73 'NetConnection.Connect.Success' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 0B '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (11) 64 65 73 63 72 69 70 74 69 6F 6E 'description' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 15 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (21) 43 6F 6E 6E 65 63 74 69 6F 6E 20 73 75 63 63 65 65 64 65 64 2E 'Connection succeeded.' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 0E '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (14) 6F 62 6A 65 63 74 45 6E 63 6F 64 69 6E 67 'objectEncoding' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (8) 40 08 00 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 00 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 09 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP prep amf_cmd (20) fmt=0 csid=3 timestamp=0 mlen=190 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP send nmsg=1, priority=0 #4 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 202 of 202 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 -1 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 recv() not ready (11: Resource temporarily unavailable) 2016/05/04 21:16:06 [debug] 9513#0: 1 epoll add event: fd:18 op:1 ev:80002001 2016/05/04 21:16:06 [debug] 9513#0: worker cycle 2016/05/04 21:16:06 [debug] 9513#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9513#0: epoll timer: 60000 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:18 ev:0001 d:0000000001952D00 2016/05/04 21:16:06 [debug] 9513#0: 1 post event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 196 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 delete posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 16 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=0 csid=2 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=0 ack_size (5) time=16426513+0 mlen=4 len=0 msid=0 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP recv ack_size (5) csid=2 timestamp=16426513 mlen=4 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 nhandlers: 1 2016/05/04 21:16:06 [debug] 9513#0: 1 calling handler 0 2016/05/04 21:16:06 [debug] 9513#0: 1 receive ack_size=5000000 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 -1 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 recv() not ready (11: Resource temporarily unavailable) 2016/05/04 21:16:06 [debug] 9513#0: worker cycle 2016/05/04 21:16:06 [debug] 9513#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9513#0: epoll timer: 59804 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:18 ev:0001 d:0000000001952D00 2016/05/04 21:16:06 [debug] 9513#0: 1 post event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 25 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 delete posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 38 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=0 csid=3 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=0 amf3_cmd (17) time=225+0 mlen=26 len=0 msid=0 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP recv amf3_cmd (17) csid=3 timestamp=225 mlen=26 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 nhandlers: 1 2016/05/04 21:16:06 [debug] 9513#0: 1 calling handler 0 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF3 prefix: 0 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 0C '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (12) 63 72 65 61 74 65 53 74 72 65 61 6D 'createStream' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF func 'createstream' passed to handler 0/1 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 40 00 00 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [info] 9513#0: 1 createStream, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/04 21:16:06 [debug] 9513#0: 1 create: amf nelts=4 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (2) 00 07 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (7) 5F 72 65 73 75 6C 74 '_result' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (8) 40 00 00 00 00 00 00 00 '@???????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 05 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF write (8) 3F F0 00 00 00 00 00 00 '????????' 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP prep amf_cmd (20) fmt=0 csid=3 timestamp=0 mlen=29 msid=0 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP send nmsg=1, priority=0 #5 2016/05/04 21:16:06 [debug] 9513#0: 1 send: fd:18 41 of 41 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 -1 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 recv() not ready (11: Resource temporarily unavailable) 2016/05/04 21:16:06 [debug] 9513#0: worker cycle 2016/05/04 21:16:06 [debug] 9513#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9513#0: epoll timer: 59779 2016/05/04 21:16:06 [debug] 9513#0: epoll: fd:18 ev:0001 d:0000000001952D00 2016/05/04 21:16:06 [debug] 9513#0: 1 post event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: timer delta: 21 2016/05/04 21:16:06 [debug] 9513#0: posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 delete posted event 000000000198AB90 2016/05/04 21:16:06 [debug] 9513#0: 1 recv: fd:18 146 of 146 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP bheader fmt=0 csid=8 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP mheader fmt=0 amf3_cmd (17) time=225+0 mlen=38 len=0 msid=1 2016/05/04 21:16:06 [debug] 9513#0: 1 RTMP recv amf3_cmd (17) csid=8 timestamp=225 mlen=38 msid=1 nbufs=1 2016/05/04 21:16:06 [debug] 9513#0: 1 nhandlers: 1 2016/05/04 21:16:06 [debug] 9513#0: 1 calling handler 0 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF3 prefix: 0 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 07 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (7) 70 75 62 6C 69 73 68 'publish' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF func 'publish' passed to handler 0/1 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 00 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (8) 00 00 00 00 00 00 00 00 '????????' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 05 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 05 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (5) 4E 69 6B 6F 73 'Nikos' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (1) 02 '?' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (2) 00 06 '??' 2016/05/04 21:16:06 [debug] 9513#0: 1 AMF read (6) 61 70 70 65 6E 64 'append' 2016/05/04 21:16:06 [info] 9513#0: *1 publish: name='Nikos' args='' type=append silent=0, client: 192.168.10.2, server: 0.0.0.0:1935 2016/05/04 21:16:06 [notice] 9511#0: signal 17 (SIGCHLD) received 2016/05/04 21:16:06 [alert] 9511#0: worker process 9513 exited on signal 11 (core dumped) 2016/05/04 21:16:06 [debug] 9511#0: shmtx forced unlock 2016/05/04 21:16:06 [debug] 9511#0: wake up, sigio 0 2016/05/04 21:16:06 [debug] 9511#0: reap children 2016/05/04 21:16:06 [debug] 9511#0: child: 0 9512 e:0 t:0 d:0 r:1 j:0 2016/05/04 21:16:06 [debug] 9511#0: child: 1 9513 e:0 t:1 d:0 r:1 j:0 2016/05/04 21:16:06 [debug] 9511#0: pass close channel s:1 pid:9513 to:9512 2016/05/04 21:16:06 [debug] 9511#0: pass close channel s:1 pid:9513 to:9515 2016/05/04 21:16:06 [debug] 9511#0: pass close channel s:1 pid:9513 to:9516 2016/05/04 21:16:06 [debug] 9515#0: epoll: fd:14 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9511#0: pass close channel s:1 pid:9513 to:9517 2016/05/04 21:16:06 [debug] 9515#0: channel handler 2016/05/04 21:16:06 [debug] 9515#0: channel: 32 2016/05/04 21:16:06 [debug] 9515#0: channel command: 2 2016/05/04 21:16:06 [debug] 9515#0: close channel s:1 pid:9513 our:9513 fd:11 2016/05/04 21:16:06 [debug] 9515#0: channel: -2 2016/05/04 21:16:06 [debug] 9515#0: timer delta: 492 2016/05/04 21:16:06 [debug] 9515#0: worker cycle 2016/05/04 21:16:06 [debug] 9511#0: channel 11:12 2016/05/04 21:16:06 [debug] 9515#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9515#0: epoll add event: fd:8 op:1 ev:00002001 2016/05/04 21:16:06 [debug] 9515#0: epoll add event: fd:9 op:1 ev:00002001 2016/05/04 21:16:06 [debug] 9515#0: epoll timer: -1 2016/05/04 21:16:06 [debug] 9512#0: epoll: fd:10 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9512#0: channel handler 2016/05/04 21:16:06 [debug] 9512#0: channel: 32 2016/05/04 21:16:06 [debug] 9517#0: epoll: fd:18 ev:0001 d:0000000001952A60 2016/05/04 21:16:06 [debug] 9512#0: channel command: 2 2016/05/04 21:16:06 [debug] 9517#0: channel handler 2016/05/04 21:16:06 [debug] 9512#0: close channel s:1 pid:9513 our:9513 fd:3 2016/05/04 21:16:06 [debug] 9512#0: channel: -2 2016/05/04 21:16:06 [debug] 9512#0: timer delta: 491 2016/05/04 21:16:06 [debug] 9512#0: worker cycle 2016/05/04 21:16:06 [debug] 9517#0: channel: 32 2016/05/04 21:16:06 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9517#0: channel command: 2 2016/05/04 21:16:06 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9517#0: close channel s:1 pid:9513 our:9513 fd:11 2016/05/04 21:16:06 [debug] 9517#0: channel: -2 2016/05/04 21:16:06 [debug] 9517#0: timer delta: 997 2016/05/04 21:16:06 [debug] 9516#0: epoll: fd:16 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9517#0: epoll timer: 1003 2016/05/04 21:16:06 [debug] 9516#0: channel handler 2016/05/04 21:16:06 [debug] 9516#0: channel: 32 2016/05/04 21:16:06 [debug] 9516#0: channel command: 2 2016/05/04 21:16:06 [debug] 9516#0: close channel s:1 pid:9513 our:9513 fd:11 2016/05/04 21:16:06 [debug] 9516#0: channel: -2 2016/05/04 21:16:06 [debug] 9516#0: timer delta: 492 2016/05/04 21:16:06 [debug] 9516#0: worker cycle 2016/05/04 21:16:06 [debug] 9516#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9516#0: epoll timer: 500 2016/05/04 21:16:06 [notice] 9511#0: start worker process 9524 2016/05/04 21:16:06 [debug] 9511#0: pass channel s:1 pid:9524 fd:11 to s:0 pid:9512 fd:3 2016/05/04 21:16:06 [debug] 9511#0: pass channel s:1 pid:9524 fd:11 to s:2 pid:9515 fd:13 2016/05/04 21:16:06 [debug] 9511#0: pass channel s:1 pid:9524 fd:11 to s:3 pid:9516 fd:15 2016/05/04 21:16:06 [debug] 9511#0: pass channel s:1 pid:9524 fd:11 to s:4 pid:9517 fd:17 2016/05/04 21:16:06 [debug] 9512#0: epoll: fd:10 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9512#0: channel handler 2016/05/04 21:16:06 [debug] 9512#0: channel: 32 2016/05/04 21:16:06 [debug] 9512#0: channel command: 1 2016/05/04 21:16:06 [debug] 9512#0: get channel s:1 pid:9524 fd:3 2016/05/04 21:16:06 [debug] 9511#0: child: 2 9515 e:0 t:0 d:0 r:1 j:0 2016/05/04 21:16:06 [debug] 9517#0: epoll: fd:18 ev:0001 d:0000000001952A60 2016/05/04 21:16:06 [debug] 9512#0: channel: -2 2016/05/04 21:16:06 [debug] 9511#0: child: 3 9516 e:0 t:0 d:0 r:1 j:0 2016/05/04 21:16:06 [debug] 9517#0: channel handler 2016/05/04 21:16:06 [debug] 9512#0: timer delta: 0 2016/05/04 21:16:06 [debug] 9511#0: child: 4 9517 e:0 t:0 d:0 r:1 j:0 2016/05/04 21:16:06 [debug] 9517#0: channel: 32 2016/05/04 21:16:06 [debug] 9512#0: worker cycle 2016/05/04 21:16:06 [debug] 9511#0: sigsuspend 2016/05/04 21:16:06 [debug] 9517#0: channel command: 1 2016/05/04 21:16:06 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9517#0: get channel s:1 pid:9524 fd:10 2016/05/04 21:16:06 [debug] 9516#0: epoll: fd:16 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9517#0: channel: -2 2016/05/04 21:16:06 [debug] 9516#0: channel handler 2016/05/04 21:16:06 [debug] 9517#0: timer delta: 0 2016/05/04 21:16:06 [debug] 9515#0: epoll: fd:14 ev:0001 d:0000000001952C20 2016/05/04 21:16:06 [debug] 9517#0: epoll timer: 1003 2016/05/04 21:16:06 [debug] 9516#0: channel: 32 2016/05/04 21:16:06 [debug] 9515#0: post event 000000000198AB30 2016/05/04 21:16:06 [debug] 9516#0: channel command: 1 2016/05/04 21:16:06 [debug] 9515#0: timer delta: 0 2016/05/04 21:16:06 [debug] 9516#0: get channel s:1 pid:9524 fd:11 2016/05/04 21:16:06 [debug] 9515#0: posted event 000000000198AB30 2016/05/04 21:16:06 [debug] 9516#0: channel: -2 2016/05/04 21:16:06 [debug] 9515#0: delete posted event 000000000198AB30 2016/05/04 21:16:06 [debug] 9516#0: timer delta: 0 2016/05/04 21:16:06 [debug] 9515#0: channel handler 2016/05/04 21:16:06 [debug] 9516#0: worker cycle 2016/05/04 21:16:06 [debug] 9515#0: channel: 32 2016/05/04 21:16:06 [debug] 9516#0: accept mutex locked 2016/05/04 21:16:06 [debug] 9515#0: channel command: 1 2016/05/04 21:16:06 [debug] 9516#0: epoll add event: fd:8 op:1 ev:00002001 2016/05/04 21:16:06 [debug] 9515#0: get channel s:1 pid:9524 fd:11 2016/05/04 21:16:06 [debug] 9516#0: epoll add event: fd:9 op:1 ev:00002001 2016/05/04 21:16:06 [debug] 9515#0: channel: -2 2016/05/04 21:16:06 [debug] 9516#0: epoll timer: -1 2016/05/04 21:16:06 [debug] 9515#0: worker cycle 2016/05/04 21:16:06 [debug] 9515#0: accept mutex lock failed: 1 2016/05/04 21:16:06 [debug] 9515#0: epoll del event: fd:8 op:2 ev:00000000 2016/05/04 21:16:06 [debug] 9515#0: epoll del event: fd:9 op:2 ev:00000000 2016/05/04 21:16:06 [notice] 9511#0: signal 29 (SIGIO) received 2016/05/04 21:16:06 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:06 [debug] 9511#0: wake up, sigio 0 2016/05/04 21:16:06 [debug] 9511#0: sigsuspend 2016/05/04 21:16:06 [debug] 9524#0: notify eventfd: 20 2016/05/04 21:16:06 [debug] 9524#0: eventfd: 21 2016/05/04 21:16:06 [debug] 9524#0: malloc: 00000000018E6C40:6144 2016/05/04 21:16:06 [debug] 9524#0: malloc: 0000000001952A60:229376 2016/05/04 21:16:06 [debug] 9524#0: malloc: 000000000198AA70:98304 2016/05/04 21:16:06 [debug] 9524#0: malloc: 00000000019A2A80:98304 2016/05/04 21:16:06 [debug] 9524#0: auto_push: creating sockets 2016/05/04 21:16:06 [debug] 9524#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.1' 2016/05/04 21:16:06 [debug] 9524#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.1' 2016/05/04 21:16:06 [debug] 9524#0: epoll add event: fd:12 op:1 ev:00002001 2016/05/04 21:16:06 [debug] 9524#0: setproctitle: "nginx: worker process" 2016/05/04 21:16:06 [debug] 9524#0: worker cycle 2016/05/04 21:16:06 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:06 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:07 [debug] 9512#0: worker cycle 2016/05/04 21:16:07 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:07 [debug] 9515#0: worker cycle 2016/05/04 21:16:07 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9524#0: timer delta: 503 2016/05/04 21:16:07 [debug] 9524#0: worker cycle 2016/05/04 21:16:07 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:07 [debug] 9515#0: worker cycle 2016/05/04 21:16:07 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:07 [debug] 9512#0: worker cycle 2016/05/04 21:16:07 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:07 [debug] 9524#0: worker cycle 2016/05/04 21:16:07 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:07 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:07 [debug] 9517#0: timer delta: 1003 2016/05/04 21:16:07 [debug] 9517#0: event timer del: -1: 1462385767924 2016/05/04 21:16:07 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:07 [debug] 9517#0: event timer add: -1: 2000:1462385769924 2016/05/04 21:16:07 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:08 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9512#0: worker cycle 2016/05/04 21:16:08 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:08 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9515#0: worker cycle 2016/05/04 21:16:08 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:08 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9524#0: worker cycle 2016/05/04 21:16:08 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:08 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9515#0: worker cycle 2016/05/04 21:16:08 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:08 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9512#0: worker cycle 2016/05/04 21:16:08 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:08 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:08 [debug] 9524#0: worker cycle 2016/05/04 21:16:08 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:08 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:09 [debug] 9512#0: worker cycle 2016/05/04 21:16:09 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:09 [debug] 9515#0: worker cycle 2016/05/04 21:16:09 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:09 [debug] 9524#0: worker cycle 2016/05/04 21:16:09 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9517#0: timer delta: 2002 2016/05/04 21:16:09 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:09 [debug] 9517#0: event timer del: -1: 1462385769924 2016/05/04 21:16:09 [debug] 9512#0: worker cycle 2016/05/04 21:16:09 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:09 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:09 [debug] 9515#0: worker cycle 2016/05/04 21:16:09 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:09 [debug] 9517#0: event timer add: -1: 2000:1462385771926 2016/05/04 21:16:09 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:09 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:09 [debug] 9524#0: worker cycle 2016/05/04 21:16:09 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:09 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9512#0: worker cycle 2016/05/04 21:16:10 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9515#0: worker cycle 2016/05/04 21:16:10 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9524#0: worker cycle 2016/05/04 21:16:10 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9512#0: worker cycle 2016/05/04 21:16:10 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9515#0: worker cycle 2016/05/04 21:16:10 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:10 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:10 [debug] 9524#0: worker cycle 2016/05/04 21:16:10 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:10 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:11 [debug] 9515#0: worker cycle 2016/05/04 21:16:11 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:11 [debug] 9512#0: worker cycle 2016/05/04 21:16:11 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:11 [debug] 9524#0: worker cycle 2016/05/04 21:16:11 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9517#0: timer delta: 2002 2016/05/04 21:16:11 [debug] 9517#0: event timer del: -1: 1462385771926 2016/05/04 21:16:11 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:11 [debug] 9517#0: event timer add: -1: 2000:1462385773929 2016/05/04 21:16:11 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:11 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:11 [debug] 9512#0: worker cycle 2016/05/04 21:16:11 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:11 [debug] 9515#0: worker cycle 2016/05/04 21:16:11 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:11 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:11 [debug] 9524#0: worker cycle 2016/05/04 21:16:11 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:11 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:12 [debug] 9524#0: worker cycle 2016/05/04 21:16:12 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:12 [debug] 9515#0: worker cycle 2016/05/04 21:16:12 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:12 [debug] 9512#0: worker cycle 2016/05/04 21:16:12 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:12 [debug] 9512#0: worker cycle 2016/05/04 21:16:12 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:12 [debug] 9515#0: worker cycle 2016/05/04 21:16:12 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:12 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:12 [debug] 9524#0: worker cycle 2016/05/04 21:16:12 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:12 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:13 [debug] 9515#0: worker cycle 2016/05/04 21:16:13 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:13 [debug] 9512#0: worker cycle 2016/05/04 21:16:13 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:13 [debug] 9524#0: worker cycle 2016/05/04 21:16:13 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9517#0: timer delta: 2002 2016/05/04 21:16:13 [debug] 9517#0: event timer del: -1: 1462385773929 2016/05/04 21:16:13 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:13 [debug] 9517#0: event timer add: -1: 2000:1462385775931 2016/05/04 21:16:13 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:13 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:13 [debug] 9515#0: worker cycle 2016/05/04 21:16:13 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:13 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9524#0: worker cycle 2016/05/04 21:16:13 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:13 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:13 [debug] 9512#0: worker cycle 2016/05/04 21:16:13 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:13 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:14 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:14 [debug] 9524#0: worker cycle 2016/05/04 21:16:14 [debug] 9512#0: worker cycle 2016/05/04 21:16:14 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:14 [debug] 9515#0: worker cycle 2016/05/04 21:16:14 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:14 [debug] 9524#0: worker cycle 2016/05/04 21:16:14 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9512#0: timer delta: 501 2016/05/04 21:16:14 [debug] 9512#0: worker cycle 2016/05/04 21:16:14 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:14 [debug] 9515#0: timer delta: 501 2016/05/04 21:16:14 [debug] 9515#0: worker cycle 2016/05/04 21:16:14 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:14 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:15 [debug] 9524#0: worker cycle 2016/05/04 21:16:15 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9515#0: timer delta: 500 2016/05/04 21:16:15 [debug] 9515#0: worker cycle 2016/05/04 21:16:15 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9512#0: timer delta: 500 2016/05/04 21:16:15 [debug] 9512#0: worker cycle 2016/05/04 21:16:15 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9517#0: timer delta: 2003 2016/05/04 21:16:15 [debug] 9517#0: event timer del: -1: 1462385775931 2016/05/04 21:16:15 [debug] 9517#0: hls: cleanup path='/tmp/HLS/mobile' playlen=4000 2016/05/04 21:16:15 [debug] 9517#0: event timer add: -1: 2000:1462385777934 2016/05/04 21:16:15 [debug] 9517#0: epoll timer: 2000 2016/05/04 21:16:15 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:15 [debug] 9524#0: worker cycle 2016/05/04 21:16:15 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:15 [debug] 9515#0: worker cycle 2016/05/04 21:16:15 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:15 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:15 [debug] 9512#0: worker cycle 2016/05/04 21:16:15 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:15 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9524#0: timer delta: 501 2016/05/04 21:16:16 [debug] 9524#0: worker cycle 2016/05/04 21:16:16 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:16 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9512#0: timer delta: 503 2016/05/04 21:16:16 [debug] 9512#0: worker cycle 2016/05/04 21:16:16 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:16 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9515#0: timer delta: 503 2016/05/04 21:16:16 [debug] 9515#0: worker cycle 2016/05/04 21:16:16 [debug] 9515#0: accept mutex lock failed: 0 2016/05/04 21:16:16 [debug] 9515#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9524#0: timer delta: 500 2016/05/04 21:16:16 [debug] 9524#0: worker cycle 2016/05/04 21:16:16 [debug] 9524#0: accept mutex lock failed: 0 2016/05/04 21:16:16 [debug] 9524#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9512#0: timer delta: 502 2016/05/04 21:16:16 [debug] 9512#0: worker cycle 2016/05/04 21:16:16 [debug] 9512#0: accept mutex lock failed: 0 2016/05/04 21:16:16 [debug] 9512#0: epoll timer: 500 2016/05/04 21:16:16 [debug] 9515#0: timer delta: 502 2016/05/04 21:16:16 [debug] 9515#0: worker cycle 2016/05/04 21:16:16 [debug] 9515#0: accept mutex lo

sceptic30 commented 8 years ago

@chriswiggins yes still exists even on 1 worker, thats why i compiled with debug flag and post configs and debug log to see whats going on. @misiek08 might see something interesting in the log

chriswiggins commented 8 years ago

Ok no worries. Just as long as the debug log is the one that you captured with only 1 worker process :-)

On 5/05/2016, at 7:02 AM, sceptic30 notifications@github.com<mailto:notifications@github.com> wrote:

@chriswigginshttps://github.com/chriswiggins yes still exists even on 1 worker, thats why i compiled with debug flag and post configs and debug log to see whats going on. @misiek08https://github.com/misiek08 might see something instersting in the log

You are receiving this because you were mentioned. Reply to this email directly or view it on GitHubhttps://github.com/sergey-dryabzhinsky/nginx-rtmp-module/issues/127#issuecomment-216967853

misiek08 commented 8 years ago 
2016/05/04 21:15:59 [debug] 9513#0: auto_push: creating sockets
2016/05/04 21:15:59 [debug] 9512#0: auto_push: creating sockets
2016/05/04 21:15:59 [debug] 9513#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.1'
2016/05/04 21:15:59 [debug] 9512#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.0'
2016/05/04 21:15:59 [debug] 9512#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.0'
2016/05/04 21:15:59 [debug] 9513#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.1'
2016/05/04 21:15:59 [debug] 9515#0: auto_push: creating sockets
2016/05/04 21:15:59 [debug] 9515#0: auto_push: create socket '/tmp/rtmp-sockets/nginx-rtmp.2'
2016/05/04 21:15:59 [debug] 9515#0: auto_push: delete existing socket '/tmp/rtmp-sockets/nginx-rtmp.2'

I see nginx is still trying to push to another worker. Remove rtmp_auto_push related configuration directives from config. I'm not 100% sure but it looks like 4 workers were enabled while producing this log. (it should be 4, but there's are additional processes spawned like cache manager, so I might be wrong, but it looks like I'm right).

sceptic30 commented 8 years ago

@misiek08 still same results , i gave up hope :(

e7d commented 8 years ago

Hello everyone,

Using nginx with nginx-rtmp-module for a long time now, I can confirm the previous reports. I don't have the skills to dive through debugging, though.

But he facts are clear. Everything worked fine up to nginx 1.9.10. Starting version 1.9.11, and also using the new 1.10.0, it became impossible to run, even with a dead simple straight forward configuration as following:

user www-data;
worker_processes 1;
pid /run/nginx.pid;

events {
        worker_connections 1024;
}

rtmp_auto_push on;
rtmp_auto_push_reconnect 1s;
rtmp_socket_dir /tmp;

error_log /var/log/nginx/error.log debug;

rtmp {
        server {
                listen 1935;
                chunk_size 8192;

                application transcode {
                        live on;
                }
        }
}

Using this configuration, here is what I can find in error.log:

2016/05/09 22:02:57 [debug] 4173#0: accept on 0.0.0.0:1935, ready: 0
2016/05/09 22:02:57 [debug] 4173#0: posix_memalign: 0000000001F5CD80:4096 @16
2016/05/09 22:02:57 [debug] 4173#0: *2 accept: 192.168.32.1:60845 fd:3
2016/05/09 22:02:57 [info] 4173#0: *2 client connected '192.168.32.1'
2016/05/09 22:02:57 [debug] 4173#0: *2 posix_memalign: 0000000001F64DC0:4096 @16
2016/05/09 22:02:57 [debug] 4173#0: *2 setting chunk_size=128
2016/05/09 22:02:57 [debug] 4173#0: *2 posix_memalign: 0000000001FC7030:4096 @16
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: start server handshake
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: allocating buffer
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 1537 of 1537
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: stage 2
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: peer version=0.0.0.0 epoch=138360560
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: old-style challenge
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 1537 of 1537
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: stage 3
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: old-style response
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 1536 of 1536
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: stage 4
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 1536 of 1536
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: stage 5
2016/05/09 22:02:57 [debug] 4173#0: *2 handshake: done
2016/05/09 22:02:57 [debug] 4173#0: *2 event timer add: 3: 1000:1462831378938
2016/05/09 22:02:57 [debug] 4173#0: *2 ping: wait 1000ms
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 -1 of 146
2016/05/09 22:02:57 [debug] 4173#0: *2 recv() not ready (11: Resource temporarily unavailable)
2016/05/09 22:02:57 [debug] 4173#0: *2 epoll add event: fd:3 op:1 ev:80002001
2016/05/09 22:02:57 [debug] 4173#0: timer delta: 8318
2016/05/09 22:02:57 [debug] 4173#0: worker cycle
2016/05/09 22:02:57 [debug] 4173#0: epoll timer: 1000
2016/05/09 22:02:57 [debug] 4173#0: epoll: fd:3 ev:0001 d:0000000001FFA408
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 16 of 146
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP bheader fmt=0 csid=2
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP mheader fmt=0 chunk_size (1) time=0+0 mlen=4 len=0 msid=0
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP recv chunk_size (1) csid=2 timestamp=0 mlen=4 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:57 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:57 [debug] 4173#0: *2 setting chunk_size=4096
2016/05/09 22:02:57 [debug] 4173#0: *2 posix_memalign: 0000000001FC8040:4096 @16
2016/05/09 22:02:57 [debug] 4173#0: *2 free: 0000000001FC7030, unused: 3774
2016/05/09 22:02:57 [debug] 4173#0: *2 malloc: 0000000001FC9050:4114
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 -1 of 4114
2016/05/09 22:02:57 [debug] 4173#0: *2 recv() not ready (11: Resource temporarily unavailable)
2016/05/09 22:02:57 [debug] 4173#0: timer delta: 1
2016/05/09 22:02:57 [debug] 4173#0: worker cycle
2016/05/09 22:02:57 [debug] 4173#0: epoll timer: 999
2016/05/09 22:02:57 [debug] 4173#0: epoll: fd:3 ev:0001 d:0000000001FFA408
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 196 of 4114
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP bheader fmt=0 csid=3
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP mheader fmt=0 amf_cmd (20) time=0+0 mlen=184 len=0 msid=0
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=184 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:57 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 07 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (7) 63 6F 6E 6E 65 63 74 'connect'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF func 'connect' passed to handler 0/1
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 00 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (8) 3F F0 00 00 00 00 00 00 '????????'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 03 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 03 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (3) 61 70 70 'app'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 09 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (9) 74 72 61 6E 73 63 6F 64 65 'transcode'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 04 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (4) 74 79 70 65 'type'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 0A '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (10) XX XX XX XX XX XX XX XX XX XX '??????????'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 08 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (8) 66 6C 61 73 68 56 65 72 'flashVer'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 1F '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (31) 46 4D 4C 45 2F 33 2E 30 20 28 63 6F 6D 70 61 74 69 62 6C 65 3B 20 46 4D 53 63 2F 31 2E 30 29 'FMLE/3.0 (compatible; FMSc/1.0)'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 06 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (6) 73 77 66 55 72 6C 'swfUrl'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 1E '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (30) 72 74 6D 70 3A 2F 2F 72 74 6D 70 2E 6E 65 61 70 2E 64 65 76 2F 74 72 61 6E 73 63 6F 64 65 'rtmp://rtmp.neap.dev/transcode'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 05 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (5) 74 63 55 72 6C 'tcUrl'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 1E '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (30) 72 74 6D 70 3A 2F 2F 72 74 6D 70 2E 6E 65 61 70 2E 64 65 76 2F 74 72 61 6E 73 63 6F 64 65 'rtmp://rtmp.neap.dev/transcode'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (2) 00 00 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF read (1) 09 '?'
2016/05/09 22:02:57 [info] 4173#0: *2 connect: app='transcode' args='' flashver='FMLE/3.0 (compatible; FMSc/1.0)' swf_url='rtmp://rtmp.neap.dev/transcode' tc_url='rtmp://rtmp.neap.dev/transcode' page_url='' acodecs=0 vcodecs=0 object_encoding=0, client: 192.168.32.1, server: 0.0.0.0:1935
2016/05/09 22:02:57 [debug] 4173#0: *2 create: ack_size=5000000
2016/05/09 22:02:57 [debug] 4173#0: malloc: 0000000001FD7070:8310
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP prep ack_size (5) fmt=0 csid=2 timestamp=0 mlen=4 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #1
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 16 of 16
2016/05/09 22:02:57 [debug] 4173#0: *2 create: bandwidth ack_size=5000000 limit=2
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP prep bandwidth (6) fmt=0 csid=2 timestamp=0 mlen=5 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #2
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 17 of 17
2016/05/09 22:02:57 [debug] 4173#0: *2 chunk_size=8192
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP prep chunk_size (1) fmt=0 csid=2 timestamp=0 mlen=4 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #3
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 16 of 16
2016/05/09 22:02:57 [debug] 4173#0: *2 create: amf nelts=4
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 07 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (7) 5F 72 65 73 75 6C 74 '_result'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (8) 3F F0 00 00 00 00 00 00 '????????'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 03 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 06 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (6) 66 6D 73 56 65 72 'fmsVer'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 0D '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (13) 46 4D 53 2F 33 2C 30 2C 31 2C 31 32 33 'FMS/3,0,1,123'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 0C '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (12) 63 61 70 61 62 69 6C 69 74 69 65 73 'capabilities'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (8) 40 3F 00 00 00 00 00 00 '@???????'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 00 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 09 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 03 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 05 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (5) 6C 65 76 65 6C 'level'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 06 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (6) 73 74 61 74 75 73 'status'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 04 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (4) 63 6F 64 65 'code'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 1D '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (29) 4E 65 74 43 6F 6E 6E 65 63 74 69 6F 6E 2E 43 6F 6E 6E 65 63 74 2E 53 75 63 63 65 73 73 'NetConnection.Connect.Success'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 0B '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (11) 64 65 73 63 72 69 70 74 69 6F 6E 'description'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 15 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (21) 43 6F 6E 6E 65 63 74 69 6F 6E 20 73 75 63 63 65 65 64 65 64 2E 'Connection succeeded.'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 0E '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (14) 6F 62 6A 65 63 74 45 6E 63 6F 64 69 6E 67 'objectEncoding'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (8) 00 00 00 00 00 00 00 00 '????????'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (2) 00 00 '??'
2016/05/09 22:02:57 [debug] 4173#0: *2 AMF write (1) 09 '?'
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP prep amf_cmd (20) fmt=0 csid=3 timestamp=0 mlen=190 msid=0 nbufs=1
2016/05/09 22:02:57 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #4
2016/05/09 22:02:57 [debug] 4173#0: *2 send: fd:3 202 of 202
2016/05/09 22:02:57 [debug] 4173#0: *2 recv: fd:3 -1 of 4114
2016/05/09 22:02:57 [debug] 4173#0: *2 recv() not ready (11: Resource temporarily unavailable)
2016/05/09 22:02:57 [debug] 4173#0: timer delta: 43
2016/05/09 22:02:57 [debug] 4173#0: worker cycle
2016/05/09 22:02:57 [debug] 4173#0: epoll timer: 956
2016/05/09 22:02:58 [debug] 4173#0: epoll: fd:3 ev:0001 d:0000000001FFA408
2016/05/09 22:02:58 [debug] 4173#0: *2 recv: fd:3 41 of 4114
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP bheader fmt=1 csid=3
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP mheader fmt=1 amf_cmd (20) time=0+0 mlen=33 len=0 msid=0
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=33 msid=0 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:58 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 0D '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (13) 72 65 6C 65 61 73 65 53 74 72 65 61 6D 'releaseStream'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF cmd 'releasestream' no handler
2016/05/09 22:02:58 [debug] 4173#0: *2 recv: fd:3 -1 of 4114
2016/05/09 22:02:58 [debug] 4173#0: *2 recv() not ready (11: Resource temporarily unavailable)
2016/05/09 22:02:58 [debug] 4173#0: timer delta: 50
2016/05/09 22:02:58 [debug] 4173#0: worker cycle
2016/05/09 22:02:58 [debug] 4173#0: epoll timer: 906
2016/05/09 22:02:58 [debug] 4166#0: timer delta: 3004
2016/05/09 22:02:58 [debug] 4166#0: event timer del: -1: 1462831378039
2016/05/09 22:02:58 [debug] 4166#0: hls: cleanup path='/data/rtmp/hls' playlen=6000
2016/05/09 22:02:58 [debug] 4166#0: dash: cleanup path='/data/rtmp/dash' playlen=6000
2016/05/09 22:02:58 [debug] 4166#0: event timer add: -1: 3000:1462831381043
2016/05/09 22:02:58 [debug] 4166#0: epoll timer: 3000
2016/05/09 22:02:58 [debug] 4173#0: epoll: fd:3 ev:0001 d:0000000001FFA408
2016/05/09 22:02:58 [debug] 4173#0: *2 recv: fd:3 70 of 4114
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP bheader fmt=1 csid=3
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP mheader fmt=1 amf_cmd (20) time=0+0 mlen=29 len=0 msid=0
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=29 msid=0 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:58 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 09 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (9) 46 43 50 75 62 6C 69 73 68 'FCPublish'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF func 'fcpublish' passed to handler 0/1
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (8) 40 08 00 00 00 00 00 00 '@???????'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 05 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 04 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (4) 74 65 73 74 'test'
2016/05/09 22:02:58 [debug] 4173#0: *2 live: onFCPublish: stream='test'
2016/05/09 22:02:58 [debug] 4173#0: *2 create: amf nelts=4
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 0B '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (11) 6F 6E 46 43 50 75 62 6C 69 73 68 'onFCPublish'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (8) 00 00 00 00 00 00 00 00 '????????'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 05 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 03 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 05 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (5) 6C 65 76 65 6C 'level'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 06 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (6) 73 74 61 74 75 73 'status'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 04 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (4) 63 6F 64 65 'code'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 17 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (23) 4E 65 74 53 74 72 65 61 6D 2E 50 75 62 6C 69 73 68 2E 53 74 61 72 74 'NetStream.Publish.Start'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 0B '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (11) 64 65 73 63 72 69 70 74 69 6F 6E 'description'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 04 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (4) 74 65 73 74 'test'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 00 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 09 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP prep amf_cmd (20) fmt=0 csid=5 timestamp=0 mlen=96 msid=1 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #5
2016/05/09 22:02:58 [debug] 4173#0: *2 send: fd:3 108 of 108
2016/05/09 22:02:58 [debug] 4173#0: *2 reusing formerly read data: 33
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP bheader fmt=1 csid=3
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP mheader fmt=1 amf_cmd (20) time=0+0 mlen=25 len=0 msid=0
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=25 msid=0 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:58 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 0C '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (12) 63 72 65 61 74 65 53 74 72 65 61 6D 'createStream'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF func 'createstream' passed to handler 0/1
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (8) 40 10 00 00 00 00 00 00 '@???????'
2016/05/09 22:02:58 [info] 4173#0: *2 createStream, client: 192.168.32.1, server: 0.0.0.0:1935
2016/05/09 22:02:58 [debug] 4173#0: *2 create: amf nelts=4
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (2) 00 07 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (7) 5F 72 65 73 75 6C 74 '_result'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (8) 40 10 00 00 00 00 00 00 '@???????'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 05 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF write (8) 3F F0 00 00 00 00 00 00 '????????'
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP prep amf_cmd (20) fmt=0 csid=3 timestamp=0 mlen=29 msid=0 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP send nmsg=1, priority=0 #6
2016/05/09 22:02:58 [debug] 4173#0: *2 send: fd:3 41 of 41
2016/05/09 22:02:58 [debug] 4173#0: *2 recv: fd:3 -1 of 4114
2016/05/09 22:02:58 [debug] 4173#0: *2 recv() not ready (11: Resource temporarily unavailable)
2016/05/09 22:02:58 [debug] 4173#0: timer delta: 45
2016/05/09 22:02:58 [debug] 4173#0: worker cycle
2016/05/09 22:02:58 [debug] 4173#0: epoll timer: 861
2016/05/09 22:02:58 [debug] 4173#0: epoll: fd:3 ev:0001 d:0000000001FFA408
2016/05/09 22:02:58 [debug] 4173#0: *2 recv: fd:3 46 of 4114
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP bheader fmt=0 csid=4
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP mheader fmt=0 amf_cmd (20) time=0+0 mlen=34 len=0 msid=1
2016/05/09 22:02:58 [debug] 4173#0: *2 RTMP recv amf_cmd (20) csid=4 timestamp=0 mlen=34 msid=1 nbufs=1
2016/05/09 22:02:58 [debug] 4173#0: *2 nhandlers: 1
2016/05/09 22:02:58 [debug] 4173#0: *2 calling handler 0
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 07 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (7) 70 75 62 6C 69 73 68 'publish'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF func 'publish' passed to handler 0/1
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 00 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (8) 40 14 00 00 00 00 00 00 '@???????'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 05 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 04 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (4) 74 65 73 74 'test'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (1) 02 '?'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (2) 00 04 '??'
2016/05/09 22:02:58 [debug] 4173#0: *2 AMF read (4) 6C 69 76 65 'live'
2016/05/09 22:02:58 [info] 4173#0: *2 publish: name='test' args='' type=live silent=0, client: 192.168.32.1, server: 0.0.0.0:1935
2016/05/09 22:02:58 [notice] 4164#0: signal 17 (SIGCHLD) received
2016/05/09 22:02:58 [alert] 4164#0: worker process 4173 exited on signal 11
2016/05/09 22:02:58 [debug] 4164#0: shmtx forced unlock
2016/05/09 22:02:58 [debug] 4164#0: shmtx forced unlock
2016/05/09 22:02:58 [debug] 4164#0: wake up, sigio 0
2016/05/09 22:02:58 [debug] 4164#0: reap children
2016/05/09 22:02:58 [debug] 4164#0: child: 0 4173 e:0 t:1 d:0 r:1 j:0
2016/05/09 22:02:58 [debug] 4164#0: pass close channel s:0 pid:4173 to:4166
2016/05/09 22:02:58 [debug] 4164#0: channel 3:11
2016/05/09 22:02:58 [debug] 4166#0: epoll: fd:13 ev:0001 d:0000000001FF9FD0
2016/05/09 22:02:58 [debug] 4166#0: channel handler
2016/05/09 22:02:58 [debug] 4166#0: channel: 32
2016/05/09 22:02:58 [debug] 4166#0: channel command: 2
2016/05/09 22:02:58 [debug] 4166#0: close channel s:0 pid:4173 our:4173 fd:3
2016/05/09 22:02:58 [debug] 4166#0: channel: -2
2016/05/09 22:02:58 [debug] 4166#0: timer delta: 114
2016/05/09 22:02:58 [debug] 4166#0: epoll timer: 2886
2016/05/09 22:02:58 [notice] 4164#0: start worker process 4176
2016/05/09 22:02:58 [debug] 4164#0: pass channel s:0 pid:4176 fd:3 to s:1 pid:4166 fd:12
2016/05/09 22:02:58 [debug] 4164#0: child: 1 4166 e:0 t:0 d:0 r:1 j:0
2016/05/09 22:02:58 [debug] 4164#0: sigsuspend
2016/05/09 22:02:58 [notice] 4164#0: signal 29 (SIGIO) received
2016/05/09 22:02:58 [debug] 4164#0: wake up, sigio 0
2016/05/09 22:02:58 [debug] 4164#0: sigsuspend
2016/05/09 22:02:58 [debug] 4166#0: epoll: fd:13 ev:0001 d:0000000001FF9FD0
2016/05/09 22:02:58 [debug] 4166#0: channel handler
2016/05/09 22:02:58 [debug] 4166#0: channel: 32
2016/05/09 22:02:58 [debug] 4166#0: channel command: 1
2016/05/09 22:02:58 [debug] 4166#0: get channel s:0 pid:4176 fd:3
2016/05/09 22:02:58 [debug] 4166#0: channel: -2
2016/05/09 22:02:58 [debug] 4166#0: timer delta: 0
2016/05/09 22:02:58 [debug] 4166#0: epoll timer: 2886
2016/05/09 22:02:58 [debug] 4176#0: notify eventfd: 15
2016/05/09 22:02:58 [debug] 4176#0: eventfd: 16
2016/05/09 22:02:58 [debug] 4176#0: malloc: 0000000001F61DA0:6144
2016/05/09 22:02:58 [debug] 4176#0: malloc: 0000000001FF9FD0:221184
2016/05/09 22:02:58 [debug] 4176#0: malloc: 000000000202FFE0:98304
2016/05/09 22:02:58 [debug] 4176#0: malloc: 0000000002047FF0:98304
2016/05/09 22:02:58 [debug] 4176#0: epoll add event: fd:10 op:1 ev:00002001
2016/05/09 22:02:58 [debug] 4176#0: auto_push: creating sockets
2016/05/09 22:02:58 [debug] 4176#0: auto_push: create socket '/tmp/nginx-rtmp.0'
2016/05/09 22:02:58 [debug] 4176#0: auto_push: delete existing socket '/tmp/nginx-rtmp.0'
2016/05/09 22:02:58 [debug] 4176#0: epoll add event: fd:11 op:1 ev:00002001
2016/05/09 22:02:58 [debug] 4176#0: setproctitle: "nginx: worker process"
2016/05/09 22:02:58 [debug] 4176#0: worker cycle
2016/05/09 22:02:58 [debug] 4176#0: epoll timer: -1
2016/05/09 22:03:01 [debug] 4166#0: timer delta: 2889
2016/05/09 22:03:01 [debug] 4166#0: event timer del: -1: 1462831381043
2016/05/09 22:03:01 [debug] 4166#0: event timer add: -1: 3000:1462831384046
2016/05/09 22:03:01 [debug] 4166#0: epoll timer: 3000
RocFang commented 8 years ago

@e7d Hello , your infomation is quite useful, thanks.For your situation, you just need to remove the 

rtmp_auto_push on;
rtmp_auto_push_reconnect 1s;
rtmp_socket_dir /tmp;

lines from configuration file and it should work fine. BTW, it also does not make sense to have auto_push config when you have only one worker process.

Of course It's a bug, let's talk about the details. we know that every rtmp session has a module context array. According to the code below:

    s->ctx = ngx_pcalloc(c->pool, sizeof(void *) * ngx_rtmp_max_module);
    if (s->ctx == NULL) {
        ngx_rtmp_close_connection(c);
        return NULL;
    }

But, ngx_rtmp_auto_push_module is not a rtmp type module. It's a core module instead and this is the key problem.

When a publisher comes in and publish a live stream, ngx_rtmp_auto_push_publish will get executed.Bad thing will happen in code below:

    ctx = ngx_rtmp_get_module_ctx(s, ngx_rtmp_auto_push_module);
    if (ctx == NULL) {
        ctx = ngx_palloc(s->connection->pool,
                         sizeof(ngx_rtmp_auto_push_ctx_t));
        if (ctx == NULL) {
            goto next;
        }
        ngx_rtmp_set_ctx(s, ctx, ngx_rtmp_auto_push_module);

    }

As what i have mentioned above, ngx_rtmp_auto_push_module is a core module, so it has no place in ngx_rtmp_session_t->ctx. So ngx_rtmp_get_module_ctx will cause bad things.

Why it work fine in old nginx version? Because in the version previous than nginx-1.9.11, the default ctx_index of a module is 0. From nginx-1.9.11 ,the default ctx_index of a module is -1.When it's 0, it actually use ngx_rtmp_core_module's ctx position, and ngx_rtmp_core_module luckily does not use it's ctx. But when it's -1, it will certainly override someone else's memory.

It's easy to fix this problem, but i do not suggest using auto_push in real production env. It has many other bugs.

@sergey-dryabzhinsky sergey, you can have a check of this bug too.

BTW, the default value of ctx_index is defined in the macro

NGX_MODULE_V1

e7d commented 8 years ago

Hello @RocFang,

Thank you for the really detailed response! Even though I'm not really into C code, I do get the core problem of this. Actually, after posting my message, I did some more investigation and noticed that removing the configuration part regarding "auto push" was solving it. I now understand why.

Just to be completely clear, and if I get it correctly, it means that if I want to use nginx version 1.9.11 or after, I'll not be able to use "auto push" at all. I'm OK with that since you say it could introduce different bugs. Does this also means I would never be able to use more than 1 worker process? In that case, and in a multi core configuration, I guess I would never be able to benefit from all my cores ? That could be quite a big drawback.

misiek08 commented 8 years ago

You can setup load balancer in front of multiple nginx processes and just push every steam to other processes. You should run one nginx for each core and make it listen on another port.

xxxman2008 commented 8 years ago

sorry ，after read all above ,i know RocFang not suggest using auto_push in real production env. Ok ,but if there's a plan to fix this "-1" bug?

and .. misiek08 suggestion maybe work ,but ...it's a little not acceptable for me. So i really hope the bug can be fixed.

xxxman2008 commented 8 years ago

after a while ,i just realized this is not arut verion ..So ,i clone this ,and made some test.

The test is based on nginx 1.9.10 ( 16 workers ). when i use arut-module with "rtmp_auto_push on", works fine for me.

it's strange , when i use this version with "rtmp_auto_push on". when i first connect ,and play one of my streams ,it's ok. then ,i disconnect . make new connection and play same stream .........it's ..stucked then , disconnect ,connection again ,play ....stucked.

misiek08 commented 8 years ago

Sometimes your connection will go to correct worker (first connection should go to first worker where published data are available), but next few requests will go to incorrect workers.

  1. Why you can't use multiple instances behind proxy?
  2. Patches for bugs welcome :)
darktar commented 8 years ago

The only way to use multiple_workers is using 1.9.10 nginx version?.. the changelog from 1.9.10 to mainline have alot of bugfix... some of those bug are affecting nginx-rtmp module?