New %codes for computing message forwarding delays

src/AccessLogEntry.h

@@ -32,11 +32,45 @@
 #include "ssl/support.h"
 #endif
 
+#include <optional>
+
 /* forward decls */
 class HttpReply;
 class HttpRequest;
 class CustomLog;
 
+// TODO: move
+/// Accumulates timings of message IO events.
+class MessageTimer
+{
+public:
+    using Clock = std::chrono::system_clock;
+    using Time = Clock::time_point;
+
+    MessageTimer() = default;
+    explicit MessageTimer(const Time &s) : first(s), last(s) {}
+
+    /// sets firstTime (if uninitialized yet) and lastTime (always) to the current time
+    void update() {
+        last = Clock::now();
+        if (!first)
+            first = last;
+    }
+
+    /// removes firstTime and lastTime values
+    void reset() { *this = MessageTimer(); }
+
+    /// the time of the first IO for the message
+    auto firstTime() const { return first; }
+
+    /// the time of the last IO for the message
+    auto lastTime() const { return last; }
+
+private:
+    std::optional<Time> first;
+    std::optional<Time> last;
+};
+
 class AccessLogEntry: public CodeContext
 {
 
@@ -164,6 +198,11 @@ class AccessLogEntry: public CodeContext
         Security::CertPointer sslClientCert; ///< cert received from the client
 #endif
         AnyP::PortCfgPointer port;
+
+        MessageTimer requestReadTimer; ///< first/last IO when receiving request from the client
+        MessageTimer responseWriteTimer; ///< first/last IO when writing response to the client
+        MessageTimer requestWriteTimer; ///< first/last IO when writing request to the peer
+        MessageTimer responseReadTimer; ///< first/last IO when reading response from the peer
     } cache;
 
     /** \brief This subclass holds log info for various headers in raw format

src/FwdState.cc

@@ -1063,6 +1063,9 @@ FwdState::successfullyConnectedToPeer(const Comm::ConnectionPointer &conn)
 
     NoteOutgoingConnectionSuccess(serverConnection()->getPeer());
 
+    if (al)
+        al->cache.requestWriteTimer.reset();
+
     dispatch();
 }
 

src/HttpControlMsg.cc

@@ -12,7 +12,7 @@
 #include "HttpControlMsg.h"
 
 void
-HttpControlMsgSink::doneWithControlMsg()
+HttpControlMsgSink::doneWithControlMsg(const bool)
 {
     if (cbControlMsgSent) {
         ScheduleCallHere(cbControlMsgSent);
@@ -28,7 +28,7 @@ HttpControlMsgSink::wroteControlMsg(const CommIoCbParams &params)
         return;
 
     if (params.flag == Comm::OK) {
-        doneWithControlMsg();
+        doneWithControlMsg(true);
         return;
     }
 

src/HttpControlMsg.h

@@ -33,7 +33,8 @@ class HttpControlMsgSink: public virtual AsyncJob
     /// called to send the 1xx message and notify the Source
     virtual void sendControlMsg(HttpControlMsg msg) = 0;
 
-    virtual void doneWithControlMsg();
+    /// \param wasSent whether the message was written to the client
+    virtual void doneWithControlMsg(bool wasSent);
 
     /// callback to handle Comm::Write completion
     void wroteControlMsg(const CommIoCbParams &);

src/auth/basic/NIS/nis_support.h

@@ -8,9 +8,6 @@
 #ifndef SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
 #define SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
 
-#ifndef SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
-#define SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H
-
 extern char * get_nis_password(char *user, char *nisdomain, char *nismap);
 
 #endif /* SQUID_SRC_AUTH_BASIC_NIS_NIS_SUPPORT_H */

src/cf.data.pre

@@ -4868,6 +4868,93 @@ DOC_START
 			values may significantly understate or exaggerate actual times.
 			Do not use this measurement unless you know it works in your case.
 
