Connect time is inflated

Problem Description

Measured connect timings can be heavily inflated, especially when the event loop is very busy. This issue is concerned with TCP connect time only, but other timings such as TLS handshake time have also been observed to be inflated.

Context: I’ve observed that when loading web pages in Chrome that produce many HTTP requests across multiple origins, MITM proxy sporadically reports significantly inflated TCP connect time; compared with:

• Another proxy (browsermob-proxy fork);
• Chrome’s self reporting by the DevTools protocol;

Testing has been limited to HTTP/1.1 only.

The problem seems to be two fold:

• The use of asyncio.open_connection incorporates the DNS lookup time into the connect time.
• But more worryingly it’s not possible to accurately measure the async open_connection because you don’t know when the event loop will start and finish the task execution.

Here are some results from a reproducible test case linked below. In this test a web page is loaded in a fresh browser 5 times for each of the scenarios, and the web page loads 5 assets from each of 5 different origins. Statistics are gathered from all of the HTTP requests made. When no proxy is used, I get the stats directly from Chrome. When the proxy is used, I get the stats from har_dump.py add-on.

Note that my patch is intended just to be a demonstration of how the problem can be solved, i'm not suggesting you use it directly. The in-line comments explain that I wrote it for an older version of mitmproxy and these changes as they are will inflate the TLS handshake time, because that is measured from timestamp_tcp_setup, which is now more accurately timestamped earlier.

No proxy results
Count: 130
Total: 2614
Min: 20.046
Median: 20.088
Mean: 20.105
Max: 20.365
Std Dev: 0.055

Unpatched proxied results
Count: 130
Total: 4359
Min: 21.000
Median: 29.000
Mean: 33.531
Max: 84.000
Std Dev: 13.631

Patched proxied results
Count: 130
Total: 2697
Min: 20.000
Median: 20.000
Mean: 20.746
Max: 41.000
Std Dev: 2.660

You can see that with the unpatched proxy, median/mean TCP connect times are higher than with no proxy, or the patched proxy. The standard deviation is also notably higher - the measurements are less stable. Total connect time is significantly higher for the unpatched proxy.

The issue can become significantly exacerbated when the event loop is very busy, with connection times observed in the wild that should be ~10 ms instead sometimes taking 100s of milliseconds.

You can find the patch in https://github.com/matseymour28590/mitmproxy-testing.

Steps to reproduce the behaviour:

Assuming you have docker installed and are using a bash shell

1. git clone git@github.com:matseymour28590/mitmproxy-testing.git
2. cd mitmproxy-testing
3. ./run.sh

System Information

Paste the output of "mitmproxy --version" here.
Mitmproxy: 9.0.1
Python: 3.11.3
OpenSSL: OpenSSL 3.0.7 1 Nov 2022
Platform: Linux-5.19.0-41-generic-x86_64-with-glibc2.31

Start by reviewing the current timing around asyncio.open_connection and timestamp_tcp_setup, then reproduce the measurements with the linked mitmproxy-testing repository using run.sh. Compare the proxy results with the reported Chrome and patched measurements. Done means TCP connect timing excludes DNS and event-loop scheduling inflation without incorrectly inflating TLS handshake timing.