From: Eduard Bagdasaryan <eduard.bagdasaryan@measurement-factory.com>
Date: Tue, 10 Sep 2019 05:36:25 +0000 (+0000)
Subject: Supply ALE with HttpReply before checking http_reply_access (#398)
X-Git-Tag: SQUID_5_0_1~47
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=49f57088f725f0823afa2bedfcef6a1b210eb0d8;p=thirdparty%2Fsquid.git

Supply ALE with HttpReply before checking http_reply_access (#398)

Before this fix, Squid warned "ALE missing HttpReply object",
because ALE::reply was initialized too late. This problem affected
both HTTP and FTP code paths.

To avoid these problems, ALE::reply is initialized early with the
available (received) response.

Also:

* Fixed logging control (1xx) responses in case these responses
  are final. Before this fix, '-' was logged.

* All reply headers ('<h') were logged with a single CR separator,
  instead of CRLF.

* Supply ALE for send_hit ACL. cb36505 already covered many (but not
  all) similar cases.
---

diff --git a/src/AccessLogEntry.cc b/src/AccessLogEntry.cc
index 09de0a22c6..35e998f1ff 100644
--- a/src/AccessLogEntry.cc
+++ b/src/AccessLogEntry.cc
@@ -10,6 +10,7 @@
 #include "AccessLogEntry.h"
 #include "HttpReply.h"
 #include "HttpRequest.h"
+#include "MemBuf.h"
 #include "proxyp/Header.h"
 #include "SquidConfig.h"
 #include "ssl/support.h"
@@ -104,14 +105,11 @@ AccessLogEntry::~AccessLogEntry()
     safe_free(adapt.last_meta);
 #endif
 
-    safe_free(headers.reply);
-
     safe_free(headers.adapted_request);
     HTTPMSGUNLOCK(adapted_request);
 
     safe_free(lastAclName);
 
-    HTTPMSGUNLOCK(reply);
     HTTPMSGUNLOCK(request);
 #if ICAP_CLIENT
     HTTPMSGUNLOCK(icap.reply);
@@ -131,3 +129,10 @@ AccessLogEntry::effectiveVirginUrl() const
     return nullptr;
 }
 
+void
+AccessLogEntry::packReplyHeaders(MemBuf &mb) const
+{
+    if (reply)
+        reply->packHeadersUsingFastPacker(mb);
+}
+
diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index a33450bf5e..e048ea05fc 100644
--- a/src/AccessLogEntry.h
+++ b/src/AccessLogEntry.h
@@ -61,6 +61,9 @@ public:
 
     void syncNotes(HttpRequest *request);
 
+    /// dump all reply headers (for sending or risky logging)
+    void packReplyHeaders(MemBuf &mb) const;
+
     SBuf url;
 
     /// TCP/IP level details about the client connection
@@ -158,7 +161,6 @@ public:
     public:
         char *request = nullptr; //< virgin HTTP request headers
         char *adapted_request = nullptr; //< HTTP request headers after adaptation and redirection
-        char *reply = nullptr;
     } headers;
 
 #if USE_ADAPTATION
@@ -177,7 +179,7 @@ public:
     SBuf lastAclData; ///< string for external_acl_type %DATA format code
 
     HierarchyLogEntry hier;
-    HttpReply *reply = nullptr;
+    HttpReplyPointer reply;
     HttpRequest *request = nullptr; //< virgin HTTP request
     HttpRequest *adapted_request = nullptr; //< HTTP request after adaptation and redirection
 
diff --git a/src/acl/FilledChecklist.cc b/src/acl/FilledChecklist.cc
index cc0c2b5ee1..d026015303 100644
--- a/src/acl/FilledChecklist.cc
+++ b/src/acl/FilledChecklist.cc
@@ -116,7 +116,6 @@ ACLFilledChecklist::verifyAle() const
     if (reply && !al->reply) {
         showDebugWarning("HttpReply object");
         al->reply = reply;
-        HTTPMSGLOCK(al->reply);
     }
 
 #if USE_IDENT
diff --git a/src/adaptation/icap/ModXact.cc b/src/adaptation/icap/ModXact.cc
index b9895981b7..7c4d4492d2 100644
--- a/src/adaptation/icap/ModXact.cc
+++ b/src/adaptation/icap/ModXact.cc
@@ -1338,11 +1338,8 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
     al.adapted_request = adapted_request_;
     HTTPMSGLOCK(al.adapted_request);
 
