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 09de0a22c6c9f23acfdc0a9b057aa47bb25e07f8..35e998f1ff0054810e230f3ee764dafb04d038eb 100644 (file)
--- 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 a33450bf5e05c9af5e62628418a41e15e2e42121..e048ea05fcd7ebc5d203dd4c2940a061b7aeaea1 100644 (file)
--- 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 cc0c2b5ee15ea330e2d7d9aa7ec6092cab4d3e7e..d02601530335010ae08c7ef467bef917598cc627 100644 (file)
--- 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 b9895981b7bbcb18429ca830b0e93be52d4f1261..7c4d4492d27479e5510bf19d6491f18a0ed41e2e 100644 (file)
--- 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 5a9c1102998373698e7f799c390af0bd080f8472..e1b922aac9812c0bba5afeb898b129ba09b98448 100644 (file)
--- 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 67d689b8deffdf26d3766f353a0a976e4571898e..b60e8061b91bb77c4f3e3cc3eb7d738124d8fc92 100644 (file)
--- 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 7d7fc75ce8801f73b37412b67faccd2aee365d91..24afc1cc923e95e9a7816037012cda0cf670336b 100644 (file)
--- 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 4339d6bb50f4a86419579088a93ebc4e0e47d01c..ec31fa60083a285ab638ab9c5de9bbb0d1bcf7e0 100644 (file)
--- 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 776fa3f3d31b3649d2f9b243c154d3239d660e25..e6db9a83ded120f1cca5969bcc6c74d704c19fb8 100644 (file)
--- 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 062d199e28b4de64a64f370a8a795529e890c459..f4754310c3f50be3d5069b18f61bc6ed4e46236e 100644 (file)
--- 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 f197c70d274cd7c9a8958133d068763a26cc6514..1bfab0c9b5ee1451312d6c4241b45d8ee46b9595 100644 (file)
--- 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 7c56333e5b6e34e739d308bb0de3d2a2f20b5c60..21111a7fac914a82be31b627bd171e88f44756e4 100644 (file)
--- 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 6d6e1fb237ded9ad1c51f7460d625bf9f47d4cd0..51a5642766fa229bfd54d3604a72d70eb733cf9c 100644 (file)
--- 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 d6f9681d6c25f8ad97854fc7ac2e3349b33f6ef8..8b0d00ccb8a6c43a4b8a84458fe7fad720f09f7f 100644 (file)
--- 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 d63dc84e52915ea4ca32aef9fc3c026a8c02d87b..3be51f4d0035aab658780ffaf22e92913173a239 100644 (file)
--- 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 9737c17ab238966da611ab2cac63dd84e2a317ab..a81961d48e2900a165c67b78cb1d4c374eb968c5 100644 (file)
--- 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);
 }