+		The following x_time %codes produce approximate absolute time of event
+		x in <full seconds since epoch>.<fractional seconds> format. Squid
+		should remember these events when they happen, but various temporary
+		implementation deficiencies may result in information loss for
+		unsuccessful transactions. Using logged times for erroneous
+		transaction analysis requires understanding of these Squid-version
+		specific limitations and is not recommended.
+
+		For CONNECT tunnels, all bytes (and a successful connection closure
+		indication) received from the client and forwarded to the server are
+		considered to be a part of the CONNECT request, while all bytes (and a
+		successful connection closure indication) received from the server and
+		forwarded to the client are considered to be a part of the CONNECT
+		response.
+
+		A failed socket read(2) or write(2) call is normally not reflected in
+		these %codes. Such I/O failures usually result in transaction errors.
+
+		If Squid received (or sent) the entire message in one network I/O (or
+		equivalent), then the corresponding x_first_byte_time value will be
+		the same as x_last_byte_time value.
+
+		received_request_first_byte_time: Squid starts parsing an incoming
+			client HTTP or FTP request. For requests generated by Squid (e.g.,
+			to download missing intermediate certificates or to fake a CONNECT
+			request during SslBump operations), this time is the time of that
+			request generation.
+
+			In most cases, Squid receives the entire request header in one
+			network read(2), but it is possible that the header will not be
+			fully received (and parsed) until a later time. Thus, this %code
+			time does not always correspond to the time when Squid starts
+			evaluating (beyond basic parsing) and forwarding a request.
+
+			In most cases, a client does not send the next request on a
+			client-to-Squid connection until Squid responds to the previous
+			one, but it is possible that Squid reads bytes belonging to
+			multiple requests in one network read(2). Squid may also read
+			PROXY protocol or TLS messages before reading HTTP or FTP request
+			bytes. In such and similar cases, this %code value does not match
+			the last read(2) time because Squid has to spend time on handling
+			other read bytes first.
+
+			Currently, this time may not match %tS because %tS timestamps is
+			created when the entire request header has been parsed.
+
+			Client-to-Squid TCP connection acceptance and client-Squid TLS
+			handshake (if any) happen earlier. REQMOD adaptation of read bytes
+			(if any) happens later.
+
+		received_request_last_byte_time: The last time Squid received HTTP or
+			FTP bytes (or a successful connection closure indication)
+			associated with the current request.
+
+		sent_request_first_byte_time: Squid successfully sent the first HTTP
+			or FTP request byte (at least) to an origin server or cache_peer.
+
+			If Squid retries or re-forwards a failed request, then this %code
+			reflects the _last_ such attempt.
+
+			Any Squid-to-peer TCP connection establishment, CONNECT tunnel
+			establishment, and TLS handshake happen earlier. RESPMOD
+			adaptation happens later.
+
+		sent_request_last_byte_time: The last time Squid successfully sent
+			HTTP or FTP bytes associated with the current request. See
+			%sent_request_first_byte_time %code for more caveats.
+
+		received_response_first_byte_time: Squid successfully received the
+			first HTTP or FTP response byte from an origin server or
+			cache_peer.
+
+			If Squid retries or re-forwards a failed request, then this %code
+			reflects the response in the _last_ such attempt.
+
+		received_response_last_byte_time: The last time Squid received HTTP or
+			FTP bytes (or a successful connection closure indication)
+			associated with the current response. See
+			%received_response_first_byte_time %code for more caveats.
+
+		sent_response_first_byte_time: Squid successfully sent the first HTTP
+			or FTP response byte (at least) to the client.
+
+		sent_response_last_byte_time: The last time Squid successfully sent
+			HTTP or FTP bytes associated with the current response to the
+			client. See %sent_response_first_byte_time %code for more caveats.
+
 	Access Control related format codes:
 
 		et	Tag returned by external acl

src/client_side.cc

@@ -1026,6 +1026,8 @@ ConnStateData::afterClientWrite(size_t size)
     if (pipeline.empty())
         return;
 
+    currentWriter().al->cache.responseWriteTimer.update();
+
     auto ctx = pipeline.front();
     if (size) {
         statCounter.client_http.kbytes_out += size;
@@ -1936,6 +1938,13 @@ ConnStateData::clientParseRequests()
             assert(!preservingClientData_);
         }
 
+        // The "first byte" time of a (possibly pipelined) request is defined as
+        // the time we _start_ parsing its header. If requestFirstByteTime is
+        // set, then do nothing as we continue to parse a request header we
+        // started to parse earlier. Otherwise, remember the time we started.
+        if (!requestFirstByteTime)
+            requestFirstByteTime = MessageTimer::Clock::now();
+
         if (Http::StreamPointer context = parseOneRequest()) {
             debugs(33, 5, clientConnection << ": done parsing a request");
             extendLifetime();
@@ -3723,7 +3732,7 @@ ConnStateData::sendControlMsg(HttpControlMsg msg)
 
         if (!writeControlMsgAndCall(rep.getRaw(), call)) {
             // but still inform the caller (so it may resume its operation)
-            doneWithControlMsg();
+            doneWithControlMsg(false);
         }
         return;
     }
@@ -3733,9 +3742,11 @@ ConnStateData::sendControlMsg(HttpControlMsg msg)
 }
 
 void