-    if (adapted_reply_) {
-        al.reply = adapted_reply_;
-        HTTPMSGLOCK(al.reply);
-    } else
-        al.reply = NULL;
+    // XXX: This reply (and other ALE members!) may have been needed earlier.
+    al.reply = adapted_reply_;
 
     if (h->rfc931.size())
         al.cache.rfc931 = h->rfc931.termedBuf();
@@ -1377,12 +1374,6 @@ void Adaptation::Icap::ModXact::finalizeLogInfo()
         if (replyHttpBodySize >= 0)
             al.cache.highOffset = replyHttpBodySize;
         //don't set al.cache.objectSize because it hasn't exist yet
-
-        MemBuf mb;
-        mb.init();
-        adapted_reply_->header.packInto(&mb);
-        al.headers.reply = xstrdup(mb.buf);
-        mb.clean();
     }
     prepareLogWithRequestDetails(adapted_request_, alep);
     Xaction::finalizeLogInfo();
diff --git a/src/adaptation/icap/icap_log.cc b/src/adaptation/icap/icap_log.cc
index 5a9c110299..e1b922aac9 100644
--- a/src/adaptation/icap/icap_log.cc
+++ b/src/adaptation/icap/icap_log.cc
@@ -62,7 +62,7 @@ void icapLogLog(AccessLogEntry::Pointer &al)
     if (IcapLogfileStatus == LOG_ENABLE) {
         ACLFilledChecklist checklist(NULL, al->adapted_request, NULL);
         if (al->reply) {
-            checklist.reply = al->reply;
+            checklist.reply = al->reply.getRaw();
             HTTPMSGLOCK(checklist.reply);
         }
         accessLogLogTo(Config.Log.icaplogs, al, &checklist);
diff --git a/src/client_side.cc b/src/client_side.cc
index 67d689b8de..b60e8061b9 100644
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -427,7 +427,7 @@ ClientHttpRequest::logRequest()
     if (request) {
         SBuf matched;
         for (auto h: Config.notes) {
-            if (h->match(request, al->reply, al, matched)) {
+            if (h->match(request, al->reply.getRaw(), al, matched)) {
                 request->notes()->add(h->key(), matched);
                 debugs(33, 3, h->key() << " " << matched);
             }
@@ -438,7 +438,7 @@ ClientHttpRequest::logRequest()
 
     ACLFilledChecklist checklist(NULL, request, NULL);
     if (al->reply) {
-        checklist.reply = al->reply;
+        checklist.reply = al->reply.getRaw();
         HTTPMSGLOCK(checklist.reply);
     }
 
@@ -456,7 +456,7 @@ ClientHttpRequest::logRequest()
         ACLFilledChecklist statsCheck(Config.accessList.stats_collection, request, NULL);
         statsCheck.al = al;
         if (al->reply) {
-            statsCheck.reply = al->reply;
+            statsCheck.reply = al->reply.getRaw();
             HTTPMSGLOCK(statsCheck.reply);
         }
         updatePerformanceCounters = statsCheck.fastCheck().allowed();
@@ -3695,6 +3695,11 @@ ConnStateData::finishDechunkingRequest(bool withSuccess)
 void
 ConnStateData::sendControlMsg(HttpControlMsg msg)
 {
+    if (const auto context = pipeline.front()) {
+        if (context->http)
+            context->http->al->reply = msg.reply;
+    }
+
     if (!isOpen()) {
         debugs(33, 3, HERE << "ignoring 1xx due to earlier closure");
         return;
diff --git a/src/client_side_reply.cc b/src/client_side_reply.cc
index 7d7fc75ce8..24afc1cc92 100644
--- a/src/client_side_reply.cc
+++ b/src/client_side_reply.cc
@@ -1649,6 +1649,8 @@ clientReplyContext::cloneReply()
     reply = http->storeEntry()->getReply()->clone();
     HTTPMSGLOCK(reply);
 
+    http->al->reply = reply;
+
     if (reply->sline.protocol == AnyP::PROTO_HTTP) {
         /* RFC 2616 requires us to advertise our version (but only on real HTTP traffic) */
         reply->sline.version = Http::ProtocolVersion();
@@ -2251,18 +2253,6 @@ clientReplyContext::sendMoreData (StoreIOBuffer result)
         sc->setDelayId(DelayId::DelayClient(http,reply));
 #endif
 
-    /* handle headers */
-
-    if (Config.onoff.log_mime_hdrs) {
-        size_t k;
-
-        if ((k = headersEnd(buf, reqofs))) {
-            safe_free(http->al->headers.reply);
-            http->al->headers.reply = (char *)xcalloc(k + 1, 1);
-            xstrncpy(http->al->headers.reply, buf, k);
-        }
-    }
-
     holdingBuffer = result;
     processReplyAccess();
     return;
diff --git a/src/client_side_request.cc b/src/client_side_request.cc
index 4339d6bb50..ec31fa6008 100644
--- a/src/client_side_request.cc
+++ b/src/client_side_request.cc
@@ -2018,6 +2018,8 @@ ClientHttpRequest::handleAdaptedHeader(Http::Message *msg)
         storeEntry()->replaceHttpReply(new_rep);
         storeEntry()->timestampsSet();
 
+        al->reply = new_rep;
+
         if (!adaptedBodySource) // no body
             storeEntry()->complete();
         clientGetMoreData(node, this);
diff --git a/src/clients/Client.cc b/src/clients/Client.cc
index 776fa3f3d3..e6db9a83de 100644
--- a/src/clients/Client.cc
+++ b/src/clients/Client.cc
@@ -121,6 +121,8 @@ Client::setVirginReply(HttpReply *rep)
     assert(rep);
     theVirginReply = rep;
     HTTPMSGLOCK(theVirginReply);
+    if (fwd->al)
+        fwd->al->reply = theVirginReply;
     return theVirginReply;
 }
 
@@ -140,6 +142,8 @@ Client::setFinalReply(HttpReply *rep)
     assert(rep);
     theFinalReply = rep;
     HTTPMSGLOCK(theFinalReply);
+    if (fwd->al)
+        fwd->al->reply = theFinalReply;
 
     // give entry the reply because haveParsedReplyHeaders() expects it there
     entry->replaceHttpReply(theFinalReply, false); // but do not write yet
@@ -523,6 +527,7 @@ Client::blockCaching()
         ACLFilledChecklist ch(acl, originalRequest().getRaw());
         ch.reply = const_cast<HttpReply*>(entry->getReply()); // ACLFilledChecklist API bug
         HTTPMSGLOCK(ch.reply);
+        ch.al = fwd->al;
         if (!ch.fastCheck().allowed()) { // when in doubt, block
             debugs(20, 3, "store_miss prohibits caching");
             return true;
diff --git a/src/format/Format.cc b/src/format/Format.cc
index 062d199e28..f4754310c3 100644
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -357,7 +357,7 @@ sslErrorName(Security::ErrorCode err, char *buf, size_t size)
 static const Http::Message *
 actualReplyHeader(const AccessLogEntry::Pointer &al)
 {
-    const Http::Message *msg = al->reply;
+    const Http::Message *msg = al->reply.getRaw();
 #if ICAP_CLIENT
     // al->icap.reqMethod is methodNone in access.log context
     if (!msg && al->icap.reqMethod == Adaptation::methodReqmod)
@@ -891,24 +891,35 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
             } else
 #endif
             {
+                // just headers without start-line and CRLF
+                // XXX: reconcile with '<h'
                 out = al->headers.request;
                 quote = 1;
             }
             break;
 
         case LFT_ADAPTED_REQUEST_ALL_HEADERS:
+            // just headers without start-line and CRLF
+            // XXX: reconcile with '<h'
             out = al->headers.adapted_request;
             quote = 1;
             break;
 
-        case LFT_REPLY_ALL_HEADERS:
-            out = al->headers.reply;
+        case LFT_REPLY_ALL_HEADERS: {
+            MemBuf allHeaders;
+            allHeaders.init();
+            // status-line + headers + CRLF
+            // XXX: reconcile with '>h' and '>ha'
+            al->packReplyHeaders(allHeaders);
+            sb.assign(allHeaders.content(), allHeaders.contentSize());
+            out = sb.c_str();
 #if ICAP_CLIENT
             if (!out && al->icap.reqMethod == Adaptation::methodReqmod)
                 out = al->headers.adapted_request;
 #endif
             quote = 1;
-            break;
+        }
+        break;
 
         case LFT_USER_NAME:
 #if USE_AUTH
diff --git a/src/http.cc b/src/http.cc
index f197c70d27..1bfab0c9b5 100644
--- a/src/http.cc
+++ b/src/http.cc
@@ -788,6 +788,9 @@ HttpStateData::processReplyHeader()
 void
 HttpStateData::handle1xx(HttpReply *reply)
 {
+    if (fwd->al)
+        fwd->al->reply = reply;
+
     HttpReply::Pointer msg(reply); // will destroy reply if unused
 
     // one 1xx at a time: we must not be called while waiting for previous 1xx
diff --git a/src/log/FormatHttpdCombined.cc b/src/log/FormatHttpdCombined.cc
index 7c56333e5b..21111a7fac 100644
--- a/src/log/FormatHttpdCombined.cc
+++ b/src/log/FormatHttpdCombined.cc
@@ -69,7 +69,10 @@ Log::Format::HttpdCombined(const AccessLogEntry::Pointer &al, Logfile * logfile)
 
     if (Config.onoff.log_mime_hdrs) {
         char *ereq = ::Format::QuoteMimeBlob(al->headers.request);
-        char *erep = ::Format::QuoteMimeBlob(al->headers.reply);
+        MemBuf mb;
+        mb.init();
+        al->packReplyHeaders(mb);
+        auto erep = ::Format::QuoteMimeBlob(mb.content());
         logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
         safe_free(ereq);
         safe_free(erep);
diff --git a/src/log/FormatHttpdCommon.cc b/src/log/FormatHttpdCommon.cc
index 6d6e1fb237..51a5642766 100644
--- a/src/log/FormatHttpdCommon.cc
+++ b/src/log/FormatHttpdCommon.cc
@@ -54,7 +54,10 @@ Log::Format::HttpdCommon(const AccessLogEntry::Pointer &al, Logfile * logfile)
 
     if (Config.onoff.log_mime_hdrs) {
         char *ereq = ::Format::QuoteMimeBlob(al->headers.request);
-        char *erep = ::Format::QuoteMimeBlob(al->headers.reply);
+        MemBuf mb;
+        mb.init();
+        al->packReplyHeaders(mb);
+        auto erep = ::Format::QuoteMimeBlob(mb.content());
         logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
         safe_free(ereq);
         safe_free(erep);
diff --git a/src/log/FormatSquidNative.cc b/src/log/FormatSquidNative.cc
index d6f9681d6c..8b0d00ccb8 100644
--- a/src/log/FormatSquidNative.cc
+++ b/src/log/FormatSquidNative.cc
@@ -71,7 +71,10 @@ Log::Format::SquidNative(const AccessLogEntry::Pointer &al, Logfile * logfile)
 
     if (Config.onoff.log_mime_hdrs) {
         char *ereq = ::Format::QuoteMimeBlob(al->headers.request);
-        char *erep = ::Format::QuoteMimeBlob(al->headers.reply);
+        MemBuf mb;
+        mb.init();
+        al->packReplyHeaders(mb);
+        auto erep = ::Format::QuoteMimeBlob(mb.content());
         logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
         safe_free(ereq);
         safe_free(erep);
diff --git a/src/servers/FtpServer.cc b/src/servers/FtpServer.cc
index d63dc84e52..3be51f4d00 100644
--- a/src/servers/FtpServer.cc
+++ b/src/servers/FtpServer.cc
@@ -777,12 +777,6 @@ Ftp::Server::handleReply(HttpReply *reply, StoreIOBuffer data)
     Http::StreamPointer context = pipeline.front();
     assert(context != nullptr);
 
-    if (context->http && context->http->al != NULL &&
-            !context->http->al->reply && reply) {
-        context->http->al->reply = reply;
-        HTTPMSGLOCK(context->http->al->reply);
-    }
-
     static ReplyHandler handlers[] = {
         NULL, // fssBegin
         NULL, // fssConnected
diff --git a/src/servers/Http1Server.cc b/src/servers/Http1Server.cc
index 9737c17ab2..a81961d48e 100644
--- a/src/servers/Http1Server.cc
+++ b/src/servers/Http1Server.cc
@@ -316,9 +316,6 @@ Http::One::Server::handleReply(HttpReply *rep, StoreIOBuffer receivedData)
     }
 
     assert(rep);
-    HTTPMSGUNLOCK(http->al->reply);
-    http->al->reply = rep;
-    HTTPMSGLOCK(http->al->reply);
     context->sendStartOfMessage(rep, receivedData);
 }