add request_time metric to access logs, BREAKING

fix the response_time metric, request_time was wrongly assigned to it instead, response_time is assigned the value of backend_response_time Co-Authored-By: Eloi DEMOLIS <[email protected]>
sozu-proxy · Jun 25, 2024 · 21a6c33 · 21a6c33
1 parent 0323a7b
commit 21a6c33
Show file tree

Hide file tree

Showing 7 changed files with 27 additions and 14 deletions.
diff --git a/command/src/command.proto b/command/src/command.proto
@@ -744,8 +744,6 @@ message ProtobufAccessLog {
     optional uint64 client_rtt = 9;
     // round trip time for the backend (microseconds)
     optional uint64 server_rtt = 10;
-    // time for the backend to respond (microseconds)
-    required uint64 response_time = 12;
     // time spent on a session (microseconds)
     required uint64 service_time = 13;
     // number of bytes received from the client
@@ -760,6 +758,12 @@ message ProtobufAccessLog {
     required string tag = 18;
     // POSIX timestamp, nanoseconds
     required Uint128 time = 19;
+    // Entire time between first byte received and last byte of the response.
+    // If a request ends abruptly before the last byte is transmitted,
+    // the `request_time` produced is the time elapsed since the first byte received.
+    optional uint64 request_time = 20;
+    // time for the backend to respond (microseconds)
+    optional uint64 response_time = 21;
 }
 
 message ProtobufEndpoint {

diff --git a/command/src/logging/access_logs.rs b/command/src/logging/access_logs.rs
@@ -112,7 +112,10 @@ pub struct RequestRecord<'a> {
     pub server_rtt: Option<Duration>,
     pub user_agent: Option<&'a str>,
     pub service_time: Duration,
-    pub response_time: Duration,
+    /// time from connecting to the backend until the end of the response
+    pub response_time: Option<Duration>,
+    /// time between first byte of the request and last byte of the response
+    pub request_time: Duration,
     pub bytes_in: usize,
     pub bytes_out: usize,
 
@@ -167,7 +170,7 @@ impl RequestRecord<'_> {
                 message: self.message.duplicate(),
                 protocol: self.protocol.duplicate(),
                 request_id: self.context.request_id.into(),
-                response_time: self.response_time.as_micros() as u64,
+                response_time: self.response_time.map(|t| t.as_micros() as u64),
                 server_rtt: self.server_rtt.map(|t| t.as_micros() as u64),
                 service_time: self.service_time.as_micros() as u64,
                 session_address: self.session_address.map(Into::into),
@@ -178,6 +181,7 @@ impl RequestRecord<'_> {
                 user_agent: self.user_agent.duplicate(),
                 tag: self.tag.duplicate(),
                 time: self.precise_time.into(),
+                request_time: Some(self.request_time.as_micros() as u64),
             })
         }
     }

diff --git a/command/src/logging/logs.rs b/command/src/logging/logs.rs
@@ -267,13 +267,14 @@ impl InnerLogger {
                     log.tag,
                 ],
                 standard: {
-                    formats: ["{} {} {} {}/{}/{}/{} {} {} [{}] {} {}{}\n"],
+                    formats: ["{} {} {} {}/{}/{}/{}/{} {} {} [{}] {} {}{}\n"],
                     args: [
                         log.context,
                         log.session_address.as_string_or("-"),
                         log.backend_address.as_string_or("-"),
-                        LogDuration(Some(log.response_time)),
+                        LogDuration(Some(log.request_time)),
                         LogDuration(Some(log.service_time)),
+                        LogDuration(log.response_time),
                         LogDuration(log.client_rtt),
                         LogDuration(log.server_rtt),
                         log.bytes_in,
@@ -285,7 +286,7 @@ impl InnerLogger {
                     ]
                 },
                 colored: {
-                    formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"],
+                    formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"],
                     args: @,
                 }
             },

diff --git a/lib/src/lib.rs b/lib/src/lib.rs
@@ -1026,7 +1026,8 @@ impl SessionMetrics {
         }
     }
 
-    pub fn response_time(&self) -> Duration {
+    /// time elapsed since the beginning of the session
+    pub fn request_time(&self) -> Duration {
         match self.start {
             Some(start) => Instant::now() - start,
             None => Duration::from_secs(0),
@@ -1061,14 +1062,14 @@ impl SessionMetrics {
     }
 
     pub fn register_end_of_session(&self, context: &LogContext) {
-        let response_time = self.response_time();
+        let request_time = self.request_time();
         let service_time = self.service_time();
 
         if let Some(cluster_id) = context.cluster_id {
-            time!("response_time", cluster_id, response_time.as_millis());
+            time!("request_time", cluster_id, request_time.as_millis());
             time!("service_time", cluster_id, service_time.as_millis());
         }
-        time!("response_time", response_time.as_millis());
+        time!("request_time", request_time.as_millis());
         time!("service_time", service_time.as_millis());
 
         if let Some(backend_id) = self.backend_id.as_ref() {

diff --git a/lib/src/protocol/kawa_h1/mod.rs b/lib/src/protocol/kawa_h1/mod.rs
@@ -940,7 +940,8 @@ impl<Front: SocketHandler, L: ListenerHandler + L7ListenerHandler> Http<Front, L
             client_rtt: socket_rtt(self.front_socket()),
             server_rtt: self.backend_socket.as_ref().and_then(socket_rtt),
             service_time: metrics.service_time(),
-            response_time: metrics.response_time(),
+            response_time: metrics.backend_response_time(),
+            request_time: metrics.request_time(),
             bytes_in: metrics.bin,
             bytes_out: metrics.bout,
             user_agent: self.context.user_agent.as_deref(),

diff --git a/lib/src/protocol/pipe.rs b/lib/src/protocol/pipe.rs
@@ -246,7 +246,8 @@ impl<Front: SocketHandler, L: ListenerHandler> Pipe<Front, L> {
             client_rtt: socket_rtt(self.front_socket()),
             server_rtt: self.backend_socket.as_ref().and_then(socket_rtt),
             service_time: metrics.service_time(),
-            response_time: metrics.response_time(),
+            response_time: metrics.backend_response_time(),
+            request_time: metrics.request_time(),
             bytes_in: metrics.bin,
             bytes_out: metrics.bout,
             user_agent: None

diff --git a/lib/src/tcp.rs b/lib/src/tcp.rs
@@ -225,7 +225,8 @@ impl TcpSession {
             server_rtt: None,
             user_agent: None,
             service_time: self.metrics.service_time(),
-            response_time: self.metrics.response_time(),
+            response_time: self.metrics.backend_response_time(),
+            request_time: self.metrics.request_time(),
             bytes_in: self.metrics.bin,
             bytes_out: self.metrics.bout
         );