Hello,
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 two 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.
TODO: Squid still logs nothing when the connection closes before reading
request header data. We should probably make that behavior configurable
because such connections drain Squid resources (and, hence, should be
logged) but some browsers are known to routinely create them (and,
hence, logging them by default may create too much noise).
Regards,
Eduard.
Some failed transactions are not 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 two 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.
TODO: Squid still logs nothing when the connection closes before reading
request header data. We should probably make that behavior configurable
because such connections drain Squid resources (and, hence, should be
logged) but some browsers are known to routinely create them (and,
hence, logging them by default may create too much noise).
=== modified file 'src/Pipeline.cc'
--- src/Pipeline.cc 2016-01-24 17:41:43 +0000
+++ src/Pipeline.cc 2016-07-15 09:41:40 +0000
@@ -9,55 +9,67 @@
/*
* DEBUG: section 33 Client Request Pipeline
*/
#include "squid.h"
#include "anyp/PortCfg.h"
#include "client_side.h"
#include "Debug.h"
#include "http/Stream.h"
#include "Pipeline.h"
void
Pipeline::add(const Http::StreamPointer &c)
{
requests.push_back(c);
++nrequests;
debugs(33, 3, "Pipeline " << (void*)this << " add request " << nrequests << ' ' << c);
}
Http::StreamPointer
Pipeline::front() const
{
if (requests.empty()) {
debugs(33, 3, "Pipeline " << (void*)this << " empty");
return Http::StreamPointer();
}
debugs(33, 3, "Pipeline " << (void*)this << " front " << requests.front());
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)
{
while (!requests.empty()) {
Http::StreamPointer context = requests.front();
debugs(33, 3, "Pipeline " << (void*)this << " notify(" << xerrno << ") " << context);
context->noteIoError(xerrno);
context->finished(); // cleanup and self-deregister
assert(context != requests.front());
}
}
void
Pipeline::popMe(const Http::StreamPointer &which)
{
if (requests.empty())
return;
debugs(33, 3, "Pipeline " << (void*)this << " drop " << requests.front());
// in reality there may be multiple contexts doing processing in parallel.
// XXX: pipeline still assumes HTTP/1 FIFO semantics are obeyed.
assert(which == requests.front());
requests.pop_front();
}
=== modified file 'src/Pipeline.h'
--- src/Pipeline.h 2016-01-24 17:41:43 +0000
+++ src/Pipeline.h 2016-07-15 09:41:40 +0000
@@ -19,53 +19,56 @@
*
* Transactions in the queue may be fully processed, but not yet delivered,
* or only partially processed.
*
* - HTTP/1 pipelined requests can be processed out of order but
* responses MUST be written to the client in-order.
* The front() context is for the response writing transaction.
* The back context may still be reading a request payload/body.
* Other contexts are in deferred I/O state, but may be accumulating
* payload/body data to be written later.
*
* - HTTP/2 multiplexed streams can be processed and delivered in any order.
*
* For consistency we treat the pipeline as a FIFO queue in both cases.
*/
class Pipeline
{
Pipeline(const Pipeline &) = delete;
Pipeline & operator =(const Pipeline &) = delete;
public:
Pipeline() : nrequests(0) {}
~Pipeline() = default;
/// register a new request context to the pipeline
void add(const Http::StreamPointer &);
/// 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();}
/// whether there are none or any requests currently pipelined
bool empty() const {return requests.empty();}
/// tell everybody about the err, and abort all waiting requests
void terminateAll(const int xerrno);
/// deregister the front request from the pipeline
void popMe(const Http::StreamPointer &);
/// Number of requests seen in this pipeline (so far).
/// Includes incomplete transactions.
uint32_t nrequests;
private:
/// requests parsed from the connection but not yet completed.
std::list<Http::StreamPointer> requests;
};
#endif /* SQUID_SRC_PIPELINE_H */
=== modified file 'src/client_side.cc'
--- src/client_side.cc 2016-07-11 10:57:11 +0000
+++ src/client_side.cc 2016-07-15 12:29:13 +0000
@@ -557,60 +557,62 @@
debugs(33, 2, "WARNING: Graceful closure on " << clientConnection << " due to connection-auth erase from " << by);
auth_->releaseAuthServer();
auth_ = NULL;
// XXX: need to test whether the connection re-auth challenge is sent. If not, how to trigger it from here.
// NP: the current situation seems to fix challenge loops in Safari without visible issues in others.
// we stop receiving more traffic but can leave the Job running to terminate after the error or challenge is delivered.
stopReceiving("connection-auth removed");
return;
}
// clobbered with alternative credentials
if (aur != auth_) {
debugs(33, 2, "ERROR: Closing " << clientConnection << " due to change of connection-auth from " << by);
auth_->releaseAuthServer();
auth_ = NULL;
// this is a fatal type of problem.
// Close the connection immediately with TCP RST to abort all traffic flow
comm_reset_close(clientConnection);
return;
}
/* NOT REACHABLE */
}
#endif
// cleans up before destructor is called
void
ConnStateData::swanSong()
{
debugs(33, 2, HERE << clientConnection);
+ checkLogging();
+
flags.readMore = false;
DeregisterRunner(this);
clientdbEstablished(clientConnection->remote, -1); /* decrement */
pipeline.terminateAll(0);
unpinConnection(true);
Server::swanSong(); // closes the client connection
#if USE_AUTH
// NP: do this bit after closing the connections to avoid side effects from unwanted TCP RST
setAuth(NULL, "ConnStateData::SwanSong cleanup");
#endif
flags.swanSang = true;
}
bool
ConnStateData::isOpen() const
{
return cbdataReferenceValid(this) && // XXX: checking "this" in a method
Comm::IsConnOpen(clientConnection) &&
!fd_table[clientConnection->fd].closing();
}
ConnStateData::~ConnStateData()
{
debugs(33, 3, HERE << clientConnection);
if (isOpen())
@@ -2114,64 +2116,60 @@
void
ConnStateData::receivedFirstByte()
{
if (receivedFirstByte_)
return;
receivedFirstByte_ = true;
// Set timeout to Config.Timeout.request
typedef CommCbMemFunT<ConnStateData, CommTimeoutCbParams> TimeoutDialer;
AsyncCall::Pointer timeoutCall = JobCallback(33, 5,
TimeoutDialer, this, ConnStateData::requestTimeout);
commSetConnTimeout(clientConnection, Config.Timeout.request, timeoutCall);
}
/**
* Attempt to parse one or more requests from the input buffer.
* Returns true after completing parsing of at least one request [header]. That
* includes cases where parsing ended with an error (e.g., a huge request).
*/
bool
ConnStateData::clientParseRequests()
{
bool parsed_req = false;
debugs(33, 5, HERE << clientConnection << ": attempting to parse");
// Loop while we have read bytes that are not needed for producing the body
// On errors, bodyPipe may become nil, but readMore will be cleared
while (!inBuf.isEmpty() && !bodyPipe && flags.readMore) {
- /* Don't try to parse if the buffer is empty */
- if (inBuf.isEmpty())
- break;
-
/* Limit the number of concurrent requests */
if (concurrentRequestQueueFilled())
break;
// try to parse the PROXY protocol header magic bytes
if (needProxyProtocolHeader_ && !parseProxyProtocolHeader())
break;
if (Http::Stream *context = parseOneRequest()) {
debugs(33, 5, clientConnection << ": done parsing a request");
AsyncCall::Pointer timeoutCall = commCbCall(5, 4, "clientLifetimeTimeout",
CommTimeoutCbPtrFun(clientLifetimeTimeout, context->http));
commSetConnTimeout(clientConnection, Config.Timeout.lifetime, timeoutCall);
context->registerWithConn();
processParsedRequest(context);
parsed_req = true; // XXX: do we really need to parse everything right NOW ?
if (context->mayUseConnection()) {
debugs(33, 3, HERE << "Not parsing new requests, as this request may need the connection");
break;
}
} else {
debugs(33, 5, clientConnection << ": not enough request data: " <<
inBuf.length() << " < " << Config.maxRequestHeaderSize);
Must(inBuf.length() < Config.maxRequestHeaderSize);
break;
@@ -4003,30 +4001,57 @@
void
ConnStateData::unpinConnection(const bool andClose)
{
debugs(33, 3, HERE << pinning.serverConnection);
if (pinning.peer)
cbdataReferenceDone(pinning.peer);
if (Comm::IsConnOpen(pinning.serverConnection)) {
if (pinning.closeHandler != NULL) {
comm_remove_close_handler(pinning.serverConnection->fd, pinning.closeHandler);
pinning.closeHandler = NULL;
}
stopPinnedConnectionMonitoring();
// close the server side socket if requested
if (andClose)
pinning.serverConnection->close();
pinning.serverConnection = NULL;
}
safe_free(pinning.host);
pinning.zeroReply = false;
/* NOTE: pinning.pinned should be kept. This combined with fd == -1 at the end of a request indicates that the host
* 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. */
+
+ // do not log connections that sent us no bytes (TODO: make configurable)
+ // do not log connections that closed after a transaction (those are normal)
+ // XXX: We assume that all inBuf consumption cases were covered above.
+ if (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);
+}
=== modified file 'src/client_side.h'
--- src/client_side.h 2016-05-18 16:26:16 +0000
+++ src/client_side.h 2016-07-15 09:41:40 +0000
@@ -302,60 +302,61 @@
err_type handleChunkedRequestBody();
void startPinnedConnectionMonitoring();
void clientPinnedConnectionRead(const CommIoCbParams &io);
#if USE_OPENSSL
/// Handles a ready-for-reading TLS squid-to-server connection that
/// we thought was idle.
/// \return false if and only if the connection should be closed.
bool handleIdleClientPinnedTlsRead();
#endif
/// parse input buffer prefix into a single transfer protocol request
/// return NULL to request more header bytes (after checking any limits)
/// use abortRequestParsing() to handle parsing errors w/o creating request
virtual Http::Stream *parseOneRequest() = 0;
/// start processing a freshly parsed request
virtual void processParsedRequest(Http::Stream *) = 0;
/// returning N allows a pipeline of 1+N requests (see pipeline_prefetch)
virtual int pipelinePrefetchMax() const;
/// timeout to use when waiting for the next request
virtual time_t idleTimeout() const = 0;
BodyPipe::Pointer bodyPipe; ///< set when we are reading request body
private:
/* ::Server API */
virtual bool connFinishedWithConn(int size);
+ virtual void checkLogging();
void clientAfterReadingRequests();
bool concurrentRequestQueueFilled() const;
void pinNewConnection(const Comm::ConnectionPointer &pinServer, HttpRequest *request, CachePeer *aPeer, bool auth);
/* PROXY protocol functionality */
bool proxyProtocolValidateClient();
bool parseProxyProtocolHeader();
bool parseProxy1p0();
bool parseProxy2p0();
bool proxyProtocolError(const char *reason);
/// whether PROXY protocol header is still expected
bool needProxyProtocolHeader_;
#if USE_AUTH
/// some user details that can be used to perform authentication on this connection
Auth::UserRequest::Pointer auth_;
#endif
/// the parser state for current HTTP/1.x input buffer processing
Http1::RequestParserPointer parser_;
#if USE_OPENSSL
bool switchedToHttps_;
bool parsingTlsHandshake; ///< whether we are getting/parsing TLS Hello bytes
/// The SSL server host name appears in CONNECT request or the server ip address for the intercepted requests
String sslConnectHostOrIp; ///< The SSL server host name as passed in the CONNECT request
=== modified file 'src/comm/TcpAcceptor.cc'
--- src/comm/TcpAcceptor.cc 2016-04-03 23:41:58 +0000
+++ src/comm/TcpAcceptor.cc 2016-07-15 12:44:50 +0000
@@ -1,56 +1,58 @@
/*
* Copyright (C) 1996-2016 The Squid Software Foundation and contributors
*
* Squid software is distributed under GPLv2+ license and includes
* contributions from numerous individuals and organizations.
* Please see the COPYING and CONTRIBUTORS files for details.
*/
/* 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"
#include "comm/AcceptLimiter.h"
#include "comm/comm_internal.h"
#include "comm/Connection.h"
#include "comm/Loops.h"
#include "comm/TcpAcceptor.h"
#include "CommCalls.h"
#include "eui/Config.h"
#include "fd.h"
#include "fde.h"
#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"
#include "SquidTime.h"
#include "StatCounters.h"
#include <cerrno>
#ifdef HAVE_NETINET_TCP_H
// required for accept_filter to build.
#include <netinet/tcp.h>
#endif
CBDATA_NAMESPACED_CLASS_INIT(Comm, TcpAcceptor);
Comm::TcpAcceptor::TcpAcceptor(const Comm::ConnectionPointer &newConn, const char *, const Subscription::Pointer &aSub) :
AsyncJob("Comm::TcpAcceptor"),
errcode(0),
isLimited(0),
theCallSub(aSub),
conn(newConn),
listenPort_()
{}
Comm::TcpAcceptor::TcpAcceptor(const AnyP::PortCfgPointer &p, const char *, const Subscription::Pointer &aSub) :
AsyncJob("Comm::TcpAcceptor"),
errcode(0),
isLimited(0),
theCallSub(aSub),
conn(p->listenConn),
listenPort_(p)
@@ -229,85 +231,98 @@
if (!okToAccept()) {
AcceptLimiter::Instance().defer(afd);
} else {
afd->acceptNext();
}
SetSelect(fd, COMM_SELECT_READ, Comm::TcpAcceptor::doAccept, afd, 0);
} catch (const std::exception &e) {
fatalf("FATAL: error while accepting new client connection: %s\n", e.what());
} catch (...) {
fatal("FATAL: error while accepting new client connection: [unknown]\n");
}
}
bool
Comm::TcpAcceptor::okToAccept()
{
static time_t last_warn = 0;
if (fdNFree() >= RESERVED_FD)
return true;
if (last_warn + 15 < squid_curtime) {
debugs(5, DBG_CRITICAL, "WARNING! Your cache is running out of filedescriptors");
last_warn = squid_curtime;
}
return false;
}
+static void logAcceptError(const Comm::ConnectionPointer &conn)
+{
+ AccessLogEntry::Pointer al = new AccessLogEntry;
+ al->tcpClient = conn;
+ al->url = "error:transaction-end-before-headers";
+ ACLFilledChecklist ch(NULL, NULL, NULL);
+ ch.src_addr = conn->remote;
+ ch.my_addr = conn->local;
+ accessLogLog(al, &ch);
+}
+
void
Comm::TcpAcceptor::acceptOne()
{
/*
* We don't worry about running low on FDs here. Instead,
* doAccept() will use AcceptLimiter if we reach the limit
* there.
*/
/* Accept a new connection */
ConnectionPointer newConnDetails = new Connection();
const Comm::Flag flag = oldAccept(newConnDetails);
/* Check for errors */
if (!newConnDetails->isOpen()) {
if (flag == Comm::NOMESSAGE) {
/* register interest again */
debugs(5, 5, HERE << "try later: " << conn << " handler Subscription: " << theCallSub);
SetSelect(conn->fd, COMM_SELECT_READ, doAccept, this, 0);
return;
}
// 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;
}
debugs(5, 5, HERE << "Listener: " << conn <<
" accepted new connection " << newConnDetails <<
" handler Subscription: " << theCallSub);
notify(flag, newConnDetails);
}
void
Comm::TcpAcceptor::acceptNext()
{
Must(IsConnOpen(conn));
debugs(5, 2, HERE << "connection on " << conn);
acceptOne();
}
void
Comm::TcpAcceptor::notify(const Comm::Flag flag, const Comm::ConnectionPointer &newConnDetails) const
{
// listener socket handlers just abandon the port with Comm::ERR_CLOSING
// it should only happen when this object is deleted...
if (flag == Comm::ERR_CLOSING) {
return;
}
if (theCallSub != NULL) {
AsyncCall::Pointer call = theCallSub->callback();
=== modified file 'src/comm/TcpAcceptor.h'
--- src/comm/TcpAcceptor.h 2016-01-01 00:12:18 +0000
+++ src/comm/TcpAcceptor.h 2016-07-15 12:45:05 +0000
@@ -77,36 +77,38 @@
int errcode;
protected:
friend class AcceptLimiter;
int32_t isLimited; ///< whether this socket is delayed and on the AcceptLimiter queue.
private:
Subscription::Pointer theCallSub; ///< used to generate AsyncCalls handling our events.
/// conn being listened on for new connections
/// Reserved for read-only use.
ConnectionPointer conn;
/// configuration details of the listening port (if provided)
AnyP::PortCfgPointer listenPort_;
/// listen socket closure handler
AsyncCall::Pointer closer_;
/// Method to test if there are enough file descriptors to open a new client connection
/// if not the accept() will be postponed
static bool okToAccept();
/// Method callback for whenever an FD is ready to accept a client connection.
static void doAccept(int fd, void *data);
void acceptOne();
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
#endif /* SQUID_COMM_TCPACCEPTOR_H */
=== modified file 'src/servers/Server.cc'
--- src/servers/Server.cc 2016-06-14 16:54:23 +0000
+++ src/servers/Server.cc 2016-07-15 09:41:40 +0000
@@ -140,60 +140,61 @@
if (!handleReadData())
return;
/* Continue to process previously read data */
break;
case Comm::ENDFILE: // close detected by 0-byte read
debugs(33, 5, io.conn << " closed?");
if (connFinishedWithConn(rd.size)) {
clientConnection->close();
return;
}
/* It might be half-closed, we can't tell */
fd_table[io.conn->fd].flags.socket_eof = true;
commMarkHalfClosed(io.conn->fd);
fd_note(io.conn->fd, "half-closed");
/* There is one more close check at the end, to detect aborted
* (partial) requests. At this point we can't tell if the request
* is partial.
*/
/* Continue to process previously read data */
break;
// 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;
}
afterClientRead();
}
/** callback handling the Comm::Write completion
*
* Will call afterClientWrite(size_t) to sync the I/O state.
* Then writeSomeData() to initiate any followup writes that
* could be immediately done.
*/
void
Server::clientWriteDone(const CommIoCbParams &io)
{
debugs(33,5, io.conn);
Must(writer != nullptr);
writer = nullptr;
/* Bail out quickly on Comm::ERR_CLOSING - close handlers will tidy up */
if (io.flag == Comm::ERR_CLOSING || !Comm::IsConnOpen(clientConnection)) {
debugs(33,5, io.conn << " closing Bailout.");
return;
}
Must(io.conn->fd == clientConnection->fd);
if (io.flag && pipeline.front())
=== modified file 'src/servers/Server.h'
--- src/servers/Server.h 2016-06-14 16:54:23 +0000
+++ src/servers/Server.h 2016-07-15 09:41:40 +0000
@@ -90,36 +90,39 @@
public:
/// grows the available read buffer space (if possible)
void maybeMakeSpaceAvailable();
// Client TCP connection details from comm layer.
Comm::ConnectionPointer clientConnection;
/**
* The transfer protocol currently being spoken on this connection.
* HTTP/1.x CONNECT, HTTP/1.1 Upgrade and HTTP/2 SETTINGS offer the
* ability to change protocols on the fly.
*/
AnyP::ProtocolVersion transferProtocol;
/// Squid listening port details where this connection arrived.
AnyP::PortCfgPointer port;
/// read I/O buffer for the client connection
SBuf inBuf;
bool receivedFirstByte_; ///< true if at least one byte received on this connection
/// set of requests waiting to be serviced
Pipeline pipeline;
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
};
#endif /* SQUID_SERVERS_SERVER_H */
_______________________________________________
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev
