Bug 5148: Log %Ss of failed tunnels as TCP_TUNNEL (#1354)

    ERR_CONNECT_FAIL/errno=111 NONE_NONE/503 CONNECT

    TAG_NONE/503 0 CONNECT example.com:443 - HIER_NONE/- -

When Squid failed to open a TCP connection to an origin server (or
through a cache peer) while handling a CONNECT request, Squid logged %Ss
as NONE_NONE because TunnelStateData waited for a successful TCP
connection to update the log tag. That unnecessary wait (modeled after
the necessary HTTP status code wait) complicated code. Squid now logs
TCP_TUNNEL to indicate the request handling path chosen by Squid.

We already use the same "handling path" approach for most other request
status codes. For example, TCP_MISS does not mean the miss transaction
was successful. It only means that Squid satisfied the request using the
cache miss forwarding logic. Even the LOG_TCP_REFRESH_FAIL_ERR status
code does not imply that the error response was successfully forwarded
to the client; only that the request was satisfied on a particular
(albeit very detailed in this case!) handling path.

Apply the same logic to tunneling attempts blocked by miss_access. They
were also logged as NONE_NONE and are now logged as TCP_TUNNEL.

The actual outcome of a tunneling attempt can usually be determined
using %err_code/%err_detail and %>Hs logformat codes.

diff --git a/doc/release-notes/release-6.sgml.in b/doc/release-notes/release-6.sgml.in
index 11c51da87bdfd03c3b06605af10d3802765913d3..ac0c786c483cdf8d18167276eeba244be2a51fbf 100644 (file)
--- a/doc/release-notes/release-6.sgml.in
+++ b/doc/release-notes/release-6.sgml.in
@@ -234,6 +234,8 @@ This section gives an account of those changes in three categories:
           made for this request.
        <p>Squid now adds <em>ABORTED</em> to values printed by the <em>Ss</em> code in more
           cases where a TCP Squid-to-server connection was closed prematurely.
+       <p>Squid now logs <em>TCP_TUNNEL</em> with the <em>Ss</em> code when a CONNECT tunnel
+          is attempted, not just on successful tunnel setup.
 
        <tag>server_cert_fingerprint</tag>
        <p>Removed the broken <em>-sha</em> option. <em>SHA1</em> remains the default and

diff --git a/src/LogTags.h b/src/LogTags.h
index a33c1d0ee99d3d69e28bbffef5aa67cb331d971c..d8c13cf37c5b5f733d28b60ab9533b47777d5a25 100644 (file)
--- a/src/LogTags.h
+++ b/src/LogTags.h
@@ -53,7 +53,7 @@ typedef enum {
     LOG_TCP_DENIED_REPLY,
     LOG_TCP_OFFLINE_HIT,
     LOG_TCP_REDIRECT,
-    LOG_TCP_TUNNEL,             // a binary tunnel was established for this transaction
+    LOG_TCP_TUNNEL, ///< an attempt to establish a bidirectional TCP tunnel
     LOG_UDP_HIT,
     LOG_UDP_MISS,
     LOG_UDP_DENIED,

diff --git a/src/tunnel.cc b/src/tunnel.cc
index 75facc9e4c077e5700d05546eb01d427cbc00300..af3d50ffebe55d073144a0013335f394a9a69cd5 100644 (file)
--- a/src/tunnel.cc
+++ b/src/tunnel.cc
@@ -370,6 +370,8 @@ TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) :
     al = clientRequest->al;
     http = clientRequest;
 
+    al->cache.code.update(LOG_TCP_TUNNEL);
+
     client.initConnection(clientRequest->getConn()->clientConnection, tunnelClientClosed, "tunnelClientClosed", this);
 
     AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "tunnelTimeout",
@@ -927,7 +929,6 @@ tunnelStartShoveling(TunnelStateData *tunnelState)
     commSetConnTimeout(tunnelState->server.conn, Config.Timeout.read, timeoutCall);
 
     *tunnelState->status_ptr = Http::scOkay;
-    tunnelState->al->cache.code.update(LOG_TCP_TUNNEL);
     if (cbdataReferenceValid(tunnelState)) {
 
         // Shovel any payload already pushed into reply buffer by the server response
@@ -980,8 +981,6 @@ TunnelStateData::tunnelEstablishmentDone(Http::TunnelerAnswer &answer)
     peerWait.finish();
     server.len = 0;
 
-    al->cache.code.update(LOG_TCP_TUNNEL);
-
     // XXX: al->http.code (i.e. *status_ptr) should not be (re)set
     // until we actually start responding to the client. Right here/now, we only
     // know how this cache_peer has responded to us.
@@ -1164,6 +1163,7 @@ tunnelStart(ClientHttpRequest * http)
         ch.syncAle(request, http->log_uri);
         if (ch.fastCheck().denied()) {
             debugs(26, 4, "MISS access forbidden.");
+            http->updateLoggingTags(LOG_TCP_TUNNEL);
             err = new ErrorState(ERR_FORWARDING_DENIED, Http::scForbidden, request, http->al);
             http->al->http.code = Http::scForbidden;
             errorSend(http->getConn()->clientConnection, err);