%peerType = ORIGINAL_DST; p->remote = clientConn->local; getOutgoingAddress(request, p); debugs(17, 3, HERE << "using client original destination: " << *p); serverDestinations.push_back(p); } #endif void FwdState::completed() { if (flags.forward_completed) { debugs(17, DBG_IMPORTANT, HERE << "FwdState::completed called on a completed request! Bad!"); return; } flags.forward_completed = true; + request->hier.stopPeerClock(false); + if (EBIT_TEST(entry->flags, ENTRY_ABORTED)) { debugs(17, 3, HERE << "entry aborted"); return ; } #if URL_CHECKSUM_DEBUG entry->mem_obj->checkUrlChecksum(); #endif if (entry->store_status == STORE_PENDING) { if (entry->isEmpty()) { if (!err) // we quit (e.g., fd closed) before an error or content fail(new ErrorState(ERR_READ_ERROR, Http::scBadGateway, request)); assert(err); errorAppendEntry(entry, err); err = NULL; #if USE_OPENSSL if (request->flags.sslPeek && request->clientConnectionManager.valid()) { CallJobHere1(17, 4, request->clientConnectionManager, ConnStateData, @@ -626,40 +628,42 @@ retryOrBail(); } void FwdState::retryOrBail() { if (checkRetry()) { debugs(17, 3, HERE << "re-forwarding (" << n_tries << " tries, " << (squid_curtime - start_t) << " secs)"); // we should retry the same destination if it failed due to pconn race if (pconnRace == raceHappened) debugs(17, 4, HERE << "retrying the same destination"); else serverDestinations.erase(serverDestinations.begin()); // last one failed. try another. startConnectionOrFail(); return; } // TODO: should we call completed() here and move doneWithRetries there? doneWithRetries(); + request->hier.stopPeerClock(false); + if (self != NULL && !err && shutting_down) { ErrorState *anErr = new ErrorState(ERR_SHUTTING_DOWN, Http::scServiceUnavailable, request); errorAppendEntry(entry, anErr); } self = NULL; // refcounted } // If the Server quits before nibbling at the request body, the body sender // will not know (so that we can retry). Call this if we will not retry. We // will notify the sender so that it does not get stuck waiting for space. void FwdState::doneWithRetries() { if (request && request->body_pipe != NULL) request->body_pipe->expectNoConsumption(); } // called by the server that failed after calling unregister() void @@ -781,42 +785,41 @@ ftimeout = 5; if (ftimeout < ctimeout) return (time_t)ftimeout; else return (time_t)ctimeout; } /** * Called after forwarding path selection (via peer select) has taken place * and whenever forwarding needs to attempt a new connection (routing failover). * We have a vector of possible localIP->remoteIP paths now ready to start being connected. */ void FwdState::connectStart() { assert(serverDestinations.size() > 0); debugs(17, 3, "fwdConnectStart: " << entry->url()); - if (!request->hier.first_conn_start.tv_sec) // first attempt - request->hier.first_conn_start = current_time; + request->hier.startPeerClock(); if (serverDestinations[0]->getPeer() && request->flags.sslBumped) { debugs(50, 4, "fwdConnectStart: Ssl bumped connections through parent proxy are not allowed"); ErrorState *anErr = new ErrorState(ERR_CANNOT_FORWARD, Http::scServiceUnavailable, request); fail(anErr); self = NULL; // refcounted return; } request->flags.pinned = false; // XXX: what if the ConnStateData set this to flag existing credentials? // XXX: answer: the peer selection *should* catch it and give us only the pinned peer. so we reverse the =0 step below. // XXX: also, logs will now lie if pinning is broken and leads to an error message. if (serverDestinations[0]->peerType == PINNED) { ConnStateData *pinned_connection = request->pinnedConnection(); debugs(17,7, "pinned peer connection: " << pinned_connection); // pinned_connection may become nil after a pconn race if (pinned_connection) serverConn = pinned_connection->borrowPinnedConnection(request, serverDestinations[0]->getPeer()); else serverConn = NULL; === modified file 'src/HierarchyLogEntry.h' --- src/HierarchyLogEntry.h 2014-08-23 10:39:15 +0000 +++ src/HierarchyLogEntry.h 2014-08-27 10:27:24 +0000 @@ -34,43 +34,56 @@ #include "comm/Connection.h" #include "enums.h" #include "hier_code.h" #include "http/StatusCode.h" #include "lookup_t.h" #include "PingData.h" #include "rfc2181.h" 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 total time spent communicating with peers + void startPeerClock(); + /** + * Record total time spent communicating with peers + * \param force whether to overwrite old recorded value if any + */ + void stopPeerClock(const bool force); + + /// Return the total time spent communicating with peers + int64_t totalResponseTime(); + public: hier_code code; char host[SQUIDHOSTNAMELEN]; ping_data ping; char cd_host[SQUIDHOSTNAMELEN]; /* the host of selected by cd peer */ lookup_t cd_lookup; /* cd prediction: none, miss, hit */ int n_choices; /* #peers we selected from (cd only) */ int n_ichoices; /* #peers with known rtt we selected from (cd only) */ struct timeval peer_select_start; 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 int64_t peer_response_time; ///< last peer response delay - timeval first_conn_start; ///< first connection use among all peers - int64_t total_response_time; ///< cumulative for all peers Comm::ConnectionPointer tcpServer; ///< TCP/IP level details of the last server-side connection int64_t bodyBytesRead; ///< number of body bytes received from the next hop or -1 + +private: + timeval first_conn_start; ///< first connection use among all peers + int64_t total_response_time; ///< cumulative for all peers }; #endif /* SQUID_HTTPHIERARCHYLOGENTRY_H */ === modified file 'src/Server.cc' --- src/Server.cc 2014-08-23 10:39:15 +0000 +++ src/Server.cc 2014-08-27 09:01:25 +0000 @@ -179,42 +179,41 @@ entry->release(); entry->startWriting(); // write the updated entry to store return theFinalReply; } // called when no more server communication is expected; may quit void ServerStateData::serverComplete() { debugs(11,5,HERE << "serverComplete " << this); if (!doneWithServer()) { closeServer(); assert(doneWithServer()); } completed = true; HttpRequest *r = originalRequest(); - r->hier.total_response_time = r->hier.first_conn_start.tv_sec ? - tvSubMsec(r->hier.first_conn_start, current_time) : -1; + r->hier.stopPeerClock(true); if (requestBodySource != NULL) stopConsumingFrom(requestBodySource); if (responseBodyBuffer != NULL) return; serverComplete2(); } void ServerStateData::serverComplete2() { debugs(11,5,HERE << "serverComplete2 " << this); #if USE_ADAPTATION if (virginBodyDestination != NULL) stopProducingFor(virginBodyDestination, true); if (!doneWithAdaptation()) === modified file 'src/format/Format.cc' --- src/format/Format.cc 2014-08-26 09:01:27 +0000 +++ src/format/Format.cc 2014-08-27 08:57:00 +0000 @@ -500,48 +500,50 @@ int precision = fmt->widthMax >=0 ? fmt->widthMax :3; snprintf(tmp, sizeof(tmp), "%0*" PRId64 ".%0*d", fmt->zero && (fmt->widthMin - precision - 1 >= 0) ? fmt->widthMin - precision - 1 : 0, static_cast(al->cache.start_time.tv_sec), precision, (int)(al->cache.start_time.tv_usec / fmt->divisor)); out = tmp; } break; case LFT_TIME_TO_HANDLE_REQUEST: outint = al->cache.msec; doint = 1; break; case LFT_PEER_RESPONSE_TIME: if (al->hier.peer_response_time < 0) { out = "-"; } else { outoff = al->hier.peer_response_time; dooff = 1; } break; - case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: - if (al->hier.total_response_time < 0) { + case LFT_TOTAL_SERVER_SIDE_RESPONSE_TIME: { + const int64_t total_response_time = al->hier.totalResponseTime(); + if (total_response_time < 0) { out = "-"; } else { - outoff = al->hier.total_response_time; + outoff = total_response_time; dooff = 1; } - break; + } + break; case LFT_DNS_WAIT_TIME: if (al->request && al->request->dnsWait >= 0) { outint = al->request->dnsWait; doint = 1; } break; case LFT_REQUEST_HEADER: if (al->request) sb = al->request->header.getByName(fmt->data.header.header); out = sb.termedBuf(); quote = 1; break; case LFT_ADAPTED_REQUEST_HEADER: === modified file 'src/log/access_log.cc' --- src/log/access_log.cc 2014-08-23 10:39:15 +0000 +++ src/log/access_log.cc 2014-08-27 10:30:02 +0000 @@ -238,79 +238,110 @@ log->logfile = NULL; } } #if HEADERS_LOG logfileClose(headerslog); headerslog = NULL; #endif } HierarchyLogEntry::HierarchyLogEntry() : code(HIER_NONE), cd_lookup(LOOKUP_NONE), n_choices(0), n_ichoices(0), peer_reply_status(Http::scNone), peer_response_time(-1), - total_response_time(-1), tcpServer(NULL), - bodyBytesRead(-1) + bodyBytesRead(-1), + total_response_time(-1) { memset(host, '\0', SQUIDHOSTNAMELEN); memset(cd_host, '\0', SQUIDHOSTNAMELEN); peer_select_start.tv_sec =0; peer_select_start.tv_usec =0; 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; first_conn_start.tv_sec = 0; first_conn_start.tv_usec = 0; } void HierarchyLogEntry::note(const Comm::ConnectionPointer &server, const char *requestedHost) { tcpServer = server; if (tcpServer == NULL) { code = HIER_NONE; xstrncpy(host, requestedHost, sizeof(host)); } else { code = tcpServer->peerType; if (tcpServer->getPeer()) { // went to peer, log peer host name xstrncpy(host, tcpServer->getPeer()->name, sizeof(host)); } else { xstrncpy(host, requestedHost, sizeof(host)); } } } +void +HierarchyLogEntry::startPeerClock() +{ + if (!first_conn_start.tv_sec) + first_conn_start = current_time; +} + +void +HierarchyLogEntry::stopPeerClock(const bool force) { + debugs(46, 5, "First connection started: " << first_conn_start.tv_sec << "." << + std::setfill('0') << std::setw(6) << first_conn_start.tv_usec << + ", current total response time value: " << total_response_time << + (force ? ", force fixing" : "")); + if (!force && total_response_time >= 0) + return; + + total_response_time = first_conn_start.tv_sec ? tvSubMsec(first_conn_start, current_time) : -1; +} + +int64_t +HierarchyLogEntry::totalResponseTime() +{ + // This should not really happen, but there may be rare code + // paths that lead to FwdState discarded (or transaction logged) + // without (or before) a stopPeerClock() call. + if (first_conn_start.tv_sec && total_response_time < 0) + stopPeerClock(false); + + return total_response_time; +} + static void accessLogRegisterWithCacheManager(void) { #if USE_FORW_VIA_DB fvdbRegisterWithCacheManager(); #endif } void accessLogInit(void) { CustomLog *log; accessLogRegisterWithCacheManager(); #if USE_ADAPTATION Log::TheConfig.hasAdaptToken = false; #endif #if ICAP_CLIENT Log::TheConfig.hasIcapToken = false; === modified file 'src/tunnel.cc' --- src/tunnel.cc 2014-08-26 09:01:27 +0000 +++ src/tunnel.cc 2014-08-27 10:31:55 +0000 @@ -37,40 +37,41 @@ #include "CachePeer.h" #include "client_side.h" #include "client_side_request.h" #include "comm.h" #include "comm/Connection.h" #include "comm/ConnOpener.h" #include "comm/Read.h" #include "comm/Write.h" #include "errorpage.h" #include "fde.h" #include "globals.h" #include "FwdState.h" #include "http.h" #include "HttpRequest.h" #include "HttpStateFlags.h" #include "ip/QosConfig.h" #include "LogTags.h" #include "MemBuf.h" #include "PeerSelectState.h" #include "SquidConfig.h" +#include "SquidTime.h" #include "StatCounters.h" #if USE_OPENSSL #include "ssl/bio.h" #include "ssl/PeerConnector.h" #include "ssl/ServerBump.h" #endif #include "tools.h" #if USE_DELAY_POOLS #include "DelayId.h" #endif #include #include /** * TunnelStateData is the state engine performing the tasks for * setup of a TCP tunnel from an existing open client FD to a server * then shuffling binary data between the resulting FD pair. */ /* @@ -221,40 +222,43 @@ }; static const char *const conn_established = "HTTP/1.1 200 Connection established\r\n\r\n"; static CNCB tunnelConnectDone; static ERCB tunnelErrorComplete; static CLCB tunnelServerClosed; static CLCB tunnelClientClosed; static CTCB tunnelTimeout; static PSC tunnelPeerSelectComplete; static void tunnelConnected(const Comm::ConnectionPointer &server, void *); static void tunnelRelayConnectRequest(const Comm::ConnectionPointer &server, void *); static void tunnelServerClosed(const CommCloseCbParams ¶ms) { TunnelStateData *tunnelState = (TunnelStateData *)params.data; debugs(26, 3, HERE << tunnelState->server.conn); tunnelState->server.conn = NULL; + if (tunnelState->request != NULL) + tunnelState->request->hier.stopPeerClock(false); + if (tunnelState->noConnections()) { delete tunnelState; return; } if (!tunnelState->server.len) { tunnelState->client.conn->close(); return; } } static void tunnelClientClosed(const CommCloseCbParams ¶ms) { TunnelStateData *tunnelState = (TunnelStateData *)params.data; debugs(26, 3, HERE << tunnelState->client.conn); tunnelState->client.conn = NULL; if (tunnelState->noConnections()) { delete tunnelState; @@ -845,40 +849,42 @@ */ tunnelState->serverDestinations.erase(tunnelState->serverDestinations.begin()); if (status != Comm::TIMEOUT && tunnelState->serverDestinations.size() > 0) { /* Try another IP of this destination host */ GetMarkingsToServer(tunnelState->request.getRaw(), *tunnelState->serverDestinations[0]); debugs(26, 4, HERE << "retry with : " << tunnelState->serverDestinations[0]); AsyncCall::Pointer call = commCbCall(26,3, "tunnelConnectDone", CommConnectCbPtrFun(tunnelConnectDone, tunnelState)); Comm::ConnOpener *cs = new Comm::ConnOpener(tunnelState->serverDestinations[0], call, Config.Timeout.connect); cs->setHost(tunnelState->url); AsyncJob::Start(cs); } else { debugs(26, 4, HERE << "terminate with error."); ErrorState *err = new ErrorState(ERR_CONNECT_FAIL, Http::scServiceUnavailable, tunnelState->request.getRaw()); *tunnelState->status_ptr = Http::scServiceUnavailable; err->xerrno = xerrno; // on timeout is this still: err->xerrno = ETIMEDOUT; err->port = conn->remote.port(); err->callback = tunnelErrorComplete; err->callback_data = tunnelState; errorSend(tunnelState->client.conn, err); + if (tunnelState->request != NULL) + tunnelState->request->hier.stopPeerClock(false); } return; } #if USE_DELAY_POOLS /* no point using the delayIsNoDelay stuff since tunnel is nice and simple */ if (conn->getPeer() && conn->getPeer()->options.no_delay) tunnelState->server.setDelayId(DelayId()); #endif tunnelState->request->hier.note(conn, tunnelState->getHost()); tunnelState->server.conn = conn; tunnelState->request->peer_host = conn->getPeer() ? conn->getPeer()->host : NULL; comm_add_close_handler(conn->fd, tunnelServerClosed, tunnelState); debugs(26, 4, HERE << "determine post-connect handling pathway."); if (conn->getPeer()) { tunnelState->request->peer_login = conn->getPeer()->login; tunnelState->request->flags.proxying = !(conn->getPeer()->options.originserver); @@ -1062,40 +1068,43 @@ static void tunnelPeerSelectComplete(Comm::ConnectionList *peer_paths, ErrorState *err, void *data) { TunnelStateData *tunnelState = (TunnelStateData *)data; if (peer_paths == NULL || peer_paths->size() < 1) { debugs(26, 3, HERE << "No paths found. Aborting CONNECT"); if (!err) { err = new ErrorState(ERR_CANNOT_FORWARD, Http::scServiceUnavailable, tunnelState->request.getRaw()); } *tunnelState->status_ptr = err->httpStatus; err->callback = tunnelErrorComplete; err->callback_data = tunnelState; errorSend(tunnelState->client.conn, err); return; } delete err; GetMarkingsToServer(tunnelState->request.getRaw(), *tunnelState->serverDestinations[0]); + if (tunnelState->request != NULL) + tunnelState->request->hier.startPeerClock(); + debugs(26, 3, HERE << "paths=" << peer_paths->size() << ", p[0]={" << (*peer_paths)[0] << "}, serverDest[0]={" << tunnelState->serverDestinations[0] << "}"); AsyncCall::Pointer call = commCbCall(26,3, "tunnelConnectDone", CommConnectCbPtrFun(tunnelConnectDone, tunnelState)); Comm::ConnOpener *cs = new Comm::ConnOpener(tunnelState->serverDestinations[0], call, Config.Timeout.connect); cs->setHost(tunnelState->url); AsyncJob::Start(cs); } CBDATA_CLASS_INIT(TunnelStateData); bool TunnelStateData::noConnections() const { return !Comm::IsConnOpen(server.conn) && !Comm::IsConnOpen(client.conn); } #if USE_DELAY_POOLS void TunnelStateData::Connection::setDelayId(DelayId const &newDelay)