publishing broken (SIGCHLD)

[farfelu]

I am using nginx 1.9.7 on a raspberry pi 2 on debian jessie.
Publishing appears to be broken. I've tried ffmpeg and OBS, both had connection errors.

It worked with aruts branch (v1.1.7), but I'm not having any luck with this one (v1.1.7.9).

rtmp.conf

rtmp {

    server {

        listen 1935;
        chunk_size 4096;

        application live2 {
                live on;
                dash on;
                dash_path /mnt/ramdisk/dash;
                dash_fragment 10s;
        }

        application live {
                live on;
                record off;
                publish_notify on;
                play_restart on;
        }
    }
}

ffmpeg verbose output:

Opening an output file: rtmp://192.168.3.211/live/test.
Parsing...
Parsed protocol: 0
Parsed host    : 192.168.3.211
Parsed app     : live
RTMP_Connect1, ... connected, handshaking
HandShake: Type Answer   : 03
HandShake: Server Uptime : 49550062
HandShake: FMS Version   : 0.0.0.0
HandShake: Handshaking finished....
RTMP_Connect1, handshaked
RTMP_SendPacket: fd=516, size=89
  0000:  03 00 00 00 00 00 59 14  00 00 00 00               ......Y.....
  0000:  02 00 07 63 6f 6e 6e 65  63 74 00 3f f0 00 00 00   ...connect.?....
  0010:  00 00 00 03 00 03 61 70  70 02 00 04 6c 69 76 65   ......app...live
  0020:  00 04 74 79 70 65 02 00  0a 6e 6f 6e 70 72 69 76   ..type...nonpriv
  0030:  61 74 65 00 05 74 63 55  72 6c 02 00 19 72 74 6d   ate..tcUrl...rtm
  0040:  70 3a 2f 2f 31 39 32 2e  31 36 38 2e 33 2e 32 31   p://192.168.3.21
  0050:  31 2f 6c 69 76 65 00 00  09                        1/live...
Invoking connect
RTMP_ReadPacket: fd=516
RTMP_ReadPacket, failed to read RTMP packet header
rtmp://192.168.3.211/live/test: Unknown error occurred

debug.log

