From: Alex Rousskov Date: Thu, 16 Nov 2017 05:11:19 +0000 (-0700) Subject: 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 fe6fa57ba5..b8ee0995b9 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 dfd98b3086..c72ec76340 100644 --- a/src/clients/Client.cc +++ b/src/clients/Client.cc @@ -376,6 +376,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 53bc708cb5..d5d16e0146 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 12b076cb8c..2876b44382 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 */ @@ -1188,12 +1184,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 */ @@ -1580,6 +1571,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; @@ -1589,6 +1583,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; @@ -1619,7 +1616,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 4c4be3e70f..286738f6a0 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 a0f6980281..606d9ee30b 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 4d33cb190e..64ccf4ee0d 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 45798c0a79..d46297150a 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -404,6 +404,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)) @@ -425,6 +426,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)) @@ -515,7 +517,7 @@ TunnelStateData::handleConnectResponse(const size_t chunkSize) } // CONNECT response was successfully parsed - *status_ptr = rep.sline.status(); + request->hier.peer_reply_status = rep.sline.status(); // bail if we did not get an HTTP 200 (Connection Established) response if (rep.sline.status() != Http::scOkay) { @@ -651,12 +653,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; } @@ -706,6 +711,7 @@ TunnelStateData::Connection::dataSent(size_t amount) if (size_ptr) *size_ptr += amount; + } void @@ -720,12 +726,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; } @@ -915,19 +922,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(); } @@ -958,6 +970,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); @@ -1024,7 +1037,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; @@ -1287,7 +1300,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;