Opened 4 years ago

Last modified 4 years ago

#8546 open defect

http_persistent not honored when encryption is enabled

Reported by: vschweitzer Owned by: Steven Liu
Priority: normal Component: avformat
Version: git-master Keywords: http
Cc: liuqi05@kuaishou.com Blocked By:
Blocking: Reproduced by developer: no
Analyzed by developer: no

Description

Enabling http_persistent and encryption in the hls muxer leads to HTTP
connections that multiple Web servers cannot deal with properly.
In particular, ffmpeg sends HTTP PUT requests with a "Connection: keep-alive"
header for each segment file, but it closes the connection right
afterwards and opens a new one for the next segment. This behavior can
be observed with Wireshark and multiple different Web servers,
e.g., Apache, Kestrel and tornado.

Using the most recent zeranoe build of ffmpeg for 64-bit Windows,

.\ffmpeg -y -hide_banner -f lavfi -i color=c=black:s=1920x1080:r=25 -vcodec libx264 -f hls -hls_segment_type mpegts -hls_time 0.04 -hls_list_size 100 -hls_flags second_level_segment_index+split_by_time+program_date_time -hls_init_time 0.04 -http_persistent 1 -strftime 1 -hls_segment_filename http://127.0.0.1:45000/%%18d.ts -hls_enc 1 -hls_enc_key fedcba9876543210 -hls_enc_iv fedcba9876543210 -method PUT http://127.0.0.1:45000/index.m3u8

shows the described behavior of connections being closed despite
http_persistent being enabled and keep-alive being sent. With loglevel
debug, it is visible that a connection is started for each segment,
but the closing of the connection is only implicitly visible due to
the statistics being printed (the closing can be seen more clearly
with the FIN ACK in Wireshark):

[...]
[hls @ 000001cf588da0c0] Opening 'crypto:http://127.0.0.1:45000/streams/-/data/1080p/000000000000000011.ts' for writing
[crypto @ 000001cf588e6f80] No default whitelist set
[http @ 000001cf588e6180] Setting default whitelist 'http,https,tls,rtp,tcp,udp,crypto,httpproxy'
[tcp @ 000001cf588e7540] Original list of addresses:
[tcp @ 000001cf588e7540] Address 127.0.0.1 port 45000
[tcp @ 000001cf588e7540] Interleaved list of addresses:
[tcp @ 000001cf588e7540] Address 127.0.0.1 port 45000
[tcp @ 000001cf588e7540] Starting connection attempt to 127.0.0.1 port 45000
[tcp @ 000001cf588e7540] Successfully connected to 127.0.0.1 port 45000
[http @ 000001cf588e6180] request: PUT /streams/-/data/1080p/000000000000000011.ts HTTP/1.1
Transfer-Encoding: chunked
User-Agent: Lavf/58.35.100
Accept: */*
Connection: keep-alive
Host: 127.0.0.1:45000
Icy-MetaData: 1

[AVIOContext @ 000001cf59a466c0] Statistics: 0 seeks, 1 writeouts
[hls @ 000001cf588da0c0] Opening 'http://127.0.0.1:45000/streams/-/data/1080p/index.m3u8' for writing
[...]

The opening and closing of each connection can also be observed by
inserting an av_log message in hlsenc.c in function hlsenc_io_open
after s->io_open and in function hlsenc_io_close after
ff_format_io_close.

When encryption is disabled,

.\ffmpeg -y -hide_banner -f lavfi -i color=c=black:s=1920x1080:r=25 -vcodec libx264 -f hls -hls_segment_type mpegts -hls_time 0.04 -hls_list_size 100 -hls_flags second_level_segment_index+split_by_time+program_date_time -hls_init_time 0.04 -http_persistent 1 -strftime 1 -hls_segment_filename http://127.0.0.1:45000/%%18d.ts -method PUT http://127.0.0.1:45000/index.m3u8

the connection is left open as it should be. This is also
visible with loglevel debug (note the missing statistics
for the closed connection):

[...]
[http @ 000001f9bd0e7880] Opening 'http://127.0.0.1:45000/streams/-/data/1080p/000000000000000011.ts' for writing
[http @ 000001f9ba626d40] request: PUT /streams/-/data/1080p/000000000000000011.ts HTTP/1.1
Transfer-Encoding: chunked
User-Agent: Lavf/58.35.100
Accept: */*
Connection: keep-alive
Host: 127.0.0.1:45000
Icy-MetaData: 1

[http @ 000001f9bd0e7880] Opening 'http://127.0.0.1:45000/streams/-/data/1080p/index.m3u8' for writing
[...]

