search

arut / nginx-ts-module

NGINX MPEG-TS Live Module
BSD 2-Clause "Simplified" License
422 stars 91 forks source link

'Too big PAT' - gstreamer to nginx-ts-module #23

Closed bomba5 closed 6 years ago

bomba5 commented 6 years ago

Using given example 'nginx.conf' and this gstreamer pipeline:

$ gst-launch-1.0 -v \
    rpicamsrc ! video/x-h264,width=320,height=240,framerate=8/1 ! \
    h264parse ! mpegtsmux ! curlhttpsink location=http://192.168.128.114:8000/publish/test

Fails saying: '[..] failed to transfer data: Failed sending data to the peer.'

$ cat /var/log/nginx/error.log
2017/11/30 11:59:01 [error] 159#0: *5 too big PAT: 3504, client: 192.168.128.114, server: , request: 
"POST /publish/test HTTP/1.1", host: "192.168.128.114:8000"

Any advice?
bomba5 commented 6 years ago 
$ ffmpeg -re -i life.mp4 -bsf:v h264_mp4toannexb \  
    -c:v copy -c:a copy -f mpegts http://192.168.128.114:8000/publish/test

Fails with 'av_interleaved_write_frame(): Broken pipe'.
Same error as before on nginx error.log.

bomba5 commented 6 years ago

ngx_ts_stream.c: around line 486, is where the condition fails.
I've tried to stream from many different sources. The issue still remains.

We're running on ARMv6 - Yocto 'rocko' - may this be a Type issue?

arut commented 6 years ago

@bomba5 does this happen with every stream you publish?

bomba5 commented 6 years ago

it does.

arut commented 6 years ago

Can you enable debug logging and post debug messages prior to the error?

bomba5 commented 6 years ago

Sorry, it took a while to cross-compile with the right config.

Here you go:

nginx version: nginx/1.12.1
built with OpenSSL 1.0.2l  25 May 2017
TLS SNI support enabled
configure arguments: 