2015/11/29 23:29:45 [debug] 28376#0: epoll: fd:6 ev:0001 d:018EE6A0
2015/11/29 23:29:45 [debug] 28376#0: accept on 0.0.0.0:1935, ready: 0
2015/11/29 23:29:45 [debug] 28376#0: posix_memalign: 01851150:4096 @16
2015/11/29 23:29:45 [debug] 28376#0: *1 accept: 192.168.3.199:55381 fd:12
2015/11/29 23:29:45 [info] 28376#0: *1 client connected '192.168.3.199'
2015/11/29 23:29:45 [debug] 28376#0: *1 setting chunk_size=128
2015/11/29 23:29:45 [debug] 28376#0: *1 posix_memalign: 01852180:4096 @16
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: start server handshake
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: allocating buffer
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 -1 of 1537
2015/11/29 23:29:45 [debug] 28376#0: *1 recv() not ready (11: Resource temporarily unavailable)
2015/11/29 23:29:45 [debug] 28376#0: *1 event timer add: 12: 60000:1432266987
2015/11/29 23:29:45 [debug] 28376#0: *1 epoll add event: fd:12 op:1 ev:80002001
2015/11/29 23:29:45 [debug] 28376#0: timer delta: 13915
2015/11/29 23:29:45 [debug] 28376#0: worker cycle
2015/11/29 23:29:45 [debug] 28376#0: epoll timer: 60000
2015/11/29 23:29:45 [debug] 28376#0: epoll: fd:12 ev:0001 d:018EE808
2015/11/29 23:29:45 [debug] 28376#0: *1 event timer del: 12: 1432266987
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 1537 of 1537
2015/11/29 23:29:45 [debug] 28376#0: *1 epoll del event: fd:12 op:2 ev:00000000
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: stage 2
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: peer version=0.0.0.0 epoch=49609406
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: old-style challenge
2015/11/29 23:29:45 [debug] 28376#0: *1 send: fd:12 1537 of 1537
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: stage 3
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: old-style response
2015/11/29 23:29:45 [debug] 28376#0: *1 send: fd:12 1536 of 1536
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: stage 4
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 -1 of 1536
2015/11/29 23:29:45 [debug] 28376#0: *1 recv() not ready (11: Resource temporarily unavailable)
2015/11/29 23:29:45 [debug] 28376#0: *1 event timer add: 12: 60000:1432266988
2015/11/29 23:29:45 [debug] 28376#0: *1 epoll add event: fd:12 op:1 ev:80002001
2015/11/29 23:29:45 [debug] 28376#0: timer delta: 1
2015/11/29 23:29:45 [debug] 28376#0: worker cycle
2015/11/29 23:29:45 [debug] 28376#0: epoll timer: 60000
2015/11/29 23:29:45 [debug] 28376#0: epoll: fd:12 ev:0001 d:018EE808
2015/11/29 23:29:45 [debug] 28376#0: *1 event timer del: 12: 1432266988
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 1536 of 1536
2015/11/29 23:29:45 [debug] 28376#0: *1 epoll del event: fd:12 op:2 ev:00000000
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: stage 5
2015/11/29 23:29:45 [debug] 28376#0: *1 handshake: done
2015/11/29 23:29:45 [debug] 28376#0: *1 event timer add: 12: 60000:1432266992
2015/11/29 23:29:45 [debug] 28376#0: *1 ping: wait 60000ms
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 -1 of 146
2015/11/29 23:29:45 [debug] 28376#0: *1 recv() not ready (11: Resource temporarily unavailable)
2015/11/29 23:29:45 [debug] 28376#0: *1 epoll add event: fd:12 op:1 ev:80002001
2015/11/29 23:29:45 [debug] 28376#0: timer delta: 4
2015/11/29 23:29:45 [debug] 28376#0: worker cycle
2015/11/29 23:29:45 [debug] 28376#0: epoll timer: 60000
2015/11/29 23:29:45 [debug] 28376#0: epoll: fd:12 ev:0001 d:018EE808
2015/11/29 23:29:45 [debug] 28376#0: *1 recv: fd:12 101 of 146
2015/11/29 23:29:45 [debug] 28376#0: *1 RTMP bheader fmt=0 csid=3
2015/11/29 23:29:45 [debug] 28376#0: *1 RTMP mheader fmt=0 amf_cmd (20) time=0+0 mlen=89 len=0 msid=0
2015/11/29 23:29:45 [debug] 28376#0: *1 RTMP recv amf_cmd (20) csid=3 timestamp=0 mlen=89 msid=0 nbufs=1
2015/11/29 23:29:45 [debug] 28376#0: *1 nhandlers: 1
2015/11/29 23:29:45 [debug] 28376#0: *1 calling handler 0
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 02 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 07 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (7) 63 6F 6E 6E 65 63 74 'connect'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF func 'connect' passed to handler 0/1
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 00 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (8) 3F F0 00 00 00 00 00 00 '????????'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 03 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 03 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (3) 61 70 70 'app'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 02 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 04 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (4) 6C 69 76 65 'live'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 04 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (4) 74 79 70 65 'type'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 02 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 0A '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (10) XX XX XX XX XX XX XX XX XX XX '??????????'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 05 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (5) 74 63 55 72 6C 'tcUrl'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 02 '?'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 19 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (25) 72 74 6D 70 3A 2F 2F 31 39 32 2E 31 36 38 2E 33 2E 32 31 31 2F 6C 69 76 65 'rtmp://192.168.3.211/live'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (2) 00 00 '??'
2015/11/29 23:29:45 [debug] 28376#0: *1 AMF read (1) 09 '?'
2015/11/29 23:29:45 [info] 28376#0: *1 connect: app='live' args='' flashver='' swf_url='' tc_url='rtmp://192.168.3.211/live' page_url='' acodecs=0 vcodecs=0 object_encoding=0, client: 192.168.3.199, server: 0.0.0.0:1935
2015/11/29 23:29:45 [notice] 28375#0: signal 17 (SIGCHLD) received
2015/11/29 23:29:45 [alert] 28375#0: worker process 28376 exited on signal 11
2015/11/29 23:29:45 [debug] 28375#0: shmtx forced unlock
2015/11/29 23:29:45 [debug] 28375#0: wake up, sigio 0
2015/11/29 23:29:45 [debug] 28375#0: reap children
2015/11/29 23:29:45 [debug] 28375#0: child: 0 28376 e:0 t:1 d:0 r:1 j:0
2015/11/29 23:29:45 [debug] 28375#0: pass close channel s:0 pid:28376 to:28377
2015/11/29 23:29:45 [debug] 28375#0: channel 3:8
2015/11/29 23:29:45 [debug] 28377#0: epoll: fd:10 ev:0001 d:018EE6A0
2015/11/29 23:29:45 [notice] 28375#0: start worker process 28387
2015/11/29 23:29:45 [debug] 28377#0: channel handler
2015/11/29 23:29:45 [debug] 28375#0: pass channel s:0 pid:28387 fd:3 to s:1 pid:28377 fd:9
2015/11/29 23:29:45 [debug] 28377#0: channel: 16
2015/11/29 23:29:45 [debug] 28375#0: child: 1 28377 e:0 t:0 d:0 r:1 j:0
2015/11/29 23:29:45 [debug] 28377#0: channel command: 2
2015/11/29 23:29:45 [debug] 28375#0: sigsuspend
2015/11/29 23:29:45 [debug] 28377#0: close channel s:0 pid:28376 our:28376 fd:3
2015/11/29 23:29:45 [debug] 28377#0: channel: 16
2015/11/29 23:29:45 [debug] 28377#0: channel command: 1
2015/11/29 23:29:45 [debug] 28377#0: get channel s:0 pid:28387 fd:3
2015/11/29 23:29:45 [notice] 28375#0: signal 29 (SIGIO) received
2015/11/29 23:29:45 [debug] 28377#0: channel: -2
2015/11/29 23:29:45 [debug] 28375#0: wake up, sigio 0
2015/11/29 23:29:45 [debug] 28377#0: timer delta: 13953
2015/11/29 23:29:45 [debug] 28375#0: sigsuspend
2015/11/29 23:29:45 [debug] 28377#0: epoll timer: 46047
2015/11/29 23:29:45 [debug] 28387#0: notify eventfd: 12
2015/11/29 23:29:45 [debug] 28387#0: eventfd: 13
2015/11/29 23:29:45 [debug] 28387#0: malloc: 0184F130:8192
2015/11/29 23:29:45 [debug] 28387#0: malloc: 018EE6A0:122880
2015/11/29 23:29:45 [debug] 28387#0: malloc: 0190C6A8:49152
2015/11/29 23:29:45 [debug] 28387#0: malloc: 019186B0:49152
2015/11/29 23:29:45 [debug] 28387#0: epoll add event: fd:6 op:1 ev:00002001
2015/11/29 23:29:45 [debug] 28387#0: epoll add event: fd:7 op:1 ev:00002001
2015/11/29 23:29:45 [debug] 28387#0: epoll add event: fd:8 op:1 ev:00002001
2015/11/29 23:29:45 [debug] 28387#0: setproctitle: "nginx: worker process"
2015/11/29 23:29:45 [debug] 28387#0: worker cycle
2015/11/29 23:29:45 [debug] 28387#0: epoll timer: -1

