Fix some failed transactions not being logged.

There are situations when Squid logs nothing to access.log after an
[abnormal] transaction termination. Such "stealthy" transactions may be
a security risk and an accounting problem.

ClientHttpRequest is responsible for logging most transactions but that
object is created only after the HTTP request headers are successfully
parsed. Request header parsing errors may be detected and logged
appropriately, but the job handling the incoming transaction may
terminate for reasons outside the parsing code control (e.g., a job-
killing exception thrown when there are no request headers to start
parsing yet or when the job waits for more request headers to finishing
parsing).

This change adds access logging for three cases:

1. accept(2) system call errors (before ConnStateData job is created).

2. Unexpected ConnStateData job termination, when there is no
   ClientHttpRequest to log the failure.

3. Connections which send no bytes: these connections drain Squid
   resources and, hence, should be logged.
   TODO: make this behavior configurable because some browsers are known to
   routinely create such connections(and, hence, logging them may create
   too much noise in some environments).

diff --git a/doc/release-notes/release-4.sgml b/doc/release-notes/release-4.sgml
index 167eaf72978fb96b0cf2034ebdb3a1dcbd73cbfd..088264ebb610ea7f04b206c4239cb3215a12ec4d 100644 (file)
--- a/doc/release-notes/release-4.sgml
+++ b/doc/release-notes/release-4.sgml
@@ -226,6 +226,12 @@ This section gives a thorough account of those changes in three categories:
 <sect1>Changes to existing tags<label id="modifiedtags">
 <p>
 <descrip>
+       <tag>access_log</tag>
+       <p>TCP accept(2) errors logged with URI <em>error:accept-client-connection</em>.
+       <p>Unused connections received in <em>http_port</em> or <em>https_port</em>
+          or transactions terminated before reading[parsing] request headers
+          logged with URI <em>error:transaction-end-before-headers</em>.
+
        <tag>acl</tag>
        <p>New <em>-m</em> flag for <em>note</em> ACL to match substrings.
 

diff --git a/src/Makefile.am b/src/Makefile.am
index 563d5cdb8d4ec0a1339629d5512c73bde28d17bf..8df789bfd04cda6d593d6d7a0a8e0f46015c2544 100644 (file)
--- a/src/Makefile.am
+++ b/src/Makefile.am
@@ -1433,6 +1433,8 @@ tests_testCacheManager_LDADD = \
 tests_testCacheManager_LDFLAGS = $(LIBADD_DL)
 
 tests_testDiskIO_SOURCES = \
+       AccessLogEntry.cc \
+       AccessLogEntry.h \
        CacheDigest.h \
        tests/stub_CacheDigest.cc \
        cbdata.cc \
@@ -1538,6 +1540,7 @@ tests_testDiskIO_SOURCES = \
        tests/stub_libeui.cc \
        tests/stub_libformat.cc \
        tests/stub_libicmp.cc \
+       tests/stub_liblog.cc \
        tests/stub_MemStore.cc \
        mime.h \
        tests/stub_mime.cc \
@@ -1581,6 +1584,7 @@ tests_testDiskIO_LDADD = \
        fs/libfs.la \
        ipc/libipc.la \
        $(REPL_OBJS) \
+       $(ADAPTATION_LIBS) \
        DiskIO/libdiskio.la \
        acl/libapi.la \
        anyp/libanyp.la \
@@ -2896,6 +2900,8 @@ SWAP_TEST_DS =\
        $(REPL_OBJS)
 
 tests_testUfs_SOURCES = \
+       AccessLogEntry.cc \
+       AccessLogEntry.h \
        tests/testUfs.cc \
        tests/testUfs.h \
        tests/stub_cache_manager.cc \
@@ -2907,6 +2913,7 @@ tests_testUfs_SOURCES = \
        tests/stub_ipcache.cc \
        tests/stub_libeui.cc \
        tests/stub_libicmp.cc \
