adding tcp and ssl setup timestamps to get better resolution on flows performance

libmproxy/flow.py

@@ -288,8 +288,15 @@ class Request(HTTPMsg):
             method: HTTP method
 
             timestamp_end: Seconds since the epoch signifying request transmission ended
+
+            tcp_setup_timestamp: Seconds since the epoch signifying remote TCP connection setup completion time
+            (or None, if request didn't results TCP setup)
+
+            ssl_setup_timestamp: Seconds since the epoch signifying remote SSL encryption setup completion time
+            (or None, if request didn't results SSL setup)
+
     """
-    def __init__(self, client_conn, httpversion, host, port, scheme, method, path, headers, content, timestamp_start=None, timestamp_end=None):
+    def __init__(self, client_conn, httpversion, host, port, scheme, method, path, headers, content, timestamp_start=None, timestamp_end=None, tcp_setup_timestamp=None, ssl_setup_timestamp=None):
         assert isinstance(headers, ODictCaseless)
         self.client_conn = client_conn
         self.httpversion = httpversion
@@ -298,6 +305,8 @@ class Request(HTTPMsg):
         self.timestamp_start = timestamp_start or utils.timestamp()
         self.timestamp_end = max(timestamp_end or utils.timestamp(), timestamp_start)
         self.close = False
+        self.tcp_setup_timestamp = tcp_setup_timestamp
+        self.ssl_setup_timestamp = ssl_setup_timestamp
 
         # Have this request's cookies been modified by sticky cookies or auth?
         self.stickycookie = False
@@ -361,6 +370,8 @@ class Request(HTTPMsg):
         self.content = state["content"]
         self.timestamp_start = state["timestamp_start"]
         self.timestamp_end = state["timestamp_end"]
+        self.tcp_setup_timestamp = state["tcp_setup_timestamp"]
+        self.ssl_setup_timestamp = state["ssl_setup_timestamp"]
 
     def _get_state(self):
         return dict(
@@ -374,7 +385,9 @@ class Request(HTTPMsg):
             headers = self.headers._get_state(),
             content = self.content,
             timestamp_start = self.timestamp_start,
-            timestamp_end = self.timestamp_end
+            timestamp_end = self.timestamp_end,
+            tcp_setup_timestamp = self.tcp_setup_timestamp,
+            ssl_setup_timestamp = self.ssl_setup_timestamp
         )
 
     @classmethod
@@ -391,6 +404,8 @@ class Request(HTTPMsg):
             state["content"],
             state["timestamp_start"],
             state["timestamp_end"],
+            state["tcp_setup_timestamp"],
+            state["ssl_setup_timestamp"]
         )
 
     def __hash__(self):

libmproxy/proxy.py

@@ -55,9 +55,13 @@ class ServerConnection(tcp.TCPClient):
         self.config = config
         self.scheme, self.sni = scheme, sni
         self.requestcount = 0
+        self.tcp_setup_timestamp = None
+        self.ssl_setup_timestamp = None
+
 
     def connect(self):
         tcp.TCPClient.connect(self)
+        self.tcp_setup_timestamp = time.time()
         if self.scheme == "https":
             clientcert = None
             if self.config.clientcerts:
@@ -66,6 +70,7 @@ class ServerConnection(tcp.TCPClient):
                     clientcert = path
             try:
                 self.convert_to_ssl(cert=clientcert, sni=self.sni)
+                self.ssl_setup_timestamp = time.time()
             except tcp.NetLibError, v:
                 raise ProxyError(400, str(v))
 
@@ -224,6 +229,9 @@ class ProxyHandler(tcp.BaseHandler):
                     while 1:
                         sc = self.get_server_connection(cc, scheme, host, port, self.sni)
                         sc.send(request)
+                        if sc.requestcount == 1: # add timestamps only for first request (others are not directly affected)
+                            request.tcp_setup_timestamp = sc.tcp_setup_timestamp
+                            request.ssl_setup_timestamp = sc.ssl_setup_timestamp
                         sc.rfile.reset_timestamps()
                         try:
                             httpversion, code, msg, headers, content = http.read_response(

test/test_server.py

@@ -267,7 +267,35 @@ class TestProxy(tservers.HTTPProxTest):
         request = self.master.state.view[1].request
         assert request.timestamp_end - request.timestamp_start <= 0.1
 
+    def test_request_tcp_setup_timestamp_presence(self):
+        # tests that the first request in a tcp connection has a tcp_setup_timestamp
+        # while others do not
+        connection = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
+        connection.connect(("localhost", self.proxy.port))
+        connection.send("GET http://localhost:%d/p/304:b@1k HTTP/1.1\r\n"%self.server.port)
+        connection.send("\r\n");
+        connection.recv(5000)
+        connection.send("GET http://localhost:%d/p/304:b@1k HTTP/1.1\r\n"%self.server.port)
+        connection.send("\r\n");
+        connection.recv(5000)
+        connection.close()
 
+        first_request = self.master.state.view[0].request
+        second_request = self.master.state.view[1].request
+        assert first_request.tcp_setup_timestamp
+        assert first_request.ssl_setup_timestamp == None
+        assert second_request.tcp_setup_timestamp == None
+        assert second_request.ssl_setup_timestamp == None
+
+
+class TestProxySSL(tservers.HTTPProxTest):
+    ssl=True
+    def test_request_ssl_setup_timestamp_presence(self):
+        # tests that the ssl timestamp is present when ssl is used
+        f = self.pathod("304:b@10k")
+        assert f.status_code == 304
+        first_request = self.master.state.view[0].request
+        assert first_request.ssl_setup_timestamp
 
 class MasterFakeResponse(tservers.TestMaster):
     def handle_request(self, m):