[sergey-dryabzhinsky]

Do you have worker_processes 1; in nginx config? Or more than one?

[misiek08]

Like @up, you have more than one worker process without auto-push.

[farfelu]

worker_processes was set to 4.
I've tried setting it to 1, but debug shows the same output.

[sergey-dryabzhinsky]

With what you try to publish? Via FFmpeg? What command options you pass?

[farfelu]

ffmpeg, using

ffmpeg -v debug -re -i test.mkv -c:v libx264 -c:a aac -ar 44100 -ac 1 -f flv -strict -2 rtmp://192.168.3.211/live/test

[farfelu]

I have tested this again on a amd64 machine with the same configuration, same build and it works without errors.
Might be a problem on arm platforms.

[sergey-dryabzhinsky]

Any luck with latest nginx, nginx-rtmp master on Pi2?

[farfelu]

yes, publishing works again with nginx 1.9.12 and master (12595a2) on debian jessie on the raspberry 2

the issue can be closed if you want to

[sergey-dryabzhinsky]

Ok. Thank you for testing.

[sergey-dryabzhinsky]

Can you check latest master? Reverted some onMetaData code.

[farfelu]

publishing still works, but clients can only connect before publishing starts, not after.

once publish started I can't connect to the stream anymore, be it a flash player or ffplay. it keeps playing for already connected clients though.