-ConnStateData::doneWithControlMsg()
+ConnStateData::doneWithControlMsg(const bool wasSent)
 {
-    HttpControlMsgSink::doneWithControlMsg();
+    if (wasSent && HttpControlMsgSink::cbControlMsgSent)
+        currentWriter().al->cache.responseWriteTimer.update();
+    HttpControlMsgSink::doneWithControlMsg(wasSent);
 
     if (Http::StreamPointer deferredRequest = pipeline.front()) {
         debugs(33, 3, clientConnection << ": calling PushDeferredIfNeeded after control msg wrote");
@@ -3900,6 +3911,9 @@ ConnStateData::clientPinnedConnectionRead(const CommIoCbParams &io)
     if (io.flag == Comm::ERR_CLOSING)
         return; // close handler will clean up
 
+    // AccessLogEntry::CacheDetails::responseReadTimer is not updated here
+    // because idle connections do not have an associated transaction.
+
     Must(pinning.serverConnection == io.conn);
 
 #if USE_OPENSSL

src/client_side.h

@@ -11,6 +11,7 @@
 #ifndef SQUID_SRC_CLIENT_SIDE_H
 #define SQUID_SRC_CLIENT_SIDE_H
 
+#include "AccessLogEntry.h"
 #include "acl/ChecklistFiller.h"
 #include "base/RunnersRegistry.h"
 #include "clientStreamForward.h"
@@ -95,7 +96,7 @@ class ConnStateData:
 
     /* HttpControlMsgSink API */
     void sendControlMsg(HttpControlMsg) override;
-    void doneWithControlMsg() override;
+    void doneWithControlMsg(bool) override;
 
     /// Traffic parsing
     bool clientParseRequests();
@@ -384,6 +385,10 @@ class ConnStateData:
     /// managers logging of the being-accepted TLS connection secrets
     Security::KeyLogger keyLogger;
 
+    /// The first time parseOneRequest() was called for the current request.
+    /// This member gets cleared when request headers are successfully parsed.
+    std::optional<MessageTimer::Time> requestFirstByteTime;
+
 protected:
     void startDechunkingRequest();
     void finishDechunkingRequest(bool withSuccess);

src/client_side_request.cc

@@ -125,6 +125,25 @@ ClientRequestContext::ClientRequestContext(ClientHttpRequest *anHttp) :
 
 CBDATA_CLASS_INIT(ClientHttpRequest);
 
+/// computes effective ClientHttpRequest start time, purging ConnStateData cache
+static auto
+ExtractRequestStartTime(ConnStateData * const conn)
+{
+    if (conn) {
+        // TODO: Create ClientHttpRequest earlier, when we _start_ parsing, to
+        // avoid temporary storing info in ConnStateData (among other problems).
+        if (auto &requestFirstByteTime = conn->requestFirstByteTime) {
+            const auto result = *requestFirstByteTime;
+            requestFirstByteTime.reset();
+            return result;
+        }
+        // else this is a "fake" request not triggered by header parsing
+    }
+    // else this is an "internal" request not associated with ConnStateData
+
+    return MessageTimer::Clock::now();
+}
+
 ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) :
 #if USE_ADAPTATION
     AsyncJob("ClientHttpRequest"),
@@ -133,7 +152,12 @@ ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) :
     conn_(cbdataReference(aConn))
 {
     CodeContext::Reset(al);
+
+    // TODO: Adjust transaction start (%tS) definition and code to include
+    // header parsing, removing this field and using cache.requestReadTimer.
     al->cache.start_time = current_time;
+    al->cache.requestReadTimer = MessageTimer(ExtractRequestStartTime(aConn));
+
     if (aConn) {
         al->tcpClient = aConn->clientConnection;
         al->cache.port = aConn->port;

src/clients/Client.cc

@@ -394,6 +394,9 @@ Client::sentRequestBody(const CommIoCbParams &io)
         return;
     }
 
+    if (fwd->al)
+        fwd->al->cache.requestWriteTimer.update();
+
     if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) {
         abortOnData("store entry aborted while sending request body");
         return;

src/clients/FtpClient.cc

@@ -371,6 +371,9 @@ Ftp::Client::readControlReply(const CommIoCbParams &io)
     if (io.flag == Comm::ERR_CLOSING)
         return;
 
+    if (io.flag == Comm::OK && fwd->al)
+        fwd->al->cache.responseReadTimer.update();
+
     if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) {
         if (abortOnData("entry aborted during control reply read"))
             return;
@@ -872,6 +875,9 @@ Ftp::Client::writeCommandCallback(const CommIoCbParams &io)
         /* failed closes ctrl.conn and frees ftpState */
         return;
     }
+
+    if (fwd->al)
+        fwd->al->cache.requestWriteTimer.update();
 }
 
 /// handler called by Comm when FTP control channel is closed unexpectedly
@@ -973,6 +979,9 @@ Ftp::Client::dataRead(const CommIoCbParams &io)
 
     assert(io.fd == data.conn->fd);
 
+    if (io.flag == Comm::OK && fwd->al)
+        fwd->al->cache.responseReadTimer.update();
+
     if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) {
         abortOnData("entry aborted during dataRead");
         return;

src/format/ByteCode.h

@@ -160,6 +160,14 @@ typedef enum {
     LFT_TIME_LOCALTIME,
     LFT_TIME_GMT,
     LFT_TIME_START, // the time the master transaction started
+    LFT_RECEIVED_REQUEST_FIRST_BYTE_TIME,
+    LFT_RECEIVED_REQUEST_LAST_BYTE_TIME,
+    LFT_SENT_REQUEST_FIRST_BYTE_TIME,
+    LFT_SENT_REQUEST_LAST_BYTE_TIME,
+    LFT_RECEIVED_RESPONSE_FIRST_BYTE_TIME,
+    LFT_RECEIVED_RESPONSE_LAST_BYTE_TIME,
+    LFT_SENT_RESPONSE_FIRST_BYTE_TIME,
+    LFT_SENT_RESPONSE_LAST_BYTE_TIME,
 
     /* processing time details */
     LFT_TIME_TO_HANDLE_REQUEST,