Opened 5 months ago

Last modified 4 months ago

#7346 new defect

ffmpeg dying at 86400seconds

Reported by: barhom Owned by:
Priority: normal Component: undetermined
Version: unspecified Keywords:
Cc: Blocked By:
Blocking: Reproduced by developer: no
Analyzed by developer: no

Description

Hey,

I have a full 250mb report but but I will only include the most important lines.
I have a live-transcode of an incoming mpeg2-ts that I output to tee, udp and hls.
It is currently dying at exactly 86400 seconds.

You can find the first few lines here below:


ffmpeg started on 2018-07-31 at 13:15:30
Report written to "ffmpeg-20180731-131530.log"
Command line:
f_alias -analyzeduration 1000000 -i "http://X.X.X.X4048/udp/239.193.9.189:3301?auth=c15b5077988d73c1a688272a051af1b3&e=1532959888&s=7236&t=0&p=&ident=123123F987789" -map 0:0 -map 0:1 -filter:v "yadif,scale=-2:'min(576,ih)'" -c:v libx264 -preset superfast -g 50 -keyint_min 100 -sc_threshold 0 -b:v 900k -maxrate 900k -bufsize 2000k -c:a libfdk_$
ffmpeg version N-91403-gd24c9e5 Copyright (c) 2000-2018 the FFmpeg developers
  built with gcc 6.3.0 (Debian 6.3.0-18+deb9u1) 20170516
  configuration: --prefix=/home/netsat/netsat_packages/ffmpeg_build --pkg-config-flags=--static --extra-cflags=-I/home/netsat/netsat_packages/ffmpeg_build/include --extra-ldflags=-L/home/netsat/netsat_packages/ffmpeg_build/lib --extra-libs='-lpthread -lm' --bindir=/home/netsat/netsat_packages/bin --enable-gpl --enable-libass --enable-libfdk-aac $
  libavutil      56. 18.102 / 56. 18.102
  libavcodec     58. 20.104 / 58. 20.104
  libavformat    58. 17.101 / 58. 17.101
  libavdevice    58.  4.101 / 58.  4.101
  libavfilter     7. 25.100 /  7. 25.100
  libswscale      5.  2.100 /  5.  2.100
  libswresample   3.  2.100 /  3.  2.100
  libpostproc    55.  2.100 / 55.  2.100

And here below you can find the last lines:

