From d81657759f3ac9f3e688b4b2e8051166a23f01e1 Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Wed, 15 Nov 2017 22:11:19 -0700 Subject: [PATCH] Fixed %Hs location that was later overwritten with the correct to-client value). * Fixed %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 %hier.note(server, host); + request->hier.resetPeerNotes(server, host); if (al) - al->hier.note(server, host); + al->hier.resetPeerNotes(server, host); } /** diff --git a/src/HierarchyLogEntry.h b/src/HierarchyLogEntry.h index bd7f422e53..f6c5971a8a 100644 --- a/src/HierarchyLogEntry.h +++ b/src/HierarchyLogEntry.h @@ -17,16 +17,25 @@ #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 (%(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); diff --git a/src/clients/Client.cc b/src/clients/Client.cc index 642aa5100c..59032591ed 100644 --- a/src/clients/Client.cc +++ b/src/clients/Client.cc @@ -359,6 +359,9 @@ Client::sentRequestBody(const CommIoCbParams &io) 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; diff --git a/src/format/Format.cc b/src/format/Format.cc index 1f5edb145a..b907185d5b 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -592,17 +592,17 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS 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; } } diff --git a/src/http.cc b/src/http.cc index 0863fc029f..3b2e079d38 100644 --- a/src/http.cc +++ b/src/http.cc @@ -97,10 +97,6 @@ HttpStateData::HttpStateData(FwdState *theFwdState) : surrogateNoStore = false; serverConnection = fwd->serverConnection(); - // reset peer response time stats for %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 */ @@ -1189,12 +1185,7 @@ HttpStateData::readReply(const CommIoCbParams &io) ++ IOStats.Http.read_hist[bin]; - // update peer response time stats (%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 */ @@ -1581,6 +1572,9 @@ HttpStateData::wroteLast(const CommIoCbParams &io) 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; @@ -1590,6 +1584,9 @@ HttpStateData::wroteLast(const CommIoCbParams &io) 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; @@ -1620,7 +1617,6 @@ HttpStateData::sendComplete() commSetConnTimeout(serverConnection, Config.Timeout.read, timeoutCall); flags.request_sent = true; - request->hier.peer_http_request_sent = current_time; } void diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 0bb1b063e7..cd8f0d3f86 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -237,11 +237,7 @@ HierarchyLogEntry::HierarchyLogEntry() : 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; @@ -251,8 +247,10 @@ HierarchyLogEntry::HierarchyLogEntry() : } 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; @@ -269,6 +267,31 @@ HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *reque } } +/// 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() { @@ -290,7 +313,34 @@ HierarchyLogEntry::stopPeerClock(const bool force) 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 (%= 0 && responseTime.tv_usec >= 0; } static void diff --git a/src/store.cc b/src/store.cc index 2ffde12c8c..0884ca6784 100644 --- a/src/store.cc +++ b/src/store.cc @@ -1553,10 +1553,10 @@ StoreEntry::timestampsSet() // 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; diff --git a/src/tests/stub_access_log.cc b/src/tests/stub_access_log.cc index 1b856f1b8f..48dc5d62c8 100644 --- a/src/tests/stub_access_log.cc +++ b/src/tests/stub_access_log.cc @@ -14,6 +14,11 @@ 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), diff --git a/src/tunnel.cc b/src/tunnel.cc index bb899a49dd..b1153d0b78 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -416,6 +416,7 @@ TunnelStateData::readServer(char *, size_t len, Comm::Flag errcode, int xerrno) 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)) @@ -437,6 +438,7 @@ TunnelStateData::readConnectResponseDone(char *, size_t len, Comm::Flag errcode, 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)) @@ -522,14 +524,16 @@ TunnelStateData::handleConnectResponse(const size_t chunkSize) } // 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) { @@ -664,12 +668,15 @@ TunnelStateData::writeServerDone(char *, size_t len, Comm::Flag flag, int xerrno { 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; } @@ -719,6 +726,7 @@ TunnelStateData::Connection::dataSent(size_t amount) if (size_ptr) *size_ptr += amount; + } void @@ -733,12 +741,13 @@ TunnelStateData::writeClientDone(char *, size_t len, Comm::Flag flag, int xerrno { 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; } @@ -928,19 +937,24 @@ tunnelConnectedWriteDone(const Comm::ConnectionPointer &conn, char *, size_t len /// 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(); } @@ -971,6 +985,7 @@ tunnelConnected(const Comm::ConnectionPointer &server, void *data) 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); @@ -1043,7 +1058,7 @@ tunnelConnectDone(const Comm::ConnectionPointer &conn, Comm::Flag status, int xe 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; @@ -1343,7 +1358,7 @@ switchToTunnel(HttpRequest *request, Comm::ConnectionPointer &clientConn, Comm:: 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; -- 2.47.2