ffplay gives up after some time

RTMP_ReadPacket, failed to read RTMP packet header
rtmp://192.168.3.211/live/test: Unknown error occurred

there's no indication of what's happening in nginxs debug log.

here is ffplays debug output

Parsing... :  
Parsed protocol: 0
Parsed host    : 192.168.3.211
Parsed app     : live
RTMP_Connect1, ... connected, handshaking
HandShake: Type Answer   : 03
HandShake: Server Uptime : 56014694
HandShake: FMS Version   : 0.0.0.0
HandShake: Handshaking finished....
RTMP_Connect1, handshaked
RTMP_SendPacket: fd=648, size=169
  0000:  03 00 00 00 00 00 a9 14  00 00 00 00               ............
  0000:  02 00 07 63 6f 6e 6e 65  63 74 00 3f f0 00 00 00   ...connect.?....
  0010:  00 00 00 03 00 03 61 70  70 02 00 04 6c 69 76 65   ......app...live
  0020:  00 05 74 63 55 72 6c 02  00 19 72 74 6d 70 3a 2f   ..tcUrl...rtmp:/
  0030:  2f 31 39 32 2e 31 36 38  2e 33 2e 32 31 31 2f 6c   /192.168.3.211/l
  0040:  69 76 65 00 04 66 70 61  64 01 00 00 0c 63 61 70   ive..fpad....cap
  0050:  61 62 69 6c 69 74 69 65  73 00 40 2e 00 00 00 00   abilities.@.....
  0060:  00 00 00 0b 61 75 64 69  6f 43 6f 64 65 63 73 00   ....audioCodecs.
  0070:  40 a8 ee 00 00 00 00 00  00 0b 76 69 64 65 6f 43   @.........videoC
  0000:  c3                                                 .
  0000:  6f 64 65 63 73 00 40 6f  80 00 00 00 00 00 00 0d   odecs.@o........
  0010:  76 69 64 65 6f 46 75 6e  63 74 69 6f 6e 00 3f f0   videoFunction.?.
  0020:  00 00 00 00 00 00 00 00  09                        .........
Invoking connect
RTMP_ReadPacket: fd=648   
  0000:  02 00 00 00 00 00 04 05  00 00 00 00               ............
  0000:  00 4c 4b 40                                        .LK@
HandleServerBW: server BW = 5000000
RTMP_ReadPacket: fd=648
  0000:  02 00 00 00 00 00 05 06  00 00 00 00               ............
  0000:  00 4c 4b 40 02                                     .LK@.
HandleClientBW: client BW = 5000000 2
RTMP_ReadPacket: fd=648
  0000:  02 00 00 00 00 00 04 01  00 00 00 00               ............
  0000:  00 00 10 00                                        ....
HandleChangeChunkSize, received: chunk size change to 4096
RTMP_ReadPacket: fd=648
  0000:  03 00 00 00 00 00 be 14  00 00 00 00               ............
  0000:  02 00 07 5f 72 65 73 75  6c 74 00 3f f0 00 00 00   ..._result.?....
  0010:  00 00 00 03 00 06 66 6d  73 56 65 72 02 00 0d 46   ......fmsVer...F
  0020:  4d 53 2f 33 2c 30 2c 31  2c 31 32 33 00 0c 63 61   MS/3,0,1,123..ca
  0030:  70 61 62 69 6c 69 74 69  65 73 00 40 3f 00 00 00   pabilities.@?...
  0040:  00 00 00 00 00 09 03 00  05 6c 65 76 65 6c 02 00   .........level..
  0050:  06 73 74 61 74 75 73 00  04 63 6f 64 65 02 00 1d   .status..code...
  0060:  4e 65 74 43 6f 6e 6e 65  63 74 69 6f 6e 2e 43 6f   NetConnection.Co
  0070:  6e 6e 65 63 74 2e 53 75  63 63 65 73 73 00 0b 64   nnect.Success..d
  0080:  65 73 63 72 69 70 74 69  6f 6e 02 00 15 43 6f 6e   escription...Con
  0090:  6e 65 63 74 69 6f 6e 20  73 75 63 63 65 65 64 65   nection succeede
  00a0:  64 2e 00 0e 6f 62 6a 65  63 74 45 6e 63 6f 64 69   d...objectEncodi
  00b0:  6e 67 00 00 00 00 00 00  00 00 00 00 00 09         ng............