This difference in behavior was tested with multiple versions; for ease
of testing, prebuilt versions by Zeranoe were used.
(https://ffmpeg.zeranoe.com/builds/win64/static/)

Version built on Status
f60b1212019-08-01OK
6c67c8c2019-08-06OK
3aeb6812019-08-15OK
c294f382019-08-16OK - Latest OK version
19651612019-08-18Error - Earliest version with error
cff30902019-08-18Error
661a9b22019-08-21Error
0821bc42019-08-26Error
bc9b6352020-02-24Error

As cff3090 is the parent commit of 1965161, it seems probable
that cff3090 is the offending commit. As http_persistent worked in
earlier versions, this appears to be a regression.

To reproduce

This issue should be reproducible using any HTTP server. Different
servers react differently to this behavior; here is what we observed:

Server Behavior
Kestrel (.NET)TCP reset exception, but receives all packets
Tornado (Python3)Random packets are lost without error

For easier testing, a basic HTTP server using tornado is provided.
This server keeps track of every received segment and outputs any lost
segments on localhost:<port>/status.

The Python script takes one optional argument, which specifies the port
to connect to. The default is 45000. The oldest tested Python version
is 3.7.3.

The first lost segment can appear as early as of segment 500. After
2000 segments at least one is lost with relative certainty. If after
10000 segments no single one is lost, it can be assumed that the error
does not occur.

To summarize:

  1. Start the Python script using Python 3.7 and (optionally) specfiy a port.
  2. Start FFmpeg with the command listed above, with the port number corrected.
  3. Wait until at least one segment is lost or until segment 10000.

Attachments (3)

tornado_test.py (1.2 KB ) - added by vschweitzer 4 years ago.
Tornado HTTP server example
ffmpeg-20200302-153814.zip (94.3 KB ) - added by vschweitzer 4 years ago.
Logfile generated by -report. Execution was stopped after the first three segments were lost ([275, 1281, 1398])
console_output.txt (167.5 KB ) - added by vschweitzer 4 years ago.
Console output belonging to the attached logfile.

Download all attachments as: .zip

Change History (8)

comment:1 by Carl Eugen Hoyos, 4 years ago

Keywords: http_persistent hls encryption removed

Please test current FFmpeg git head, remove -hide_banner from your command line and provide the command line you tested together with the complete, uncut console output to make this a valid ticket.

by vschweitzer, 4 years ago

Attachment: tornado_test.py added

Tornado HTTP server example

by vschweitzer, 4 years ago

Attachment: ffmpeg-20200302-153814.zip added

Logfile generated by -report. Execution was stopped after the first three segments were lost ([275, 1281, 1398])

by vschweitzer, 4 years ago

Attachment: console_output.txt added

Console output belonging to the attached logfile.

comment:2 by vschweitzer, 4 years ago

Log generated by -report and console output is uploaded for the latest zeranoe build.

comment:3 by Steven Liu, 4 years ago

Cc: liuqi05@kuaishou.com added
Owner: set to Steven Liu
Status: newopen

ffmpeg hlsenc support crypto+http protocol, but the protocol is crypto first, it is not http prtocol first, let me think about how to fix it.

comment:4 by vschweitzer, 4 years ago

Update

As it turns out, my bisection method is sligtly faulty;
this changes nothing about the actual bug, but might
hinder the process of finding it.

The behavior as seen with Torndado only appears on Windows
(probably due to differences in handling async operations).
Although this is still not expected behavior, this might
be caused by a different, (semi-)related issue.

The actual bug described here (a tcp connection being
opened and closed for each file when encrypted, even
though http_persist is enabled) still appears and does
so even in FFmpeg version prior to 1965161.
This can be observed the easiest by using wireshark,
showing only packets that involve the address or port
streamed to (when listening on localhost,
tcp.port == 45000 works well, if the default port is
used). After each segment is pushed, a tcp packet with
FIN ACK flags set is sent, causing the connection to close.

in reply to:  4 comment:5 by Steven Liu, 4 years ago

Replying to vschweitzer:

Update

As it turns out, my bisection method is sligtly faulty;
this changes nothing about the actual bug, but might
hinder the process of finding it.

The behavior as seen with Torndado only appears on Windows
(probably due to differences in handling async operations).
Although this is still not expected behavior, this might
be caused by a different, (semi-)related issue.

The actual bug described here (a tcp connection being
opened and closed for each file when encrypted, even
though http_persist is enabled) still appears and does
so even in FFmpeg version prior to 1965161.
This can be observed the easiest by using wireshark,
showing only packets that involve the address or port
streamed to (when listening on localhost,
tcp.port == 45000 works well, if the default port is
used). After each segment is pushed, a tcp packet with
FIN ACK flags set is sent, causing the connection to close.

This should support in libavformat/crypto.c

not only hlsenc but also hls.c have the same problem.
so this should be fix at the crypto module.

Note: See TracTickets for help on using tickets.