[libx264 @ 0x55d2032cd400] frame=2160210 QP=26.62 NAL=0 Slice:B Poc:16  I:51   P:589  SKIP:980  size=2671 bytes
[libx264 @ 0x55d2032cd400] frame=2160211 QP=26.79 NAL=0 Slice:B Poc:20  I:49   P:604  SKIP:967  size=2750 bytes
[libx264 @ 0x55d2032cd400] frame=2160212 QP=26.03 NAL=2 Slice:P Poc:30  I:615  P:716  SKIP:289  size=8557 bytes
[out_0_0 @ 0x55d20328d6c0] EOF on sink link out_0_0:default.
[out_0_1 @ 0x55d203318b00] EOF on sink link out_0_1:default.
No more output streams to write to, finishing.
[libx264 @ 0x55d2032cd400] frame=2160213 QP=26.67 NAL=2 Slice:B Poc:26  I:85   P:904  SKIP:631  size=4843 bytes
[libx264 @ 0x55d2032cd400] frame=2160214 QP=26.78 NAL=0 Slice:B Poc:24  I:34   P:581  SKIP:1005 size=2560 bytes
[libx264 @ 0x55d2032cd400] frame=2160215 QP=27.08 NAL=0 Slice:B Poc:28  I:36   P:643  SKIP:941  size=2603 bytes
[libx264 @ 0x55d2032cd400] frame=2160216 QP=26.13 NAL=2 Slice:P Poc:38  I:628  P:734  SKIP:258  size=8431 bytes
[libx264 @ 0x55d2032cd400] frame=2160217 QP=26.50 NAL=2 Slice:B Poc:34  I:103  P:840  SKIP:677  size=4457 bytes
[libx264 @ 0x55d2032cd400] frame=2160218 QP=27.03 NAL=0 Slice:B Poc:32  I:72   P:707  SKIP:841  size=3022 bytes
[libx264 @ 0x55d2032cd400] frame=2160219 QP=26.70 NAL=0 Slice:B Poc:36  I:39   P:707  SKIP:874  size=2772 bytes
[libx264 @ 0x55d2032cd400] frame=2160220 QP=26.06 NAL=2 Slice:P Poc:46  I:661  P:692  SKIP:267  size=8714 bytes
[libx264 @ 0x55d2032cd400] frame=2160221 QP=26.48 NAL=2 Slice:B Poc:42  I:113  P:906  SKIP:601  size=4768 bytes
[libx264 @ 0x55d2032cd400] frame=2160222 QP=27.02 NAL=0 Slice:B Poc:40  I:41   P:721  SKIP:858  size=2620 bytes
[libx264 @ 0x55d2032cd400] frame=2160223 QP=26.91 NAL=0 Slice:B Poc:44  I:46   P:790  SKIP:784  size=3131 bytes
[libx264 @ 0x55d2032cd400] frame=2160224 QP=26.47 NAL=2 Slice:P Poc:54  I:657  P:705  SKIP:258  size=9143 bytes
[libx264 @ 0x55d2032cd400] frame=2160225 QP=26.49 NAL=2 Slice:B Poc:50  I:137  P:960  SKIP:523  size=5323 bytes
[libx264 @ 0x55d2032cd400] frame=2160226 QP=26.67 NAL=0 Slice:B Poc:48  I:45   P:796  SKIP:779  size=3266 bytes
[libx264 @ 0x55d2032cd400] frame=2160227 QP=27.16 NAL=0 Slice:B Poc:52  I:52   P:788  SKIP:780  size=3405 bytes
[libx264 @ 0x55d2032cd400] frame=2160228 QP=26.32 NAL=2 Slice:P Poc:62  I:676  P:705  SKIP:239  size=9587 bytes
[libx264 @ 0x55d2032cd400] frame=2160229 QP=26.76 NAL=2 Slice:B Poc:58  I:88   P:998  SKIP:534  size=5147 bytes
[libx264 @ 0x55d2032cd400] frame=2160230 QP=27.38 NAL=0 Slice:B Poc:56  I:56   P:901  SKIP:663  size=3947 bytes
[libx264 @ 0x55d2032cd400] frame=2160231 QP=27.31 NAL=0 Slice:B Poc:60  I:144  P:703  SKIP:773  size=4801 bytes
[libfdk_aac @ 0x55d2032c8140] Trying to remove 768 more samples than there are in the queue
[AVIOContext @ 0x55d2032804c0] Statistics: 0 seeks, 11375675 writeouts
[AVIOContext @ 0x55d2032b6500] Statistics: 0 seeks, 1 writeouts
[hls muxer @ 0x55d2036db340] deleting old segment playlist1533086124.ts
[hls @ 0x55d2036dac80] Opening '/tmp/deleteme/7236_0_45c7ad8444/playlist.m3u8.tmp' for writing
[file @ 0x55d2032b6900] Setting default whitelist 'file,crypto'
EXT-X-MEDIA-SEQUENCE:1533086126
[AVIOContext @ 0x55d2032806c0] Statistics: 0 seeks, 1 writeouts
frame=2160232 fps= 25 q=-1.0 Lsize=N/A time=24:00:09.20 bitrate=N/A dup=366 drop=0 speed=   1x
video:9384589kB audio:674623kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
Input file #0 (http://X.X.X.X:4048/udp/239.193.9.189:3301?auth=c15b5077988d73c1a688272a051af1b3&e=1532959888&s=7236&t=0&p=&ident=123123F987789):
  Input stream #0:0 (video): 2159898 packets read (29347951333 bytes); 2159866 frames decoded;
  Input stream #0:1 (audio): 3598958 packets read (2073337536 bytes); 3597986 frames decoded (4144879872 samples);
  Total: 5758856 packets (31421288869 bytes) demuxed
Output file #0 ([f=mpegts]udp://239.240.0.141:3302?buffer_size=1316&pkt_size=1316|[f=hls:hls_time=2.0:hls_list_size=10:hls_start_number_source=epoch:hls_flags=delete_segments+discont_start+program_date_time]/tmp/deleteme/7236_0_45c7ad8444/playlist.m3u8):
  Output stream #0:0 (video): 2160232 frames encoded; 2160232 packets muxed (9609818740 bytes);
  Output stream #0:1 (audio): 4047735 frames encoded (4144879872 samples); 4047737 packets muxed (690814275 bytes);
  Total: 6207969 packets (10300633015 bytes) muxed