RTMP_ClientPacket, received: invoke 190 bytes
(object begin)
Property: <Name:           no-name., STRING:    _result>
Property: <Name:           no-name., NUMBER:    1.00>
Property: <Name:           no-name., OBJECT>
(object begin)
Property: <Name:             fmsVer, STRING:    FMS/3,0,1,123>
Property: <Name:       capabilities, NUMBER:    31.00>
(object end)
Property: <Name:           no-name., OBJECT>
(object begin)
Property: <Name:              level, STRING:    status>
Property: <Name:               code, STRING:    NetConnection.Connect.Success>
Property: <Name:        description, STRING:    Connection succeeded.>
Property: <Name:     objectEncoding, NUMBER:    0.00>
(object end)
(object end)  
HandleInvoke, server invoking <_result>
HandleInvoke, received result for method call <connect>
RTMP_SendPacket: fd=648, size=4
  0000:  02 00 00 00 00 00 04 05  00 00 00 00               ............
  0000:  00 4c 4b 40                                        .LK@
sending ctrl. type: 0x0003
RTMP_SendPacket: fd=648, size=10
  0000:  42 00 00 00 00 00 0a 04                            B.......
  0000:  00 03 00 00 00 00 00 00  01 2c                     .........,
RTMP_SendPacket: fd=648, size=25
  0000:  43 00 00 00 00 00 19 14                            C.......
  0000:  02 00 0c 63 72 65 61 74  65 53 74 72 65 61 6d 00   ...createStream.
  0010:  40 00 00 00 00 00 00 00  05                        @........
Invoking createStream
RTMP_ReadPacket: fd=648
  0000:  03 00 00 00 00 00 1d 14  00 00 00 00               ............
  0000:  02 00 07 5f 72 65 73 75  6c 74 00 40 00 00 00 00   ..._result.@....
  0010:  00 00 00 05 00 3f f0 00  00 00 00 00 00            .....?.......
RTMP_ClientPacket, received: invoke 29 bytes
(object begin)
Property: <Name:           no-name., STRING:    _result>
Property: <Name:           no-name., NUMBER:    2.00>
Property: NULL
Property: <Name:           no-name., NUMBER:    1.00>
(object end)
HandleInvoke, server invoking <_result>
HandleInvoke, received result for method call <createStream>
SendPlay, seekTime=0, stopTime=0, sending play: test
RTMP_SendPacket: fd=648, size=33
  0000:  08 00 00 00 00 00 21 14  01 00 00 00               ......!.....
  0000:  02 00 04 70 6c 61 79 00  40 08 00 00 00 00 00 00   ...play.@.......
  0010:  05 02 00 04 74 65 73 74  00 00 00 00 00 00 00 00   ....test........
  0020:  00                                                 .
Invoking play
sending ctrl. type: 0x0003
RTMP_SendPacket: fd=648, size=10
  0000:  c2                                                 .
  0000:  00 03 00 00 00 01 00 00  0b b8                     ..........
RTMP_ReadPacket: fd=648    
RTMPSockBuf_Fill, recv returned -1. GetSockError(): 10060 (Unknown error)
RTMP_ReadPacket, failed to read RTMP packet header
RTMP_SendPacket: fd=648, size=34
  0000:  43 00 00 00 00 00 22 14                            C.....".
  0000:  02 00 0c 64 65 6c 65 74  65 53 74 72 65 61 6d 00   ...deleteStream.
  0010:  40 10 00 00 00 00 00 00  05 00 3f f0 00 00 00 00   @.........?.....
  0020:  00 00                                              ..
Invoking deleteStream
rtmp://192.168.3.211/live/test: Unknown error occurred