This change started as a %<Hs fix described in the first bullet but
subsequent testing exposed the bug described in the second bullet,
fixing which resulted in other related fixes/improvements:
* Fixed %<Hs for received CONNECT errors: Correctly store the response
status code for %<Hs logging (instead of misplacing it in the %>Hs
location that was later overwritten with the correct to-client value).
* Fixed %<pt and %<tt for received CONNECT errors: Squid tunneling code
was missing message I/O timing maintenance required for those %codes.
* Probably fixed %<bs logging bug on forwarding retries: Squid did not
clear the (bodyBytesRead) counter between retries.
* Possibly improved %<Hs, %<pt, %<tt, %<bs logging on SslBump errors:
request->hier member did not copy all the sslServerBump->request->hier
details when generating an error response in
ConnStateData::serveDelayedError().
* Probably fixed a server.all.kbytes_out and server.other.kbytes_out
statistics bug: Squid missed written CONNECT request header bytes.
Also improved HierarchyLogEntry-related code: Reduced code duplication,
removed unnecessary destructor, and described the class. Removed
peer_http_request_sent timestamp because it ought to be equal to the
last request write time (now peer_last_write_).
TODO: Relay (expected) peer CONNECT error responses to users (instead of
hiding them behind a Squid-generated ERR_CONNECT_FAIL) and support %<h.
FwdState::syncHierNote(const Comm::ConnectionPointer &server, const char *host)
{
if (request)
- request->hier.note(server, host);
+ request->hier.resetPeerNotes(server, host);
if (al)
- al->hier.note(server, host);
+ al->hier.resetPeerNotes(server, host);
}
/**
#include "PingData.h"
#include "rfc2181.h"
+/// Maintains peer selection details and peer I/O stats.
+/// Here, "peer" is an origin server or CachePeer.
class HierarchyLogEntry
{
public:
HierarchyLogEntry();
- ~HierarchyLogEntry() { tcpServer = NULL; };
- /// Record details from a new server connection.
- /// call this whenever the destination server changes.
- void note(const Comm::ConnectionPointer &server, const char *requestedHost);
+ /// Start recording new origin server or cache peer connection details.
+ /// Call this when trying to connect to a peer.
+ void resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost);
+
+ /// Account for a TCP peer read. Maintains peer response time stats (%<pt).
+ /// Call this after each successful peer socket read(2).
+ void notePeerRead();
+
+ /// Account for a TCP peer write. Maintains peer response time stats (%<pt).
+ /// Call this after each peer socket write(2), including failed ones.
+ void notePeerWrite();
/// Start recording total time spent communicating with peers
void startPeerClock();
*/
void stopPeerClock(const bool force);
- /// Return the total time spent communicating with peers
- void totalResponseTime(struct timeval &responseTime);
+ /// Estimates response generation and sending delay at the last peer.
+ /// \returns whether the estimate (stored in `responseTime`) is available.
+ bool peerResponseTime(struct timeval &responseTime);
+
+ /// Estimates the total time spent communicating with peers.
+ /// \returns whether the estimate (stored in `responseTime`) is available.
+ bool totalResponseTime(struct timeval &responseTime);
public:
hier_code code;
struct timeval store_complete_stop;
Http::StatusCode peer_reply_status; ///< last HTTP status code received
- timeval peer_http_request_sent; ///< last peer finished writing req
- struct timeval peer_response_time; ///< last peer response delay
Comm::ConnectionPointer tcpServer; ///< TCP/IP level details of the last peer/server connection
int64_t bodyBytesRead; ///< number of body bytes received from the next hop or -1
private:
+ void clearPeerNotes();
+
timeval firstConnStart_; ///< first connection use among all peers
+ struct timeval peer_last_read_; ///< time of the last read from the last peer
+ struct timeval peer_last_write_; ///< time of the last write to the last peer
struct timeval totalResponseTime_; ///< cumulative for all peers
};
clientReplyContext *repContext = dynamic_cast<clientReplyContext *>(node->data.getRaw());
assert (repContext);
- // Fill the server IP and hostname for error page generation.
- HttpRequest::Pointer const & peekerRequest = sslServerBump->request;
- request->hier.note(peekerRequest->hier.tcpServer, request->url.host());
+ request->hier = sslServerBump->request->hier;
// Create an error object and fill it
ErrorState *err = new ErrorState(ERR_SECURE_CONNECT_FAIL, Http::scServiceUnavailable, request);
return; // do nothing;
}
+ // both successful and failed writes affect response times
+ request->hier.notePeerWrite();
+
if (io.flag) {
debugs(11, DBG_IMPORTANT, "sentRequestBody error: FD " << io.fd << ": " << xstrerr(io.xerrno));
ErrorState *err;
break;
case LFT_PEER_RESPONSE_TIME:
- if (al->hier.peer_response_time.tv_sec != -1) {
- outtv = al->hier.peer_response_time;
+ struct timeval peerResponseTime;
+ if (al->hier.peerResponseTime(peerResponseTime)) {
+ outtv = peerResponseTime;
doMsec = 1;
}
break;
case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: {
- timeval total_response_time;
- al->hier.totalResponseTime(total_response_time);
- if (total_response_time.tv_sec != -1) {
- outtv = total_response_time;
+ struct timeval totalResponseTime;
+ if (al->hier.totalResponseTime(totalResponseTime)) {
+ outtv = totalResponseTime;
doMsec = 1;
}
}
surrogateNoStore = false;
serverConnection = fwd->serverConnection();
- // reset peer response time stats for %<pt
- request->hier.peer_http_request_sent.tv_sec = 0;
- request->hier.peer_http_request_sent.tv_usec = 0;
-
if (fwd->serverConnection() != NULL)
_peer = cbdataReference(fwd->serverConnection()->getPeer()); /* might be NULL */
++ IOStats.Http.read_hist[bin];
- // update peer response time stats (%<pt)
- const timeval &sent = request->hier.peer_http_request_sent;
- if (sent.tv_sec)
- tvSub(request->hier.peer_response_time, sent, current_time);
- else
- request->hier.peer_response_time.tv_sec = -1;
+ request->hier.notePeerRead();
}
/* Continue to process previously read data */
entry->mem_obj->checkUrlChecksum();
#endif
+ // XXX: Keep in sync with Client::sentRequestBody().
+ // TODO: Extract common parts.
+
if (io.size > 0) {
fd_bytes(io.fd, io.size, FD_WRITE);
statCounter.server.all.kbytes_out += io.size;
if (io.flag == Comm::ERR_CLOSING)
return;
+ // both successful and failed writes affect response times
+ request->hier.notePeerWrite();
+
if (io.flag) {
ErrorState *err = new ErrorState(ERR_WRITE_ERROR, Http::scBadGateway, fwd->request);
err->xerrno = io.xerrno;
commSetConnTimeout(serverConnection, Config.Timeout.read, timeoutCall);
flags.request_sent = true;
- request->hier.peer_http_request_sent = current_time;
}
void
store_complete_stop.tv_sec =0;
store_complete_stop.tv_usec =0;
- peer_http_request_sent.tv_sec = 0;
- peer_http_request_sent.tv_usec = 0;
-
- peer_response_time.tv_sec = -1;
- peer_response_time.tv_usec = 0;
+ clearPeerNotes();
totalResponseTime_.tv_sec = -1;
totalResponseTime_.tv_usec = 0;
}
void
-HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *requestedHost)
+HierarchyLogEntry::resetPeerNotes(const Comm::ConnectionPointer &server, const char *requestedHost)
{
+ clearPeerNotes();
+
tcpServer = server;
if (tcpServer == NULL) {
code = HIER_NONE;
}
}
+/// forget previous notePeerRead() and notePeerWrite() calls (if any)
+void
+HierarchyLogEntry::clearPeerNotes()
+{
+ peer_last_read_.tv_sec = 0;
+ peer_last_read_.tv_usec = 0;
+
+ peer_last_write_.tv_sec = 0;
+ peer_last_write_.tv_usec = 0;
+
+ bodyBytesRead = -1;
+}
+
+void
+HierarchyLogEntry::notePeerRead()
+{
+ peer_last_read_ = current_time;
+}
+
+void
+HierarchyLogEntry::notePeerWrite()
+{
+ peer_last_write_ = current_time;
+}
+
void
HierarchyLogEntry::startPeerClock()
{
tvSub(totalResponseTime_, firstConnStart_, current_time);
}
-void
+bool
+HierarchyLogEntry::peerResponseTime(struct timeval &responseTime)
+{
+ // no I/O whatsoever
+ if (peer_last_write_.tv_sec <= 0 && peer_last_read_.tv_sec <= 0)
+ return false;
+
+ // accommodate read without (completed) write
+ const auto last_write = peer_last_write_.tv_sec > 0 ?
+ peer_last_write_ : peer_last_read_;
+
+ // accommodate write without (completed) read
+ const auto last_read = peer_last_read_.tv_sec > 0 ?
+ peer_last_read_ : peer_last_write_;
+
+ tvSub(responseTime, last_write, last_read);
+ // The peer response time (%<pt) stopwatch is currently defined to start
+ // when we wrote the entire request. Thus, if we wrote something after the
+ // last read, report zero peer response time.
+ if (responseTime.tv_sec < 0) {
+ responseTime.tv_sec = 0;
+ responseTime.tv_usec = 0;
+ }
+
+ return true;
+}
+
+bool
HierarchyLogEntry::totalResponseTime(struct timeval &responseTime)
{
// This should not really happen, but there may be rare code
stopPeerClock(false);
responseTime = totalResponseTime_;
+ return responseTime.tv_sec >= 0 && responseTime.tv_usec >= 0;
}
static void
// compensate for Squid-to-server and server-to-Squid delays
if (mem_obj && mem_obj->request) {
- const time_t request_sent =
- mem_obj->request->hier.peer_http_request_sent.tv_sec;
- if (0 < request_sent && request_sent < squid_curtime)
- served_date -= (squid_curtime - request_sent);
+ struct timeval responseTime;
+ if (mem_obj->request->hier.peerResponseTime(responseTime) &&
+ responseTime.tv_sec < squid_curtime)
+ served_date -= (squid_curtime - responseTime.tv_sec);
}
time_t exp = 0;
HierarchyLogEntry::HierarchyLogEntry() STUB
+void HierarchyLogEntry::notePeerRead() STUB
+void HierarchyLogEntry::notePeerWrite() STUB
+bool HierarchyLogEntry::peerResponseTime(struct timeval &) STUB_RETVAL(false)
+bool HierarchyLogEntry::totalResponseTime(struct timeval &) STUB_RETVAL(false)
+
ping_data::ping_data() :
n_sent(0),
n_recv(0),
server.bytesIn(len);
statCounter.server.all.kbytes_in += len;
statCounter.server.other.kbytes_in += len;
+ request->hier.notePeerRead();
}
if (keepGoingAfterRead(len, errcode, xerrno, server, client))
server.bytesIn(len);
statCounter.server.all.kbytes_in += len;
statCounter.server.other.kbytes_in += len;
+ request->hier.notePeerRead();
}
if (keepGoingAfterRead(len, errcode, xerrno, server, client))
}
// CONNECT response was successfully parsed
- *status_ptr = rep.sline.status();
+ request->hier.peer_reply_status = rep.sline.status();
// we need to relay the 401/407 responses when login=PASS(THRU)
const CachePeer *peer = server.conn->getPeer();
const char *pwd = (peer ? peer->login : nullptr);
- const bool relay = pwd && (strcmp(pwd, "PASS") == 0 || strcmp(pwd, "PASSTHRU") == 0) &&
- (*status_ptr == Http::scProxyAuthenticationRequired ||
- *status_ptr == Http::scUnauthorized);
+ const bool authRelated =
+ rep.sline.status() == Http::scUnauthorized ||
+ rep.sline.status() == Http::scProxyAuthenticationRequired;
+ const bool relay = authRelated && pwd &&
+ (strcmp(pwd, "PASS") == 0 || strcmp(pwd, "PASSTHRU") == 0);
// bail if we did not get an HTTP 200 (Connection Established) response
if (rep.sline.status() != Http::scOkay) {
{
debugs(26, 3, HERE << server.conn << ", " << len << " bytes written, flag=" << flag);
+ if (flag == Comm::ERR_CLOSING)
+ return;
+
+ request->hier.notePeerWrite();
+
/* Error? */
if (flag != Comm::OK) {
- if (flag != Comm::ERR_CLOSING) {
- debugs(26, 4, HERE << "calling TunnelStateData::server.error(" << xerrno <<")");
- server.error(xerrno); // may call comm_close
- }
+ debugs(26, 4, "to-server write failed: " << xerrno);
+ server.error(xerrno); // may call comm_close
return;
}
if (size_ptr)
*size_ptr += amount;
+
}
void
{
debugs(26, 3, HERE << client.conn << ", " << len << " bytes written, flag=" << flag);
+ if (flag == Comm::ERR_CLOSING)
+ return;
+
/* Error? */
if (flag != Comm::OK) {
- if (flag != Comm::ERR_CLOSING) {
- debugs(26, 4, HERE << "Closing client connection due to comm flags.");
- client.error(xerrno); // may call comm_close
- }
+ debugs(26, 4, "from-client read failed: " << xerrno);
+ client.error(xerrno); // may call comm_close
return;
}
/// Called when we are done writing CONNECT request to a peer.
static void
-tunnelConnectReqWriteDone(const Comm::ConnectionPointer &conn, char *, size_t, Comm::Flag flag, int, void *data)
+tunnelConnectReqWriteDone(const Comm::ConnectionPointer &conn, char *, size_t ioSize, Comm::Flag flag, int, void *data)
{
TunnelStateData *tunnelState = (TunnelStateData *)data;
debugs(26, 3, conn << ", flag=" << flag);
tunnelState->server.writer = NULL;
assert(tunnelState->waitingForConnectRequest());
+ tunnelState->request->hier.notePeerWrite();
+
if (flag != Comm::OK) {
*tunnelState->status_ptr = Http::scInternalServerError;
tunnelErrorComplete(conn->fd, data, 0);
return;
}
+ statCounter.server.all.kbytes_out += ioSize;
+ statCounter.server.other.kbytes_out += ioSize;
+
tunnelState->connectReqWriting = false;
tunnelState->connectExchangeCheckpoint();
}
if (!tunnelState->clientExpectsConnectResponse())
tunnelStartShoveling(tunnelState); // ssl-bumped connection, be quiet
else {
+ *tunnelState->status_ptr = Http::scOkay;
AsyncCall::Pointer call = commCbCall(5,5, "tunnelConnectedWriteDone",
CommIoCbPtrFun(tunnelConnectedWriteDone, tunnelState));
tunnelState->client.write(conn_established, strlen(conn_established), call, NULL);
tunnelState->server.setDelayId(DelayId());
#endif
- tunnelState->request->hier.note(conn, tunnelState->getHost());
+ tunnelState->request->hier.resetPeerNotes(conn, tunnelState->getHost());
tunnelState->server.conn = conn;
tunnelState->request->peer_host = conn->getPeer() ? conn->getPeer()->host : NULL;
fd_table[clientConn->fd].read_method = &default_read_method;
fd_table[clientConn->fd].write_method = &default_write_method;
- request->hier.note(srvConn, tunnelState->getHost());
+ request->hier.resetPeerNotes(srvConn, tunnelState->getHost());
tunnelState->server.conn = srvConn;
projects / thirdparty / squid.git / commitdiff