5757852 frames successfully decoded, 974 decoding errors
[libx264 @ 0x55d2032cd400] frame I:43205 Avg QP:19.65  size: 30194
[libx264 @ 0x55d2032cd400] frame P:607683 Avg QP:22.67  size:  7468
[libx264 @ 0x55d2032cd400] frame B:1509344 Avg QP:24.05  size:  2496
[libx264 @ 0x55d2032cd400] consecutive B-frames:  4.4%  5.2%  6.1% 84.3%
[libx264 @ 0x55d2032cd400] mb I  I16..4: 20.5% 33.0% 46.6%
[libx264 @ 0x55d2032cd400] mb P  I16..4:  6.2% 12.7%  3.5%  P16..4: 42.2%  0.0%  0.0%  0.0%  0.0%    skip:35.5%
[libx264 @ 0x55d2032cd400] mb B  I16..4:  1.0%  1.5%  0.2%  B16..8: 20.2%  0.0%  0.0%  direct:11.4%  skip:65.6%  L0:36.4% L1:47.1% BI:16.5%
[libx264 @ 0x55d2032cd400] 8x8 transform intra:51.9% inter:46.2%
[libx264 @ 0x55d2032cd400] coded y,uvDC,uvAC intra: 51.5% 55.5% 18.7% inter: 9.1% 11.3% 0.2%
[libx264 @ 0x55d2032cd400] i16 v,h,dc,p: 51% 26% 12% 12%
[libx264 @ 0x55d2032cd400] i8 v,h,dc,ddl,ddr,vr,hd,vl,hu: 23% 15% 19%  7%  6%  9%  6%  8%  7%
[libx264 @ 0x55d2032cd400] i4 v,h,dc,ddl,ddr,vr,hd,vl,hu: 29% 19% 11%  8%  6%  8%  6%  7%  7%
[libx264 @ 0x55d2032cd400] i8c dc,h,v,p: 39% 22% 27% 11%
[libx264 @ 0x55d2032cd400] Weighted P-Frames: Y:1.9% UV:0.9%
[libx264 @ 0x55d2032cd400] kb/s:889.70
[AVIOContext @ 0x55d203242680] Statistics: 32918185804 bytes read, 0 seeks

Anyone know why the transcode is dying at exactly 86400 seconds?

Change History (3)

comment:1 follow-up: Changed 5 months ago by cehoyos

Please provide your command line together with the complete, uncut default output (instead of the huge verbose output).

comment:2 in reply to: ↑ 1 Changed 5 months ago by barhom

Replying to cehoyos:

Please provide your command line together with the complete, uncut default output (instead of the huge verbose output).

I always try to give as much detail as I believe is necessary. The log for this issue is quite long, the issue doesn't appear until the process has been running for 86400seconds. I really doubt you are interested in the entire log.

You can find the complete command below, sorry I accidentally omitted it in the first post.

f_alias -analyzeduration 1000000 -i "http://X.X.X.X:4048/udp/239.193.9.189:3301?auth=c15b5077988d73c1a688272a051af1b3&e=1532959888&s=7236&t=0&p=&ident=123123F987789" \
-map 0:0 -map 0:1 -filter:v "yadif,scale=-2:'min(576,ih)'" \
-c:v libx264 -preset superfast -g 50 -keyint_min 100 -sc_threshold 0 \
-b:v 900k -maxrate 900k -bufsize 2000k -c:a libfdk_aac -b:a 64k \
-nostats -metadata "chan_id=281" -metadata "src_id=7236" \
-metadata "timeshift=0" -metadata "profile_str=45c7ad8444" \
-metadata "mcast_ip_in=239.193.9.189" \
-metadata "mcast_port_in=3301" -metadata "mcast_ip_out=239.240.0.141" \
-metadata "mcast_port_out=3301" -f tee \
"[f=mpegts]udp://239.240.0.141:3302?buffer_size=1316&pkt_size=1316|[f=hls:hls_time=2.0:hls_list_size=10:hls_start_number_source=epoch:hls_flags=delete_segments+discont_start+program_date_time]/tmp/deleteme/7236_0_45c7ad8444/playlist.m3u8" \
-report

I am curently re-running the 24hr transcode job without the tee muxer to see if the tee muxer has the limit of 86400seconds. Will report back in a day.

comment:3 Changed 4 months ago by barhom

Reran with the following command:

f_alias -analyzeduration 1000000 -i "http://X.X.X.X:4048/udp/239.193.9.189:3301?auth=c15b5077988d73c1a688272a051af1b3&e=1532959888&s=7236&t=0&p=&ident=123123F987789" -map 0:0 -map 0:1 -filter:v "yadif,scale=-2:'min(576,ih)'" -c:v libx264 -preset superfast -g 50 -keyint_min 100 -sc_threshold 0 -b:v 900k -maxrate 900k -bufsize 2000k -c:a libfdk_aac -b:a 64k -nostats -metadata chan_id=281 -metadata src_id=7236 -metadata timeshift=0 -metadata profile_str=45c7ad8444 -metadata mcast_ip_in=239.193.9.189 -metadata mcast_port_in=3301 -metadata mcast_ip_out=239.240.0.141 -metadata mcast_port_out=3301 -hls_time 2 -hls_list_size 10 -hls_start_number_source epoch -hls_flags delete_segments+discont_start+program_date_time -f hls /tmp/deleteme/7236_0_45c7ad8444/playlist.m3u8 -report

This time the transcode job was not using the tee muxer but only the HLS output.
Still died at 86400 seconds and I see the same lines in the end.

[out_0_0 @ 0x561500ed3900] EOF on sink link out_0_0:default.
[out_0_1 @ 0x561500e380c0] EOF on sink link out_0_1:default.
No more output streams to write to, finishing.

Can anyone give any kind of insight?

Note: See TracTickets for help on using tickets.