From: Eduard Bagdasaryan <eduard.bagdasaryan@measurement-factory.com>
Date: Fri, 22 Jul 2016 19:37:12 +0000 (+1200)
Subject: Fix some failed transactions not being logged.
X-Git-Tag: SQUID_4_0_13~22
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=da6dbcd110f7603f6d4cd9b3eef749311293fe77;p=thirdparty%2Fsquid.git

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 167eaf7297..088264ebb6 100644
--- 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 563d5cdb8d..8df789bfd0 100644
--- 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 b3b3290471..af50bc5d47 100644
--- 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 2d2d12a482..9202113558 100644
--- 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 2caf7687bd..fe7cbc1d7b 100644
--- 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 c3d0761d68..9fa181faea 100644
--- 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 9b74a16789..0e78d30ccd 100644
--- 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 dbc89e80e4..532fbc468d 100644
--- 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 d554f30315..daa5ed4264 100644
--- 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 481ce5758f..cedad5c613 100644
--- 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 666c930655..63b5c11d96 100644
--- 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 50ca56d4f1..0cb7dbed33 100644
--- 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