Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

[bug] ffmpeg exiting after 9 seconds #245

Closed
streamingsystems opened this issue Sep 17, 2023 · 12 comments
Closed

[bug] ffmpeg exiting after 9 seconds #245

streamingsystems opened this issue Sep 17, 2023 · 12 comments

Comments

@streamingsystems
Copy link

streamingsystems commented Sep 17, 2023 •
edited
Loading

We are playing a MP4 file from the filesystem from ffmpeg to this module. After 9.62 seconds (on Frame 307) ffmpeg exits due to the server having a problem. I went through the server logs in debug mode and could not see any errors.

We are using ffmpeg 5 but this also happens on ffmpeg 6.

When we run this same command against Wowza the error does not happen and the file continues infinitely from ffmpeg (because it's set to loop).

This is the error from ffmpeg:

av_interleaved_write_frame(): Broken pipeB time=00:00:09.62 bitrate= 22.7kbits/s speed= 1x
[flv @ 0x7f8352907d80] Failed to update header with correct duration. 26.1kbits/s speed= 1x
[flv @ 0x7f8352907d80] Failed to update header with correct filesize.

Expected behavior (期望行为)

It should just continue to play like Wowza does.

Actual behavior (实际行为)

It fails after 9.62 seconds.

OS and Nginx version (操作系统和 Nginx 版本号)

Centos, nginx version: nginx/1.24.0

Configuration file (配置文件)

We are investing RTMP and have HLS turned on and are creating 10s TS files. I can get you the config if needed.

Steps to reproduce the behavior (复现问题步骤)

This is very easy to reproduce:

If you download this file:

https://www.dropbox.com/scl/fi/5ybita2l41tr7tyhzgy25/low.mp4?rlkey=gzahw6wp6soytuyc2185zs4ef&dl=0

If you unzip this file you will have "low.mp4".

And then run this command:

ffmpeg -stream_loop -1 -re -i low.mp4 -map 0 -c copy -f flv rtmp://127.0.0.1:1935/

You will notice ffmpeg will exit.

Error log if any (错误日志)
@streamingsystems
Copy link
Author

Good morning,

I opened a bug report with FFMPEG the other day as I was thinking this was initially a problem with FFMPEG, but it turns out ifs a bug in the server.

You can see the ffmpeg correspondence here:

https://trac.ffmpeg.org/ticket/10565

One of developers uses a RTMP server called "SRS". It looks like this bug was also in SRS that was fixed very easily last nght:

ossrs/srs#3803

Here is the specific comment on the fix:

ossrs/srs#3803 (comment)

Would it be possible for you to make this fix on your code so that we can properly use the -map command in ffmpeg as it's an import feature to ffmpeg and I would imagine anyone using ffmpeg with the -map option to send to your server will hit this error.

Thanks!

@winshining
Copy link
Owner

winshining commented Sep 19, 2023 •
edited
Loading

We are playing a MP4 file from the filesystem from ffmpeg to this module. After 9.62 seconds (on Frame 307) ffmpeg exits due to the server having a problem. I went through the server logs in debug mode and could not see any errors.

We are using ffmpeg 5 but this also happens on ffmpeg 6.

When we run this same command against Wowza the error does not happen and the file continues infinitely from ffmpeg (because it's set to loop).

This is the error from ffmpeg:

av_interleaved_write_frame(): Broken pipeB time=00:00:09.62 bitrate= 22.7kbits/s speed= 1x [flv @ 0x7f8352907d80] Failed to update header with correct duration. 26.1kbits/s speed= 1x [flv @ 0x7f8352907d80] Failed to update header with correct filesize.

Expected behavior (期望行为)

It should just continue to play like Wowza does.

Actual behavior (实际行为)

It fails after 9.62 seconds.

OS and Nginx version (操作系统和 Nginx 版本号)

Centos, nginx version: nginx/1.24.0

Configuration file (配置文件)

We are investing RTMP and have HLS turned on and are creating 10s TS files. I can get you the config if needed.

Steps to reproduce the behavior (复现问题步骤)

This is very easy to reproduce:

If you download this file:

https://www.dropbox.com/scl/fi/5ybita2l41tr7tyhzgy25/low.mp4?rlkey=gzahw6wp6soytuyc2185zs4ef&dl=0

If you unzip this file you will have "low.mp4".

And then run this command:

ffmpeg -stream_loop -1 -re -i low.mp4 -map 0 -c copy -f flv rtmp://127.0.0.1:1935/

You will notice ffmpeg will exit.

Error log if any (错误日志)

No, it is not a bug in the server. But I will make a workaround before it is fixed in FFmpeg.

winshining added a commit that referenced this issue Sep 19, 2023
@winshining
[fix] worked around the buggy option -map in FFmpeg (#245).
d978ffe
@winshining
Copy link
Owner

Fixed.

Used ffmpeg command and media as you mentioned above to test:

[flv @ 0x55ebaabcac40] Failed to update header with correct duration.358.7kbits/s speed=   1x
[flv @ 0x55ebaabcac40] Failed to update header with correct filesize.
frame=  606 fps= 30 q=-1.0 Lsize=    1674kB time=00:00:20.08 bitrate= 682.9kbits/s speed=0.999x    
video:861kB audio:785kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 1.702138%

And if you set log level above error (warn or info, for example) for directive error_log, you will see warnings like the following:

2023/09/19 18:09:52 [warn] 7535#0: *2 AMF malformed: type=0, length=4, ignored, client: 127.0.0.1, server: 0.0.0.0:1935

@streamingsystems
Copy link
Author

streamingsystems commented Sep 19, 2023 •
edited
Loading

Thank you very much for taking the time to look at this and put in a work around. As you saw above, I have a bug report open with ffmpeg.

Could you explain what the bug is in ffmpeg and I can report that back to my open bug report and have them fix it?

As you probably saw as well, the person from the ossrs RTMP server also put in a fix to address this, was his fix similar to what you did in that it's really a workaround for a bug in FFMPEG?

@winshining
Copy link
Owner

Could you explain what the bug is in ffmpeg and I can report that back to my open bug report and have them fix it?

FFmpeg sends a buggy AMF0 structure when -map option is used: the AMF type is 0x00, it means it is a number and the following 8 bytes are used to represent a number, but there are only 3 bytes left.

As you probably saw as well, the person from the ossrs RTMP server also put in a fix to address this, was his fix similar to what you did in that it's really a workaround for a bug in FFMPEG?

Yes.

@streamingsystems
Copy link
Author

streamingsystems commented Sep 20, 2023 •
edited
Loading

Hello,

I would like to make a donation to your project for all of the work you do, if I send the money to the paypal account on your GitHub will that go directly to you?

I integrated your code and for some reason I am still getting the error. When I run this command:

ffmpeg -stream_loop -1 -re -i low.mp4 -map 0 -c copy -f flv rtmp://host/stream_key

I do see your new message in our error_log:

2023/09/20 08:04:56 [warn] 2217895#2217895: *1 AMF malformed: type=0, length=4, ignored, client: 10.1.201.2, server: 0.0.0.0:1935

But right afterwards I see this:

2023/09/20 08:05:01 [error] 2217895#2217895: *1 live: drop idle publisher, client: 10.1.201.2, server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217897#2217897: *8 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217901#2217901: *14 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217898#2217898: *10 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217896#2217896: *5 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217899#2217899: *11 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217900#2217900: *15 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:05:01 [error] 2217894#2217894: *4 live: drop idle publisher, client: , server: 0.0.0.0:1935

For some reason it also shows "drop idle publisher" in the logs.

This is my ffmpeg which exits:

av_interleaved_write_frame(): Broken pipeB time=00:00:09.64 bitrate= 22.7kbits/s speed= 1x
[flv @ 0x7fbfa8007a00] Failed to update header with correct duration.
[flv @ 0x7fbfa8007a00] Failed to update header with correct filesize.
Error writing trailer of rtmp://**** (my stream key) : Broken pipe
frame= 306 fps= 30 q=-1.0 Lsize= 30kB time=00:00:10.08 bitrate= 24.0kbits/s speed= 1x
video:433kB audio:396kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
Error closing file rtmp://**** (my stream key): Broken pipe
Conversion failed!

At this point ffmpeg exits. I am running the latest ffmpeg 5 (but I tried 6 last week and it still fails).

Here is our nginx:

nginx version: nginx/1.24.0
built by gcc 8.5.0 20210514 (Red Hat 8.5.0-16) (GCC)
built with OpenSSL 1.1.1k FIPS 25 Mar 2021
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx --sbin-path=/usr/sbin/nginx --modules-path=/usr/lib64/nginx/modules --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-compat --with-file-aio --with-threads --with-http_addition_module --with-http_auth_request_module --with-http_dav_module --with-http_flv_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_mp4_module --with-http_random_index_module --with-http_realip_module --with-http_secure_link_module --with-http_slice_module --with-http_ssl_module --with-http_stub_status_module --with-http_sub_module --with-http_v2_module --with-mail --with-mail_ssl_module --with-stream --with-stream_realip_module --with-stream_ssl_module --with-stream_ssl_preread_module --with-openssl-opt=enable-ktls --with-cc-opt='-O2 -g -pipe -Wall -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2 -Wp,-D_GLIBCXX_ASSERTIONS -fexceptions -fstack-protector-strong -grecord-gcc-switches -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection -fPIC' --with-ld-opt='-Wl,-z,relro -Wl,-z,now -pie'

My nginx config for RTMP:

rtmp_auto_push on;

rtmp {

out_queue           4096;
out_cork            8;
max_streams         256;
timeout             5s;
drop_idle_publisher 5s;
respawn off;

log_interval 5s;
log_size     1m;

server {
    listen 1935;
    listen [::]:1935;

    chunk_size 4096;
    max_message 2M;

...

My nginx

user nginx;
worker_processes auto;
worker_rlimit_nofile 32768;
error_log /var/log/nginx/error.log warn;
pid /run/nginx.pid;

Load dynamic modules. See /usr/share/doc/nginx/README.dynamic.

include /usr/share/nginx/modules/*.conf;

events {
worker_connections 2048;
use epoll;
multi_accept on;
}
....

Do you have any idea why my ffmpeg would fail but yours would work?

@streamingsystems
Copy link
Author

This is interesting as your WARN message appears right when the ffmpeg process starts (see log at 8:42:20) and then 5 seconds later (8:42:25) the drop idle publisher appears (which I have set drop idle publisher set to 5 seconds in my config) and then about 5 seconds later ffmpeg fails almost like the server disconnected it or timed out (I have timeout set to 5 seconds as well if that has anything to do with this).

2023/09/20 08:42:20 [warn] 3899738#3899738: *1075 AMF malformed: type=0, length=4, ignored, client: 10.1.201.2, server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899740#3899740: *1081 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899742#3899742: *1089 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899744#3899744: *1094 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899751#3899751: *1105 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899750#3899750: *1107 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899749#3899749: *1097 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899752#3899752: *1102 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899746#3899746: *1091 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899748#3899748: *1106 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899743#3899743: *1093 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899747#3899747: *1100 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899741#3899741: *1083 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899738#3899738: *1075 live: drop idle publisher, client: 10.1.201.2, server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899745#3899745: *1088 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899739#3899739: *1079 live: drop idle publisher, client: , server: 0.0.0.0:1935
2023/09/20 08:42:25 [error] 3899737#3899737: *1077 live: drop idle publisher, client: , server: 0.0.0.0:1935

@streamingsystems
Copy link
Author

streamingsystems commented Sep 20, 2023 •
edited
Loading

I confirmed if I comment out/remove the drop_idle_publisher the ffmpeg command does not fail so for some reason my ffmpeg command is getting killed from the server when the drop idle publisher feature is on.

@winshining
Copy link
Owner

Hello,

I would like to make a donation to your project for all of the work you do, if I send the money to the paypal account on your GitHub will that go directly to you?

I think so. Thank you very much.

I integrated your code and for some reason I am still getting the error. When I run this command:

ffmpeg -stream_loop -1 -re -i low.mp4 -map 0 -c copy -f flv rtmp://host/stream_key

I do see your new message in our error_log:

2023/09/20 08:04:56 [warn] 2217895#2217895: *1 AMF malformed: type=0, length=4, ignored, client: 10.1.201.2, server: 0.0.0.0:1935

But right afterwards I see this:

2023/09/20 08:05:01 [error] 2217895#2217895: *1 live: drop idle publisher, client: 10.1.201.2, server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217897#2217897: *8 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217901#2217901: *14 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217898#2217898: *10 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217896#2217896: *5 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217899#2217899: *11 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217900#2217900: *15 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217894#2217894: *4 live: drop idle publisher, client: , server: 0.0.0.0:1935

For some reason it also shows "drop idle publisher" in the logs.

This is my ffmpeg which exits:

av_interleaved_write_frame(): Broken pipeB time=00:00:09.64 bitrate= 22.7kbits/s speed= 1x [flv @ 0x7fbfa8007a00] Failed to update header with correct duration. [flv @ 0x7fbfa8007a00] Failed to update header with correct filesize. Error writing trailer of rtmp://**** (my stream key) : Broken pipe frame= 306 fps= 30 q=-1.0 Lsize= 30kB time=00:00:10.08 bitrate= 24.0kbits/s speed= 1x video:433kB audio:396kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown Error closing file rtmp://**** (my stream key): Broken pipe Conversion failed!

I reproduced the problem by setting:

drop_idle_publisher 5s;

While

drop_idle_publisher 15s;

is OK.

Debug logs in nginx's error.log showed that FFmpeg indeed didn't send any messages in 5s after malformed AMF was sent.

drop_idle_publiser_011036

@streamingsystems
Copy link
Author

streamingsystems commented Sep 21, 2023 via email

@winshining
Copy link
Owner

Ok thanks for looking at this. I sent you money via Paypal can you confirm you received it? From: winshining @.> Date: Thursday, September 21, 2023 at 12:12 AM To: winshining/nginx-http-flv-module @.> Cc: streamingsystems @.>, Author @.> Subject: Re: [winshining/nginx-http-flv-module] [bug] ffmpeg exiting after 9 seconds (Issue #245) Hello, I would like to make a donation to your project for all of the work you do, if I send the money to the paypal account on your GitHub will that go directly to you? I think so. Thank you very much. I integrated your code and for some reason I am still getting the error. When I run this command: ffmpeg -stream_loop -1 -re -i low.mp4 -map 0 -c copy -f flv rtmp://host/stream_key I do see your new message in our error_log: 2023/09/20 08:04:56 [warn] 2217895#2217895: 1 AMF malformed: type=0, length=4, ignored, client: 10.1.201.2, server: 0.0.0.0:1935 But right afterwards I see this: 2023/09/20 08:05:01 [error] 2217895#2217895: 1 live: drop idle publisher, client: 10.1.201.2, server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217897#2217897: 8 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217901#2217901: 14 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217898#2217898: 10 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217896#2217896: 5 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217899#2217899: 11 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217900#2217900: 15 live: drop idle publisher, client: , server: 0.0.0.0:1935 2023/09/20 08:05:01 [error] 2217894#2217894: 4 live: drop idle publisher, client: , server: 0.0.0.0:1935 For some reason it also shows "drop idle publisher" in the logs. This is my ffmpeg which exits: av_interleaved_write_frame(): Broken pipeB time=00:00:09.64 bitrate= 22.7kbits/s speed= 1x [flv @ 0x7fbfa8007a00] Failed to update header with correct duration. [flv @ 0x7fbfa8007a00] Failed to update header with correct filesize. Error writing trailer of rtmp:// (my stream key) : Broken pipe frame= 306 fps= 30 q=-1.0 Lsize= 30kB time=00:00:10.08 bitrate= 24.0kbits/s speed= 1x video:433kB audio:396kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown Error closing file rtmp:// (my stream key): Broken pipe Conversion failed! I reproduced the problem by setting: drop_idle_publisher 5s; While drop_idle_publisher 15s; is OK. Debug logs in nginx's error.log showed that FFmpeg indeed didn't send any messages in 5s after malformed AMF was sent. [drop_idle_publiser_011036]https://user-images.githubusercontent.com/3250905/269492615-f5e061fd-b9d8-4015-ae39-0ffd26fe45bc.png — Reply to this email directly, view it on GitHub<#245 (comment)>, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AOI5PRK3FZYDMZTXXRNRE3DX3PEDPANCNFSM6AAAAAA434E3PA. You are receiving this because you authored the thread.Message ID: @.**>

Sorry to come back after a long time.
No, I haven't received anything. I don't know why.

winshining added a commit that referenced this issue Sep 29, 2023
@winshining
[fix] refactored (#245) and fixed a compilation error on Mac (#246).
3274d53
@streamingsystems
Copy link
Author

streamingsystems commented Sep 29, 2023 via email

@winshining winshining mentioned this issue Oct 15, 2023
Closed
Executor-Cheng added a commit to Executor-Cheng/nginx-http-flv-module that referenced this issue Nov 2, 2023
@Executor-Cheng
sync base repo (#2)
2c55897 
* [fix] fixed a crash bug resulted from 'reload'

* [fix] fixed 'proxy protocol not working' bug.

* [fix] fixed a typo.

* [fix] fixed an endian bug in mp4 vod.

* [fix] worked around the buggy option `-map` in FFmpeg.

* [fix] refactored (winshining#245) and fixed a compilation error on Mac.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@winshining @streamingsystems