+       tests/stub_liblog.cc \
        tests/stub_MemStore.cc \
        tests/stub_neighbors.cc \
        tests/stub_pconn.cc \
@@ -3053,6 +3060,7 @@ tests_testUfs_LDADD = \
        ip/libip.la \
        mem/libmem.la \
        store/libstore.la \
+       $(ADAPTATION_LIBS) \
        sbuf/libsbuf.la \
        $(top_builddir)/lib/libmisccontainers.la \
        $(top_builddir)/lib/libmiscencoding.la \
@@ -3083,6 +3091,8 @@ testRefCount_LDADD = \
        $(XTRA_LIBS)
 
 tests_testRock_SOURCES = \
+       AccessLogEntry.cc \
+       AccessLogEntry.h \
        cbdata.cc \
        CacheDigest.h \
        CollapsedForwarding.h \
@@ -3181,6 +3191,7 @@ tests_testRock_SOURCES = \
        tests/stub_libeui.cc \
        tests/stub_libformat.cc \
        tests/stub_libicmp.cc \
+       tests/stub_liblog.cc \
        tests/stub_libmgr.cc \
        tests/stub_libsecurity.cc \
        tests/stub_MemStore.cc \
@@ -3226,6 +3237,7 @@ tests_testRock_LDADD = \
        base/libbase.la \
        mem/libmem.la \
        store/libstore.la \
+       $(ADAPTATION_LIBS) \
        sbuf/libsbuf.la \
        $(top_builddir)/lib/libmisccontainers.la \
        $(top_builddir)/lib/libmiscencoding.la \

diff --git a/src/Pipeline.cc b/src/Pipeline.cc
index b3b3290471f1e09cf095897f2bf1545820dacd54..af50bc5d47fb14527a6484f2517797c9fa9aa2ae 100644 (file)
--- a/src/Pipeline.cc
+++ b/src/Pipeline.cc
@@ -36,6 +36,18 @@ Pipeline::front() const
     return requests.front();
 }
 