--crossbuild=Linux:arm 
--with-endian=big 
--with-int=4 
--with-long=4 
--with-long-long=8 
--with-ptr-size=4 
--with-sig-atomic-t=4 
--with-size-t=4 
--with-off-t=4 
--with-time-t=4 
--with-sys-nerr=132 
--conf-path=/etc/nginx/nginx.conf 
--http-log-path=/var/log/nginx/access.log 
--error-log-path=/var/log/nginx/error.log 
--http-client-body-temp-path=/run/nginx/client_body_temp 
--http-proxy-temp-path=/run/nginx/proxy_temp 
--http-fastcgi-temp-path=/run/nginx/fastcgi_temp 
--http-uwsgi-temp-path=/run/nginx/uwsgi_temp 
--http-scgi-temp-path=/run/nginx/scgi_temp 
--pid-path=/run/nginx/nginx.pid 
--prefix=/usr 
--with-http_ssl_module 
--with-http_gzip_static_module 
--add-module=nginx/1.12.1-r0/nginx-ts-module 
--with-debug
2017/11/29 02:23:55 [notice] 262#0: signal process started
2017/11/29 02:23:55 [debug] 264#0: bind() 0.0.0.0:8000 #6 
2017/11/29 02:23:55 [notice] 264#0: using the "epoll" event method
2017/11/29 02:23:55 [debug] 264#0: counter: B6FDB080, 1
2017/11/29 02:23:55 [notice] 264#0: nginx/1.12.1
2017/11/29 02:23:55 [notice] 264#0: OS: Linux 4.9.50
2017/11/29 02:23:55 [notice] 264#0: getrlimit(RLIMIT_NOFILE): 1024:4096
2017/11/29 02:23:55 [debug] 265#0: write: 7, BEA29AF8, 4, 0
2017/11/29 02:23:55 [debug] 265#0: setproctitle: "nginx: master process /usr/sbin/nginx"
2017/11/29 02:23:55 [notice] 265#0: start worker processes
2017/11/29 02:23:55 [debug] 265#0: channel 3:7
2017/11/29 02:23:55 [notice] 265#0: start worker process 266
2017/11/29 02:23:55 [debug] 265#0: channel 8:9
2017/11/29 02:23:55 [notice] 265#0: start cache manager process 267
2017/11/29 02:23:55 [debug] 265#0: pass channel s:1 pid:267 fd:8 to s:0 pid:266 fd:3
2017/11/29 02:23:55 [debug] 265#0: sigsuspend
2017/11/29 02:23:55 [debug] 266#0: add cleanup: 00D91120
2017/11/29 02:23:55 [debug] 266#0: malloc: 00D7E600:4
2017/11/29 02:23:55 [debug] 266#0: notify eventfd: 9
2017/11/29 02:23:55 [debug] 266#0: testing the EPOLLRDHUP flag: success
2017/11/29 02:23:55 [debug] 266#0: malloc: 00D82B70:8192
2017/11/29 02:23:55 [debug] 266#0: malloc: 00D943D8:65536
2017/11/29 02:23:55 [debug] 266#0: malloc: 00DA43E0:24576
2017/11/29 02:23:55 [debug] 266#0: malloc: 00DAA3E8:24576
2017/11/29 02:23:55 [debug] 266#0: epoll add event: fd:6 op:1 ev:00002001
2017/11/29 02:23:55 [debug] 266#0: epoll add event: fd:7 op:1 ev:00002001
2017/11/29 02:23:55 [debug] 266#0: setproctitle: "nginx: worker process"
2017/11/29 02:23:55 [debug] 266#0: worker cycle
2017/11/29 02:23:55 [debug] 266#0: epoll timer: -1
2017/11/29 02:23:55 [debug] 266#0: epoll: fd:7 ev:0001 d:00D94458
2017/11/29 02:23:55 [debug] 266#0: channel handler
2017/11/29 02:23:55 [debug] 266#0: channel: 16
2017/11/29 02:23:55 [debug] 266#0: channel command: 1
2017/11/29 02:23:55 [debug] 266#0: get channel s:1 pid:267 fd:3
2017/11/29 02:23:55 [debug] 266#0: channel: -2
2017/11/29 02:23:55 [debug] 266#0: timer delta: 38
2017/11/29 02:23:55 [debug] 266#0: worker cycle
2017/11/29 02:23:55 [debug] 266#0: epoll timer: -1
2017/11/29 02:23:55 [debug] 267#0: close listening 0.0.0.0:8000 #6 
2017/11/29 02:23:55 [debug] 267#0: add cleanup: 00D91120
2017/11/29 02:23:55 [debug] 267#0: malloc: 00D7E600:4
2017/11/29 02:23:55 [debug] 267#0: notify eventfd: 10
2017/11/29 02:23:55 [debug] 267#0: testing the EPOLLRDHUP flag: success
2017/11/29 02:23:55 [debug] 267#0: malloc: 00D82B70:8192
2017/11/29 02:23:55 [debug] 267#0: malloc: 00D943D8:65536
2017/11/29 02:23:55 [debug] 267#0: malloc: 00DA43E0:24576
2017/11/29 02:23:55 [debug] 267#0: malloc: 00DAA3E8:24576
2017/11/29 02:23:55 [debug] 267#0: epoll add event: fd:9 op:1 ev:00002001
2017/11/29 02:23:55 [debug] 267#0: setproctitle: "nginx: cache manager process"
2017/11/29 02:23:55 [debug] 267#0: event timer add: -1: 0:93747226
2017/11/29 02:23:55 [debug] 267#0: epoll timer: 0
2017/11/29 02:23:55 [debug] 267#0: timer delta: 66
2017/11/29 02:23:55 [debug] 267#0: event timer del: -1: 93747226
2017/11/29 02:23:55 [debug] 267#0: ts hls file manager
2017/11/29 02:23:55 [debug] 267#0: walk tree "/var/media/hls"
2017/11/29 02:23:55 [debug] 267#0: tree name 2:".."
2017/11/29 02:23:55 [debug] 267#0: tree name 1:"."
2017/11/29 02:23:55 [debug] 267#0: ts dash file manager
2017/11/29 02:23:55 [debug] 267#0: walk tree "/var/media/dash"
2017/11/29 02:23:55 [debug] 267#0: tree name 2:".."
2017/11/29 02:23:55 [debug] 267#0: tree name 1:"."
2017/11/29 02:23:55 [debug] 267#0: event timer add: -1: 120000:93867293
2017/11/29 02:23:55 [debug] 267#0: epoll timer: 120000
2017/11/29 02:24:26 [debug] 266#0: epoll: fd:6 ev:0001 d:00D943D8
2017/11/29 02:24:26 [debug] 266#0: accept on 0.0.0.0:8000, ready: 0
2017/11/29 02:24:26 [debug] 266#0: posix_memalign: 00D7E740:256 @16
2017/11/29 02:24:26 [debug] 266#0: *1 accept: 127.0.0.1:45616 fd:10
2017/11/29 02:24:26 [debug] 266#0: *1 event timer add: 10: 60000:93837910
2017/11/29 02:24:26 [debug] 266#0: *1 reusable connection: 1
2017/11/29 02:24:26 [debug] 266#0: *1 epoll add event: fd:10 op:1 ev:80002001
2017/11/29 02:24:26 [debug] 266#0: timer delta: 30646
2017/11/29 02:24:26 [debug] 266#0: worker cycle
2017/11/29 02:24:26 [debug] 266#0: epoll timer: 60000
2017/11/29 02:24:26 [debug] 266#0: epoll: fd:10 ev:0001 d:00D944D8
2017/11/29 02:24:26 [debug] 266#0: *1 http wait request handler
2017/11/29 02:24:26 [debug] 266#0: *1 malloc: 00D87738:1024
2017/11/29 02:24:26 [debug] 266#0: *1 recv: eof:0, avail:1
2017/11/29 02:24:26 [debug] 266#0: *1 recv: fd:10 145 of 1024
2017/11/29 02:24:26 [debug] 266#0: *1 reusable connection: 0
2017/11/29 02:24:26 [debug] 266#0: *1 posix_memalign: 00D84B90:4096 @16
2017/11/29 02:24:26 [debug] 266#0: *1 http process request line
2017/11/29 02:24:26 [debug] 266#0: *1 http request line: "POST /publish/media HTTP/1.1"
2017/11/29 02:24:26 [debug] 266#0: *1 http uri: "/publish/media"
2017/11/29 02:24:26 [debug] 266#0: *1 http args: ""
2017/11/29 02:24:26 [debug] 266#0: *1 http exten: ""
2017/11/29 02:24:26 [debug] 266#0: *1 http process request header line
2017/11/29 02:24:26 [debug] 266#0: *1 http header: "Host: 127.0.0.1:8000"
2017/11/29 02:24:26 [debug] 266#0: *1 http header: "Accept: */*"
2017/11/29 02:24:26 [debug] 266#0: *1 http header: "Transfer-Encoding: chunked"
2017/11/29 02:24:26 [debug] 266#0: *1 http header: "Content-Type: video/mpegts"
2017/11/29 02:24:26 [debug] 266#0: *1 http header: "Expect: 100-continue"
2017/11/29 02:24:26 [debug] 266#0: *1 http header done
2017/11/29 02:24:26 [debug] 266#0: *1 event timer del: 10: 93837910
2017/11/29 02:24:26 [debug] 266#0: *1 rewrite phase: 0
2017/11/29 02:24:26 [debug] 266#0: *1 test location: "/"
2017/11/29 02:24:26 [debug] 266#0: *1 test location: "publish/"
2017/11/29 02:24:26 [debug] 266#0: *1 using configuration "/publish/"
2017/11/29 02:24:26 [debug] 266#0: *1 http cl:-1 max:0
2017/11/29 02:24:26 [debug] 266#0: *1 rewrite phase: 2
2017/11/29 02:24:26 [debug] 266#0: *1 post rewrite phase: 3
2017/11/29 02:24:26 [debug] 266#0: *1 generic phase: 4
2017/11/29 02:24:26 [debug] 266#0: *1 generic phase: 5
2017/11/29 02:24:26 [debug] 266#0: *1 access phase: 6
2017/11/29 02:24:26 [debug] 266#0: *1 access phase: 7
2017/11/29 02:24:26 [debug] 266#0: *1 post access phase: 8
2017/11/29 02:24:26 [debug] 266#0: *1 ts hls create
2017/11/29 02:24:26 [debug] 266#0: *1 add cleanup: 00D85400
2017/11/29 02:24:26 [debug] 266#0: *1 ts dash create
2017/11/29 02:24:26 [debug] 266#0: *1 add cleanup: 00D854B0
2017/11/29 02:24:26 [debug] 266#0: *1 send 100 Continue
2017/11/29 02:24:26 [debug] 266#0: *1 send: fd:10 25 of 25
2017/11/29 02:24:26 [debug] 266#0: *1 http request body chunked filter
2017/11/29 02:24:26 [debug] 266#0: *1 malloc: 00DB03F0:8192
2017/11/29 02:24:26 [debug] 266#0: *1 http read client request body
2017/11/29 02:24:26 [debug] 266#0: *1 recv: eof:0, avail:0
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body recv -2
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body rest 3
2017/11/29 02:24:26 [debug] 266#0: *1 event timer add: 10: 60000:93837912
2017/11/29 02:24:26 [debug] 266#0: *1 ts read
2017/11/29 02:24:26 [debug] 266#0: *1 http finalize request: -4, "/publish/media?" a:1, c:2
2017/11/29 02:24:26 [debug] 266#0: *1 http request count:2 blk:0
2017/11/29 02:24:26 [debug] 266#0: timer delta: 2
2017/11/29 02:24:26 [debug] 266#0: worker cycle
2017/11/29 02:24:26 [debug] 266#0: epoll timer: 60000
2017/11/29 02:24:26 [debug] 266#0: epoll: fd:10 ev:0001 d:00D944D8
2017/11/29 02:24:26 [debug] 266#0: *1 http run request: "/publish/media?"
2017/11/29 02:24:26 [debug] 266#0: *1 http read client request body
2017/11/29 02:24:26 [debug] 266#0: *1 recv: eof:0, avail:1
2017/11/29 02:24:26 [debug] 266#0: *1 recv: fd:10 3 of 3
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body recv 3
2017/11/29 02:24:26 [debug] 266#0: *1 http body chunked buf t:1 f:0 00DB03F0, pos 00DB03F0, size: 3 file: 0, size: 0
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 62 s:0
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 63 s:1
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 0D s:1
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body rest 193
2017/11/29 02:24:26 [debug] 266#0: *1 recv: eof:0, avail:1
2017/11/29 02:24:26 [debug] 266#0: *1 recv: fd:10 191 of 193
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body recv 191
2017/11/29 02:24:26 [debug] 266#0: *1 http client request body rest 193
2017/11/29 02:24:26 [debug] 266#0: *1 http body chunked buf t:1 f:0 00DB03F0, pos 00DB03F3, size: 191 file: 0, size: 0
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 0A s:3
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 47 s:4
2017/11/29 02:24:26 [debug] 266#0: *1 http body chunked buf t:1 f:0 00DB03F0, pos 00DB04B0, size: 2 file: 0, size: 0
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 0D s:5
2017/11/29 02:24:26 [debug] 266#0: *1 http chunked byte: 0A s:6
2017/11/29 02:24:26 [debug] 266#0: *1 http body new buf t:1 f:0 00DB03F4, pos 00DB03F4, size: 188 file: 0, size: 0
2017/11/29 02:24:26 [debug] 266#0: *1 event timer: 10, old: 93837912, new: 93837915
2017/11/29 02:24:26 [debug] 266#0: *1 ts read
2017/11/29 02:24:26 [debug] 266#0: *1 ts packet pid:0x0000, pusi:1, c:00, r:0, pcr:0, n:17
2017/11/29 02:24:26 [debug] 266#0: *1 ts pat
2017/11/29 02:24:26 [error] 266#0: *1 too big PAT: 3504, client: 127.0.0.1, server: , request: "POST /publish/media HTTP/1.1", host: "127.0.0.1:8000"
2017/11/29 02:24:26 [debug] 266#0: *1 http finalize request: -1, "/publish/media?" a:1, c:1
2017/11/29 02:24:26 [debug] 266#0: *1 http terminate request count:1
2017/11/29 02:24:26 [debug] 266#0: *1 http terminate cleanup count:1 blk:0
2017/11/29 02:24:26 [debug] 266#0: *1 http posted request: "/publish/media?"
2017/11/29 02:24:26 [debug] 266#0: *1 http terminate handler count:1
2017/11/29 02:24:26 [debug] 266#0: *1 http request count:1 blk:0
2017/11/29 02:24:26 [debug] 266#0: *1 http close request
2017/11/29 02:24:26 [debug] 266#0: *1 http log handler
2017/11/29 02:24:26 [debug] 266#0: *1 run cleanup: 00D854B0
2017/11/29 02:24:26 [debug] 266#0: *1 ts dash cleanup
2017/11/29 02:24:26 [debug] 266#0: *1 run cleanup: 00D85400
2017/11/29 02:24:26 [debug] 266#0: *1 ts hls cleanup
2017/11/29 02:24:26 [debug] 266#0: *1 free: 00DB03F0
2017/11/29 02:24:26 [debug] 266#0: *1 free: 00D84B90, unused: 1102
2017/11/29 02:24:26 [debug] 266#0: *1 close http connection: 10
2017/11/29 02:24:26 [debug] 266#0: *1 event timer del: 10: 93837912
2017/11/29 02:24:26 [debug] 266#0: *1 reusable connection: 0
2017/11/29 02:24:26 [debug] 266#0: *1 free: 00D87738
2017/11/29 02:24:26 [debug] 266#0: *1 free: 00D7E740, unused: 8
2017/11/29 02:24:26 [debug] 266#0: timer delta: 3
2017/11/29 02:24:26 [debug] 266#0: worker cycle
2017/11/29 02:24:26 [debug] 266#0: epoll timer: -1
2017/11/29 02:25:55 [debug] 267#0: timer delta: 120081
arut commented 6 years ago

