changing requests and responses to have two timestamps, one marking their initiation, and the other their complete

3 files changed, 75 insertions, 19 deletions

diff --git a/libmproxy/flow.py b/libmproxy/flow.py
index 8e4c2117..9a6b5527 100644..100755
--- a/libmproxy/flow.py
+++ b/libmproxy/flow.py
@@ -256,17 +256,20 @@ class Request(HTTPMsg):
 
             path: Path portion of the URL
 
-            timestamp: Seconds since the epoch
+            timestamp_start: Seconds since the epoch signifying request transmission started
 
             method: HTTP method
+
+            timestamp_end: Seconds since the epoch signifying request transmission ended
     """
-    def __init__(self, client_conn, httpversion, host, port, scheme, method, path, headers, content, timestamp=None):
+    def __init__(self, client_conn, httpversion, host, port, scheme, method, path, headers, content, timestamp_start=None, timestamp_end=None):
         assert isinstance(headers, ODictCaseless)
         self.client_conn = client_conn
         self.httpversion = httpversion
         self.host, self.port, self.scheme = host, port, scheme
         self.method, self.path, self.headers, self.content = method, path, headers, content
-        self.timestamp = timestamp or utils.timestamp()
+        self.timestamp_start = timestamp_start or utils.timestamp()
+        self.timestamp_end = max(timestamp_end or utils.timestamp(), timestamp_start)
         self.close = False
         controller.Msg.__init__(self)
 
@@ -330,7 +333,8 @@ class Request(HTTPMsg):
         self.path = state["path"]
         self.headers = ODictCaseless._from_state(state["headers"])
         self.content = state["content"]
-        self.timestamp = state["timestamp"]
+        self.timestamp_start = state["timestamp_start"]
+        self.timestamp_end = state["timestamp_end"]
 
     def _get_state(self):
         return dict(
@@ -343,7 +347,8 @@ class Request(HTTPMsg):
             path = self.path,
             headers = self.headers._get_state(),
             content = self.content,
-            timestamp = self.timestamp,
+            timestamp_start = self.timestamp_start,
+            timestamp_end = self.timestamp_end
         )
 
     @classmethod
@@ -358,7 +363,8 @@ class Request(HTTPMsg):
             str(state["path"]),
             ODictCaseless._from_state(state["headers"]),
             state["content"],
-            state["timestamp"]
+            state["timestamp_start"],
+            state["timestamp_end"],
         )
 
     def __hash__(self):
@@ -545,15 +551,18 @@ class Response(HTTPMsg):
             is content associated, but not present. CONTENT_MISSING evaluates
             to False to make checking for the presence of content natural.
 
-            timestamp: Seconds since the epoch
+            timestamp_start: Seconds since the epoch signifying response transmission started
+
+            timestamp_end: Seconds since the epoch signifying response transmission ended
     """
-    def __init__(self, request, httpversion, code, msg, headers, content, cert, timestamp=None):
+    def __init__(self, request, httpversion, code, msg, headers, content, cert, timestamp_start=None, timestamp_end=None):
         assert isinstance(headers, ODictCaseless)
         self.request = request
         self.httpversion, self.code, self.msg = httpversion, code, msg
         self.headers, self.content = headers, content
         self.cert = cert
-        self.timestamp = timestamp or utils.timestamp()
+        self.timestamp_start = timestamp_start or utils.timestamp()
+        self.timestamp_end = max(timestamp_end or utils.timestamp(), timestamp_start)
         controller.Msg.__init__(self)
         self.replay = False
 