+Http::StreamPointer
+Pipeline::back() const
+{
+    if (requests.empty()) {
+        debugs(33, 3, "Pipeline " << (void*)this << " empty");
+        return Http::StreamPointer();
+    }
+
+    debugs(33, 3, "Pipeline " << (void*)this << " back " << requests.back());
+    return requests.back();
+}
+
 void
 Pipeline::terminateAll(int xerrno)
 {

diff --git a/src/Pipeline.h b/src/Pipeline.h
index 2d2d12a482328d62a105991ce4f76b40fa20c87e..920211355890dba40eb4adefea33327c4e9a904d 100644 (file)
--- a/src/Pipeline.h
+++ b/src/Pipeline.h
@@ -46,6 +46,9 @@ public:
     /// get the first request context in the pipeline
     Http::StreamPointer front() const;
 
+    /// get the last request context in the pipeline
+    Http::StreamPointer back() const;
+
     /// how many requests are currently pipelined
     size_t count() const {return requests.size();}
 

diff --git a/src/client_side.cc b/src/client_side.cc
index 2caf7687bdb546838478b7844ef5a90eaa5cc6ba..fe7cbc1d7b958c66639e2b9873751733cc8c2157 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -584,6 +584,8 @@ void
 ConnStateData::swanSong()
 {
     debugs(33, 2, HERE << clientConnection);
+    checkLogging();
+
     flags.readMore = false;
     DeregisterRunner(this);
     clientdbEstablished(clientConnection->remote, -1);  /* decrement */
@@ -4026,3 +4028,35 @@ ConnStateData::unpinConnection(const bool andClose)
      * connection has gone away */
 }
 
+void
+ConnStateData::checkLogging()
+{
+    // if we are parsing request body, its request is responsible for logging
+    if (bodyPipe)
+        return;
+
+    // a request currently using this connection is responsible for logging
+    if (!pipeline.empty() && pipeline.back()->mayUseConnection())
+        return;
+
+    /* Either we are waiting for the very first transaction, or
+     * we are done with the Nth transaction and are waiting for N+1st.
+     * XXX: We assume that if anything was added to inBuf, then it could
+     * only be consumed by actions already covered by the above checks.
+     */
+
+    // do not log connections that closed after a transaction (it is normal)
+    // TODO: access_log needs ACLs to match received-no-bytes connections
+    // XXX: TLS may return here even though we got no transactions yet
+    // XXX: PROXY protocol may return here even though we got no
+    // transactions yet
+    if (receivedFirstByte_ && inBuf.isEmpty())
+        return;
+
+    /* Create a temporary ClientHttpRequest object. Its destructor will log. */
+    ClientHttpRequest http(this);
+    http.req_sz = inBuf.length();
+    char const *uri = "error:transaction-end-before-headers";
+    http.uri = xstrdup(uri);
+    setLogUri(&http, uri);
+}

diff --git a/src/client_side.h b/src/client_side.h
index c3d0761d6874b4b8f042f373968baaf1b1825997..9fa181faead3ecbffb4f025690c071e198830b6e 100644 (file)
--- a/src/client_side.h
+++ b/src/client_side.h
@@ -329,6 +329,7 @@ protected:
 private:
     /* ::Server API */
     virtual bool connFinishedWithConn(int size);
+    virtual void checkLogging();
 
     void clientAfterReadingRequests();
     bool concurrentRequestQueueFilled() const;

diff --git a/src/comm/TcpAcceptor.cc b/src/comm/TcpAcceptor.cc
index 9b74a1678965992c670411efd8d67896e8f42f76..0e78d30ccd7769074d469d79cc491d6a695626fe 100644 (file)
--- a/src/comm/TcpAcceptor.cc
+++ b/src/comm/TcpAcceptor.cc
@@ -9,6 +9,7 @@
 /* DEBUG: section 05    Listener Socket Handler */
 
 #include "squid.h"
+#include "acl/FilledChecklist.h"
 #include "anyp/PortCfg.h"
 #include "base/TextException.h"
 #include "client_db.h"
@@ -24,6 +25,7 @@
 #include "globals.h"
 #include "ip/Intercept.h"
 #include "ip/QosConfig.h"
+#include "log/access_log.h"
 #include "MasterXaction.h"
 #include "profiler/Profiler.h"
 #include "SquidConfig.h"
@@ -256,6 +258,18 @@ Comm::TcpAcceptor::okToAccept()
     return false;
 }
 
+static void
+logAcceptError(const Comm::ConnectionPointer &conn)
+{
+    AccessLogEntry::Pointer al = new AccessLogEntry;
+    al->tcpClient = conn;
+    al->url = "error:accept-client-connection";
+    ACLFilledChecklist ch(nullptr, nullptr, nullptr);
+    ch.src_addr = conn->remote;
+    ch.my_addr = conn->local;
+    accessLogLog(al, &ch);
+}
+
 void
 Comm::TcpAcceptor::acceptOne()
 {
@@ -281,6 +295,8 @@ Comm::TcpAcceptor::acceptOne()
 
         // A non-recoverable error; notify the caller */
         debugs(5, 5, HERE << "non-recoverable error:" << status() << " handler Subscription: " << theCallSub);
+        if (intendedForUserConnections())
+            logAcceptError(newConnDetails);
         notify(flag, newConnDetails);
         mustStop("Listener socket closed");
         return;

diff --git a/src/comm/TcpAcceptor.h b/src/comm/TcpAcceptor.h
index dbc89e80e4c8879b486e160647f839d232034978..532fbc468d9b0da1087814dfa7ff262b4b95c118 100644 (file)
--- a/src/comm/TcpAcceptor.h
+++ b/src/comm/TcpAcceptor.h
@@ -104,6 +104,8 @@ private:
     Comm::Flag oldAccept(Comm::ConnectionPointer &details);
     void setListen();
     void handleClosure(const CommCloseCbParams &io);
+    /// whether we are listening on one of the squid.conf *ports
+    bool intendedForUserConnections() const { return bool(listenPort_); }
 };
 
 } // namespace Comm