Well, I think the problem is endianness. Is your server big-endian? And what does nginx say when you configure it?

auto/configure ...|grep order
bomba5 commented 6 years ago 
checking for system byte ordering ... big endian

Wich makes no sense to me, we're cross compiling for an ARM processor

arut commented 6 years ago

This should be the endianness of the target platform. ARMv6 can be both big-endian and little-endian. So make sure you have the right endianness when cross-compiling and running the code.

bomba5 commented 6 years ago

Well this is actually quite strange because the whole rest of the system gets cross-compiled with the right endianness set!

Just a quick check on a target machine with the running system:

Python 2.7.13 (default, Nov 29 2017, 05:20:18) 
[GCC 7.2.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> from sys import byteorder
>>> print (byteorder)
little

I've forced passing --with-endian=little to the configure

# nginx -V
nginx version: nginx/1.12.1
built with OpenSSL 1.0.2l  25 May 2017
TLS SNI support enabled
configure arguments: --crossbuild=Linux:arm --with-endian=little

But the configure log still says:

checking for system byte ordering ... big endian
bomba5 commented 6 years ago

I'm closing this anyways. This issue is somewhere related to Yocto, meta-raspberrypi layer, nginx bitbake recipe or nginx configure itself - not to nginx-ts-module.

Moving the topic to the correct tracker