@@ -589,7 +598,7 @@ class Response(HTTPMsg):
         """
         if not now:
             now = time.time()
-        delta = now - self.timestamp
+        delta = now - self.timestamp_start
         refresh_headers = [
             "date",
             "expires",
@@ -621,7 +630,8 @@ class Response(HTTPMsg):
         self.msg = state["msg"]
         self.headers = ODictCaseless._from_state(state["headers"])
         self.content = state["content"]
-        self.timestamp = state["timestamp"]
+        self.timestamp_start = state["timestamp_start"]
+        self.timestamp_end = state["timestamp_end"]
         self.cert = certutils.SSLCert.from_pem(state["cert"]) if state["cert"] else None
 
     def _get_state(self):
@@ -630,9 +640,10 @@ class Response(HTTPMsg):
             code = self.code,
             msg = self.msg,
             headers = self.headers._get_state(),
-            timestamp = self.timestamp,
+            timestamp_start = self.timestamp_start,
+            timestamp_end = self.timestamp_end,
             cert = self.cert.to_pem() if self.cert else None,
-            content = self.content
+            content = self.content,
         )
 
     @classmethod
@@ -645,7 +656,8 @@ class Response(HTTPMsg):
             ODictCaseless._from_state(state["headers"]),
             state["content"],
             certutils.SSLCert.from_pem(state["cert"]) if state["cert"] else None,
-            state["timestamp"],
+            state["timestamp_start"],
+            state["timestamp_end"],
         )
 
     def __eq__(self, other):
diff --git a/libmproxy/proxy.py b/libmproxy/proxy.py
index b1ce310c..4c57aeb0 100644..100755
--- a/libmproxy/proxy.py
+++ b/libmproxy/proxy.py
@@ -180,14 +180,16 @@ class ProxyHandler(tcp.BaseHandler):
                         scheme, host, port = request.scheme, request.host, request.port
                     self.server_connect(scheme, host, port)
                     self.server_conn.send(request)
+                    self.server_conn.rfile.reset_timestamps()
                     httpversion, code, msg, headers, content = http.read_response(
                         self.server_conn.rfile,
                         request.method,
                         self.config.body_size_limit
                     )
                     response = flow.Response(
-                        request, httpversion, code, msg, headers, content, self.server_conn.cert
+                        request, httpversion, code, msg, headers, content, self.server_conn.cert, self.server_conn.rfile.first_byte_timestamp, utils.timestamp()
                     )
+
                     response = response._send(self.mqueue)
                     if response is None:
                         self.server_conn.terminate()
@@ -266,6 +268,7 @@ class ProxyHandler(tcp.BaseHandler):
             self.sni = sn.decode("utf8").encode("idna")
 
     def read_request(self, client_conn):
+        self.rfile.reset_timestamps()
         if self.config.transparent_proxy:
             host, port = self.config.transparent_proxy["resolver"].original_addr(self.connection)
             if not self.ssl_established and (port in self.config.transparent_proxy["sslports"]):
@@ -289,7 +292,7 @@ class ProxyHandler(tcp.BaseHandler):
             content = http.read_http_body_request(
                         self.rfile, self.wfile, headers, httpversion, self.config.body_size_limit
                     )
-            return flow.Request(client_conn, httpversion, host, port, scheme, method, path, headers, content)
+            return flow.Request(client_conn, httpversion, host, port, scheme, method, path, headers, content, self.rfile.first_byte_timestamp, utils.timestamp())
         elif self.config.reverse_proxy:
             line = self.get_line(self.rfile)
             if line == "":
@@ -303,7 +306,7 @@ class ProxyHandler(tcp.BaseHandler):
             content = http.read_http_body_request(
                         self.rfile, self.wfile, headers, httpversion, self.config.body_size_limit
                     )
-            return flow.Request(client_conn, httpversion, host, port, "http", method, path, headers, content)
+            return flow.Request(client_conn, httpversion, host, port, "http", method, path, headers, content, self.rfile.first_byte_timestamp, utils.timestamp())
         else:
             line = self.get_line(self.rfile)
             if line == "":
@@ -340,7 +343,7 @@ class ProxyHandler(tcp.BaseHandler):
                 content = http.read_http_body_request(
                     self.rfile, self.wfile, headers, httpversion, self.config.body_size_limit
                 )
-                return flow.Request(client_conn, httpversion, host, port, "https", method, path, headers, content)
+                return flow.Request(client_conn, httpversion, host, port, "https", method, path, headers, content, self.rfile.first_byte_timestamp, utils.timestamp())
             else:
                 r = http.parse_init_proxy(line)
                 if not r:
@@ -350,7 +353,7 @@ class ProxyHandler(tcp.BaseHandler):
                 content = http.read_http_body_request(
                     self.rfile, self.wfile, headers, httpversion, self.config.body_size_limit
                 )
-                return flow.Request(client_conn, httpversion, host, port, scheme, method, path, headers, content)
+                return flow.Request(client_conn, httpversion, host, port, scheme, method, path, headers, content, self.rfile.first_byte_timestamp, utils.timestamp())
 
     def read_headers(self, authenticate=False):
         headers = http.read_headers(self.rfile)
diff --git a/test/test_server.py b/test/test_server.py
index 38d33d90..76f24743 100644
--- a/test/test_server.py
+++ b/test/test_server.py
@@ -74,3 +74,44 @@ class TestProxy(tutils.HTTPProxTest):
         assert l.request.client_conn.address
         assert "host" in l.request.headers
         assert l.response.code == 304
+
+    def test_response_timestamps(self):
+        # test that we notice at least 2 sec delay between timestamps
+        # in response object
+        f = self.pathod("304:b@1k:p50,2")
+        assert f.status_code == 304
+
+        response = self.master.state.view[0].response
+        assert 2 <= response.timestamp_end - response.timestamp_start <= 2.2
+
+    def test_request_timestamps(self):
+        # test that we notice at least 2 sec delay between timestamps
+        # in request object
+        connection = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
+        connection.connect(("127.0.0.1", self.proxy.port))
+
+        # call pathod server, wait a second to complete the request
+        connection.send("GET http://localhost:%d/p/304:b@1k HTTP/1.1\r\n"%self.server.port)
+        sleep(2.1)
+        connection.send("\r\n");
+        connection.recv(50000)
+        connection.close()
+
+        request, response = self.master.state.view[0].request, self.master.state.view[0].response
+        assert response.code == 304  # sanity test for our low level request
+        assert 2 <= request.timestamp_end - request.timestamp_start <= 2.2
+
+    def test_request_timestamps_not_affected_by_client_time(self):
+        # test that don't include user wait time in request's timestamps
+
+        f = self.pathod("304:b@10k")
+        assert f.status_code == 304
+        sleep(1)
+        f = self.pathod("304:b@10k")
+        assert f.status_code == 304
+
+        request = self.master.state.view[0].request
+        assert request.timestamp_end - request.timestamp_start <= 0.1
+
+        request = self.master.state.view[1].request
+        assert request.timestamp_end - request.timestamp_start <= 0.1