diff --git a/src/servers/Server.cc b/src/servers/Server.cc
index d554f30315f6ba521ad914ff87c1ac3e09ebcbef..daa5ed426415c6ce9246d9b44b40f9a08bf6cb25 100644 (file)
--- a/src/servers/Server.cc
+++ b/src/servers/Server.cc
@@ -167,6 +167,7 @@ Server::doClientRead(const CommIoCbParams &io)
     // case Comm::COMM_ERROR:
     default: // no other flags should ever occur
         debugs(33, 2, io.conn << ": got flag " << rd.flag << "; " << xstrerr(rd.xerrno));
+        checkLogging();
         pipeline.terminateAll(rd.xerrno);
         io.conn->close();
         return;

diff --git a/src/servers/Server.h b/src/servers/Server.h
index 481ce5758f9f312b954715ca4ca0be175ab443fe..cedad5c61398159c85741c387be4efee112e0b37 100644 (file)
--- a/src/servers/Server.h
+++ b/src/servers/Server.h
@@ -117,6 +117,9 @@ protected:
     void doClientRead(const CommIoCbParams &io);
     void clientWriteDone(const CommIoCbParams &io);
 
+    /// Log the current [attempt at] transaction if nobody else will.
+    virtual void checkLogging() = 0;
+
     AsyncCall::Pointer reader; ///< set when we are reading
     AsyncCall::Pointer writer; ///< set when we are writing
 };

diff --git a/src/tests/stub_icp.cc b/src/tests/stub_icp.cc
index 666c9306556bb9ad1eaaaca5e1fc2f025a4de12c..63b5c11d96f55e598501e5f2913dd9cbbf1c950b 100644 (file)
--- a/src/tests/stub_icp.cc
+++ b/src/tests/stub_icp.cc
@@ -9,7 +9,6 @@
 #include "squid.h"
 #include "comm/Connection.h"
 #include "ICP.h"
-#include "icp_opcode.h"
 
 #define STUB_API "icp_*.cc"
 #include "tests/STUB.h"
@@ -43,3 +42,7 @@ void icpConnectionClose(void) STUB
 int icpSetCacheKey(const cache_key * key) STUB_RETVAL(0)
 const cache_key *icpGetCacheKey(const char *url, int reqnum) STUB_RETVAL(NULL)
 
+#include "icp_opcode.h"
+// dynamically generated
+#include "icp_opcode.cc"
+

diff --git a/src/tests/stub_liblog.cc b/src/tests/stub_liblog.cc
index 50ca56d4f1807aa007cb2c36635c3e47d30a7c69..0cb7dbed3361f52dc1817a277e617c812cbf7740 100644 (file)
--- a/src/tests/stub_liblog.cc
+++ b/src/tests/stub_liblog.cc
@@ -12,6 +12,23 @@
 #define STUB_API "log/liblog.la"
 #include "tests/STUB.h"
 
+// XXX: these should be moved to a log/ *.h file
+#include "AccessLogEntry.h"
+/*
+AccessLogEntry::~AccessLogEntry() {STUB}
+void AccessLogEntry::getLogClientIp(char *, size_t) const STUB
+SBuf AccessLogEntry::getLogMethod() const STUB_RETVAL(SBuf())
+#if USE_OPENSSL
+AccessLogEntry::SslDetails::SslDetails() {STUB}
+#endif
+*/
+void accessLogLogTo(CustomLog *, AccessLogEntry::Pointer &, ACLChecklist *) STUB
+void accessLogLog(AccessLogEntry::Pointer &, ACLChecklist *) STUB
+void accessLogRotate(void) STUB
+void accessLogClose(void) STUB
+void accessLogInit(void) STUB
+const char *accessLogTime(time_t) STUB_RETVAL(nullptr)
+
 #include "log/access_log.h"
 void fvdbCountVia(const char *) STUB
 void fvdbCountForw(const char *) STUB