http_persistent not honored when encryption is enabled

[vschweitzer]

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
f60b121	2019-08-01	OK
6c67c8c	2019-08-06	OK
3aeb681	2019-08-15	OK
c294f38	2019-08-16	OK - Latest OK version
1965161	2019-08-18	Error - Earliest version with error
cff3090	2019-08-18	Error
661a9b2	2019-08-21	Error
0821bc4	2019-08-26	Error
bc9b635	2020-02-24	Error

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.

[Carl Eugen Hoyos]

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.

[vschweitzer]

Tornado HTTP server example

[vschweitzer]

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

[vschweitzer]

Console output belonging to the attached logfile.

[vschweitzer]

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

[Steven Liu]

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.

[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.

[Steven Liu]

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.