From 324fe06a069474556859d93edb6d57baa3a91c73 Mon Sep 17 00:00:00 2001 From: Aleric Inglewood Date: Wed, 14 Nov 2012 02:12:27 +0100 Subject: [PATCH] Improved printed info when curl times out. --- indra/llmessage/aicurl.cpp | 32 ++++++----- indra/llmessage/aicurlprivate.h | 10 ++-- indra/llmessage/aicurlthread.cpp | 97 +++++++++++++++++++++++++++++++- 3 files changed, 119 insertions(+), 20 deletions(-) diff --git a/indra/llmessage/aicurl.cpp b/indra/llmessage/aicurl.cpp index 3aacd0ecd..2353f24bd 100644 --- a/indra/llmessage/aicurl.cpp +++ b/indra/llmessage/aicurl.cpp @@ -1222,19 +1222,6 @@ void CurlEasyRequest::removed_from_multi_handle(AICurlEasyRequest_wat& curl_easy mHandleEventsTarget->removed_from_multi_handle(curl_easy_request_w); } -void CurlEasyRequest::print_diagnostics(CURLcode code) -{ - if (code == CURLE_OPERATION_TIMEDOUT) - { - // mTimeout SHOULD always be set, but I see no reason not to test it, as - // this is far from the code that guaranteeds that it is set. - if (mTimeout) - { - mTimeout->print_diagnostics(this); - } - } -} - PerHostRequestQueuePtr CurlEasyRequest::getPerHostPtr(void) { if (!mPerHostPtr) @@ -1314,6 +1301,25 @@ void BufferedCurlEasyRequest::resetState(void) mInput.reset(); } +void BufferedCurlEasyRequest::print_diagnostics(CURLcode code) +{ + char* eff_url; + getinfo(CURLINFO_EFFECTIVE_URL, &eff_url); + if (code == CURLE_OPERATION_TIMEDOUT) + { + // mTimeout SHOULD always be set, but I see no reason not to test it, as + // this is far from the code that guaranteeds that it is set. + if (mTimeout) + { + mTimeout->print_diagnostics(this, eff_url); + } + } + else + { + llwarns << "Curl returned error code " << code << " (" << curl_easy_strerror(code) << ") for HTTP request to \"" << eff_url << "\"." << llendl; + } +} + ThreadSafeBufferedCurlEasyRequest* BufferedCurlEasyRequest::get_lockobj(void) { return static_cast(AIThreadSafeSimple::wrapper_cast(this)); diff --git a/indra/llmessage/aicurlprivate.h b/indra/llmessage/aicurlprivate.h index 3ecdae2b0..a1d449998 100644 --- a/indra/llmessage/aicurlprivate.h +++ b/indra/llmessage/aicurlprivate.h @@ -97,7 +97,7 @@ class HTTPTimeout : public LLRefCount { bool has_stalled(void) const { return mStalled < sClockCount; } // Called from BufferedCurlEasyRequest::processOutput if a timeout occurred. - void print_diagnostics(CurlEasyRequest const* curl_easy_request); + void print_diagnostics(CurlEasyRequest const* curl_easy_request, char const* eff_url); #if defined(CWDEBUG) || defined(DEBUG_CURLIO) void* get_lockobj(void) const { return mLockObj; } @@ -344,9 +344,6 @@ class CurlEasyRequest : public CurlEasyHandle { finished(curl_easy_request_w); } - // Called by in case of an error. - void print_diagnostics(CURLcode code); - // Called by MultiHandle::check_msg_queue() to fill info with the transfer info. void getTransferInfo(AITransferInfo* info); @@ -356,7 +353,7 @@ class CurlEasyRequest : public CurlEasyHandle { // For debugging purposes. void print_curl_timings(void) const; - private: + protected: curl_slist* mHeaders; AICurlEasyHandleEvents* mHandleEventsTarget; CURLcode mResult; //AIFIXME: this does not belong in the request object, but belongs in the response object. @@ -478,6 +475,9 @@ class BufferedCurlEasyRequest : public CurlEasyRequest { // Called from curlHeaderCallback. void setStatusAndReason(U32 status, std::string const& reason); + // Called from processOutput by in case of an error. + void print_diagnostics(CURLcode code); + public: // Return pointer to the ThreadSafe (wrapped) version of this object. ThreadSafeBufferedCurlEasyRequest* get_lockobj(void); diff --git a/indra/llmessage/aicurlthread.cpp b/indra/llmessage/aicurlthread.cpp index 8a4c8482d..7009d5bf3 100644 --- a/indra/llmessage/aicurlthread.cpp +++ b/indra/llmessage/aicurlthread.cpp @@ -1971,9 +1971,102 @@ void HTTPTimeout::done(AICurlEasyRequest_wat const& curlEasyRequest_w, CURLcode DoutCurl("done: mStalled set to -1"); } -void HTTPTimeout::print_diagnostics(CurlEasyRequest const* curl_easy_request) +void HTTPTimeout::print_diagnostics(CurlEasyRequest const* curl_easy_request, char const* eff_url) { - llwarns << "Request to " << curl_easy_request->getLowercaseHostname() << " timed out for " << curl_easy_request->getTimeoutPolicy()->name() << llendl; + llwarns << "Request to \"" << curl_easy_request->getLowercaseHostname() << "\" timed out for " << curl_easy_request->getTimeoutPolicy()->name() << llendl; + llinfos << "Effective URL: \"" << eff_url << "\"." << llendl; + double namelookup_time, connect_time, appconnect_time, pretransfer_time, starttransfer_time; + curl_easy_request->getinfo(CURLINFO_NAMELOOKUP_TIME, &namelookup_time); + curl_easy_request->getinfo(CURLINFO_CONNECT_TIME, &connect_time); + curl_easy_request->getinfo(CURLINFO_APPCONNECT_TIME, &appconnect_time); + curl_easy_request->getinfo(CURLINFO_PRETRANSFER_TIME, &pretransfer_time); + curl_easy_request->getinfo(CURLINFO_STARTTRANSFER_TIME, &starttransfer_time); + if (namelookup_time == 0) + { + llwarns << "Huh? Curl returned CURLE_OPERATION_TIMEDOUT, but DNS lookup did not occur according to timings. Expected CURLE_COULDNT_RESOLVE_PROXY or CURLE_COULDNT_RESOLVE_HOST!" << llendl; + llassert(connect_time == 0); + llassert(appconnect_time == 0); + llassert(pretransfer_time == 0); + llassert(starttransfer_time == 0); + // Fatal error for diagnostics. + return; + } + // If namelookup_time is less than 500 microseconds, then it's very likely just a DNS cache lookup. + else if (namelookup_time < 500e-6) + { + llinfos << "Hostname was still in DNS cache." << llendl; + } + else + { + llwarns << "DNS lookup of " << curl_easy_request->getLowercaseHostname() << " took " << namelookup_time << " seconds." << llendl; + } + if (connect_time == 0) + { + llwarns << "Huh? Curl returned CURLE_OPERATION_TIMEDOUT, but connection did not occur according to timings. Expected CURLE_COULDNT_CONNECT!" << llendl; + llassert(appconnect_time == 0); + llassert(pretransfer_time == 0); + llassert(starttransfer_time == 0); + // Fatal error for diagnostics. + return; + } + // If connect_time is almost equal to namelookup_time, then it was just set because it was already connected. + if (connect_time - namelookup_time <= 1e-6) + { + llinfos << "The socket was already connected (to remote or proxy)." << llendl; + if (appconnect_time == 0) + { + llwarns << "The SSL/TLS handshake never occurred according to the timings!" << llendl; + return; + } + // If appconnect_time is almost equal to connect_time, then it was just set because this is a connection re-use. + if (appconnect_time - connect_time <= 1e-6) + { + llinfos << "Connection with HTTP server was already established; this was a re-used connection." << llendl; + } + else + { + llinfos << "SSL/TLS handshake with HTTP server took " << (appconnect_time - connect_time) << " seconds." << llendl; + } + } + else + { + llinfos << "Socket connected to remote host (or proxy) in " << (connect_time - namelookup_time) << " seconds." << llendl; + if (appconnect_time == 0) + { + llwarns << "The SSL/TLS handshake never occurred according to the timings!" << llendl; + return; + } + llinfos << "SSL/TLS handshake with HTTP server took " << (appconnect_time - connect_time) << " seconds." << llendl; + } + if (pretransfer_time == 0) + { + llwarns << "The transfer never happened because there was too much in the pipeline (apparently)." << llendl; + return; + } + else if (pretransfer_time - appconnect_time >= 1e-6) + { + llinfos << "Apparently there was a delay, due to waits in line for the pipeline, of " << (pretransfer_time - appconnect_time) << " seconds before the transfer began." << llendl; + } + if (starttransfer_time == 0) + { + llwarns << "No data was ever received from the server according to the timings." << llendl; + } + else + { + llinfos << "The time it took to send the request to the server plus the time it took before the server started to reply was " << (starttransfer_time - pretransfer_time) << " seconds." << llendl; + } + if (mNothingReceivedYet) + { + llinfos << "No data at all was actually received from the server." << llendl; + } + if (mUploadFinished) + { + llinfos << "The request upload finished successfully." << llendl; + } + if (mLastSecond > 0 && mLowSpeedOn) + { + llinfos << "The " << (mNothingReceivedYet ? "upload" : "download") << " did last " << mLastSecond << " second" << ((mLastSecond == 1) ? "" : "s") << ", before it timed out." << llendl; + } } } // namespace curlthread