From ec436b0e3b7c4fbaa5e054e6bd5501c339c95834 Mon Sep 17 00:00:00 2001 From: Aleric Inglewood Date: Sun, 24 Nov 2013 17:55:46 +0100 Subject: [PATCH] Improve upload_finished detection for HTTP requests. We detect the end of an upload when libcurl informs us that it is no longer interested in knowing if a socket is writable (which it tells us cause we're doing the call to select(), by means of a call to MultiHandle::socket_callback). However, this does not *always* work. The debug output might look like this: [...initialization and first part of a TLS handshake...] 0x7f759f0ad700 CURL : select(55, {17, 39, 46, 47, 48, 49, 50, 51, 52, 54}, NULL, NULL, timeout = 1 ms) = 7 0x7f759f0ad700 CURLTR : curl_multi_socket_action((CURLM*)0x7f758c002920, 46, CURL_CSELECT_IN, <--- Calling curl_multi_socket_action (socket 46 is readable) 0x7f759f0ad700 CURLIO 0x13fce7b0 * SSLv3, TLS change cipher, Client hello (1): 0x7f759f0ad700 CURLIO 0x13fce7b0 S> 1 bytes 0x7f759f0ad700 CURLIO 0x13fce7b0 * SSLv3, TLS handshake, Finished (20): 0x7f759f0ad700 CURLIO 0x13fce7b0 S> 16 bytes 0x7f759f0ad700 CURLIO 0x13fce7b0 * SSL connection using AES256-SHA 0x7f759f0ad700 CURLIO 0x13fce7b0 * Server certificate: 0x7f759f0ad700 CURLIO 0x13fce7b0 * subject: C=US; ST=California; L=San Francisco; O=Linden Lab, Inc.; CN=*.agni.lindenlab.com; emailAddress=root@lindenlab.com 0x7f759f0ad700 CURLIO 0x13fce7b0 * start date: 2012-09-20 22:55:47 GMT 0x7f759f0ad700 CURLIO 0x13fce7b0 * expire date: 2015-09-20 22:55:47 GMT 0x7f759f0ad700 CURLIO 0x13fce7b0 * issuer: C=US; ST=California; L=San Francisco; O=Linden Lab, Inc.; OU=Linden Lab Certificate Authority; CN=Linden Lab Certificate Authority; emailAddress=ca@lindenlab.com 0x7f759f0ad700 CURLIO 0x13fce7b0 * SSL certificate verify ok. 0x7f759f0ad700 CURLIO 0x13fce7b0 * STATE: PROTOCONNECT => DO handle 0x7f758d62d810; (connection #2) 0x7f759f0ad700 CURLIO 0x13fce7b0 H< POST /cap/d67d4540-4504-b3d1-1d26-112010e88bd8 HTTP/1.1\r\nHost: sim10480.agni.lindenlab.com:12043\r\nAccept: */*\r\nAccept-Encoding: deflate, gzip\r\nContent-Type: application/llsd+xml\r\nX-SecondLife-UDP-Listen-Port: 32837\r\nConnection: keep-alive\r\nKeep-alive: 300\r\nContent-Length: 333\r\n\r\n 0x7f759f0ad700 CURLIO 0x13fce7b0 * STATE: DO => DO_DONE handle 0x7f758d62d810; (connection #2) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 0) <=== THIS IS NEW: total to upload: 333 bytes, total uploaded: 0 bytes. 0x7f759f0ad700 CURLIO 0x13fce7b0 * STATE: DO_DONE => WAITPERFORM handle 0x7f758d62d810; (connection #2) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 0) 0x7f759f0ad700 CURLIO 0x13fce7b0 * STATE: WAITPERFORM => PERFORM handle 0x7f758d62d810; (connection #2) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 0) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 0) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 0) 0x7f759f0ad700 CURLTR : curl_easy_getinfo((CURL*)0x13fcf320, CURLINFO_PRIVATE, 0x7f759f0abdb0) = CURLE_OK 0x7f759f0ad700 CURL : Entering MultiHandle::socket_callback((CURL*)0x13fcf320, 46, CURL_POLL_INOUT, 0x7f758c001508, 0x7f758c2ce4e0) [CURLINFO_PRIVATE = 0x13fce7b0] 0x7f759f0ad700 CURL : CurlSocketInfo::set_action(CURL_POLL_IN --> CURL_POLL_INOUT) [0x13fce7b0] <=== WATING FOR WRITING BUT ALREADY WAITING FOR INPUT! 0x7f759f0ad700 CURL 0x13fce7b0 reset_lowspeed: mLowSpeedClock = 138530973390; mStalled = -1 0x7f759f0ad700 CURLTR : {11}) = 0 <--- Returning from curl_multi_socket_action 0x7f759f0ad700 CURL : select(58, {17, 39, 46, 47, 48, 49, 50, 51, 52, 54}, {36, 46, 57}, NULL, timeout = 756 ms) = 5 0x7f759f0ad700 CURLTR : curl_multi_socket_action((CURLM*)0x7f758c002920, 46, CURL_CSELECT_OUT, <=== SOCKET AVAILABLE FOR WRITING 0x7f759f0ad700 CURLIO 0x13fce7b0 * additional stuff not fine transfer.c:1037: 0 0 0x7f759f0ad700 CURLIO 0x13fce7b0 D< 333 bytes: "foldersfetch_folders...etc" <=== WRITING *ALL* DATA 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 333) <=== THIS IS NEW, DETECT END OF UPLOAD 0x7f759f0ad700 CURL 0x13fce7b0 upload_finished: mStalled set to Time_10ms (138530973390) + 6000 (60 seconds) 0x7f759f0ad700 CURL : Entering BufferedCurlEasyRequest::curlProgressCallback(0x13fce7b0, 0, 0, 333, 333) 0x7f759f0ad700 CURL : select(58, {17, 39, 46, 47, 50, 52, 54}, {36, 46, 57}, NULL, timeout = 0 ms) = 8 0x7f759f0ad700 CURLTR : curl_multi_socket_action((CURLM*)0x7f758c002920, 46, CURL_CSELECT_IN|CURL_CSELECT_OUT, 0x7f759f0ad700 CURLIO 0x13fce7b0 * HTTP 1.1 or later with persistent connection, pipelining supported 0x7f759f0ad700 CURLIO 0x13fce7b0 H> HTTP/1.1 200 OK\r\n ...and the server already replies without a call to MultiHandle::socket_callback between writing and reading, because the socket was still (already) waiting for input anyway (since it was waiting for the SSL/TLS handshake before in this case, but it also happens when the data has to be written in more than one writes). Using the progress callback however, we are able to detect the end of the upload right after writing, anyway. --- indra/llmessage/aicurl.cpp | 33 +++++++++++++++++++++++++++++-- indra/llmessage/aicurlprivate.h | 7 ++++++- indra/llmessage/aicurlthread.cpp | 18 +++++++++++++++++ indra/llmessage/aihttptimeout.cpp | 9 +++++---- 4 files changed, 60 insertions(+), 7 deletions(-) diff --git a/indra/llmessage/aicurl.cpp b/indra/llmessage/aicurl.cpp index 6b2101a4d..99683e0c5 100644 --- a/indra/llmessage/aicurl.cpp +++ b/indra/llmessage/aicurl.cpp @@ -765,8 +765,8 @@ DEFINE_FUNCTION_SETOPT4(curl_write_callback, CURLOPT_HEADERFUNCTION, CURLOPT_WRI //DEFINE_FUNCTION_SETOPT1(curl_read_callback, CURLOPT_READFUNCTION) DEFINE_FUNCTION_SETOPT1(curl_ssl_ctx_callback, CURLOPT_SSL_CTX_FUNCTION) DEFINE_FUNCTION_SETOPT3(curl_conv_callback, CURLOPT_CONV_FROM_NETWORK_FUNCTION, CURLOPT_CONV_TO_NETWORK_FUNCTION, CURLOPT_CONV_FROM_UTF8_FUNCTION) -#if 0 // Not used by the viewer. DEFINE_FUNCTION_SETOPT1(curl_progress_callback, CURLOPT_PROGRESSFUNCTION) +#if 0 // Not used by the viewer. DEFINE_FUNCTION_SETOPT1(curl_seek_callback, CURLOPT_SEEKFUNCTION) DEFINE_FUNCTION_SETOPT1(curl_ioctl_callback, CURLOPT_IOCTLFUNCTION) DEFINE_FUNCTION_SETOPT1(curl_sockopt_callback, CURLOPT_SOCKOPTFUNCTION) @@ -901,6 +901,23 @@ void CurlEasyRequest::setSSLCtxCallback(curl_ssl_ctx_callback callback, void* us setopt(CURLOPT_SSL_CTX_DATA, this); } +//static +int CurlEasyRequest::progressCallback(void* userdata, double dltotal, double dlnow, double ultotal, double ulnow) +{ + CurlEasyRequest* self = static_cast(userdata); + ThreadSafeBufferedCurlEasyRequest* lockobj = self->get_lockobj(); + AICurlEasyRequest_wat lock_self(*lockobj); + return self->mProgressCallback(self->mProgressCallbackUserData, dltotal, dlnow, ultotal, ulnow); +} + +void CurlEasyRequest::setProgressCallback(curl_progress_callback callback, void* userdata) +{ + mProgressCallback = callback; + mProgressCallbackUserData = userdata; + setopt(CURLOPT_PROGRESSFUNCTION, callback ? &CurlEasyRequest::progressCallback : NULL); + setopt(CURLOPT_PROGRESSDATA, userdata ? this : NULL); +} + #define llmaybewarns lllog(LLApp::isExiting() ? LLError::LEVEL_INFO : LLError::LEVEL_WARN, NULL, NULL, false, true) static size_t noHeaderCallback(char* ptr, size_t size, size_t nmemb, void* userdata) @@ -927,12 +944,19 @@ static CURLcode noSSLCtxCallback(CURL* curl, void* sslctx, void* parm) return CURLE_ABORTED_BY_CALLBACK; } +static int noProgressCallback(void* userdata, double, double, double, double) +{ + llmaybewarns << "Calling noProgressCallback(); curl session aborted." << llendl; + return -1; // Cause a CURLE_ABORTED_BY_CALLBACK +} + void CurlEasyRequest::revokeCallbacks(void) { if (mHeaderCallback == &noHeaderCallback && mWriteCallback == &noWriteCallback && mReadCallback == &noReadCallback && - mSSLCtxCallback == &noSSLCtxCallback) + mSSLCtxCallback == &noSSLCtxCallback && + mProgressCallback == &noProgressCallback) { // Already revoked. return; @@ -941,6 +965,7 @@ void CurlEasyRequest::revokeCallbacks(void) mWriteCallback = &noWriteCallback; mReadCallback = &noReadCallback; mSSLCtxCallback = &noSSLCtxCallback; + mProgressCallback = &noProgressCallback; if (active() && !no_warning()) { llwarns << "Revoking callbacks on a still active CurlEasyRequest object!" << llendl; @@ -949,6 +974,7 @@ void CurlEasyRequest::revokeCallbacks(void) curl_easy_setopt(getEasyHandle(), CURLOPT_WRITEHEADER, &noWriteCallback); curl_easy_setopt(getEasyHandle(), CURLOPT_READFUNCTION, &noReadCallback); curl_easy_setopt(getEasyHandle(), CURLOPT_SSL_CTX_FUNCTION, &noSSLCtxCallback); + curl_easy_setopt(getEasyHandle(), CURLOPT_PROGRESSFUNCTION, &noProgressCallback); } CurlEasyRequest::~CurlEasyRequest() @@ -1077,6 +1103,8 @@ void CurlEasyRequest::applyDefaultOptions(void) setopt(CURLOPT_IPRESOLVE, CURL_IPRESOLVE_V4); // Disable SSL/TLS session caching; some servers (aka id.secondlife.com) refuse connections when session ids are enabled. setopt(CURLOPT_SSL_SESSIONID_CACHE, 0); + // Call the progress callback funtion. + setopt(CURLOPT_NOPROGRESS, 0); // Set the CURL options for either SOCKS or HTTP proxy. applyProxySettings(); // Cause libcurl to print all it's I/O traffic on the debug channel. @@ -1410,6 +1438,7 @@ void BufferedCurlEasyRequest::prepRequest(AICurlEasyRequest_wat& curl_easy_reque curl_easy_request_w->setWriteCallback(&curlWriteCallback, lockobj); curl_easy_request_w->setReadCallback(&curlReadCallback, lockobj); curl_easy_request_w->setHeaderCallback(&curlHeaderCallback, lockobj); + curl_easy_request_w->setProgressCallback(&curlProgressCallback, lockobj); bool allow_cookies = headers.hasHeader("Cookie"); // Allow up to sixteen redirects. diff --git a/indra/llmessage/aicurlprivate.h b/indra/llmessage/aicurlprivate.h index f2230d179..be3d90e7d 100644 --- a/indra/llmessage/aicurlprivate.h +++ b/indra/llmessage/aicurlprivate.h @@ -83,8 +83,8 @@ class CurlEasyHandle : public boost::noncopyable, protected AICurlEasyHandleEven //DECLARE_SETOPT(curl_read_callback); Same type as curl_write_callback DECLARE_SETOPT(curl_ssl_ctx_callback); DECLARE_SETOPT(curl_conv_callback); -#if 0 // Not used by the viewer. DECLARE_SETOPT(curl_progress_callback); +#if 0 // Not used by the viewer. DECLARE_SETOPT(curl_seek_callback); DECLARE_SETOPT(curl_ioctl_callback); DECLARE_SETOPT(curl_sockopt_callback); @@ -235,6 +235,7 @@ class CurlEasyRequest : public CurlEasyHandle { static size_t writeCallback(char* ptr, size_t size, size_t nmemb, void* userdata); static size_t readCallback(char* ptr, size_t size, size_t nmemb, void* userdata); static CURLcode SSLCtxCallback(CURL* curl, void* sslctx, void* userdata); + static int progressCallback(void* userdata, double, double, double, double); curl_write_callback mHeaderCallback; void* mHeaderCallbackUserData; @@ -244,12 +245,15 @@ class CurlEasyRequest : public CurlEasyHandle { void* mReadCallbackUserData; curl_ssl_ctx_callback mSSLCtxCallback; void* mSSLCtxCallbackUserData; + curl_progress_callback mProgressCallback; + void* mProgressCallbackUserData; public: void setHeaderCallback(curl_write_callback callback, void* userdata); void setWriteCallback(curl_write_callback callback, void* userdata); void setReadCallback(curl_read_callback callback, void* userdata); void setSSLCtxCallback(curl_ssl_ctx_callback callback, void* userdata); + void setProgressCallback(curl_progress_callback callback, void* userdata); // Call this if the set callbacks are about to be invalidated. void revokeCallbacks(void); @@ -441,6 +445,7 @@ class BufferedCurlEasyRequest : public CurlEasyRequest { static size_t curlWriteCallback(char* data, size_t size, size_t nmemb, void* user_data); static size_t curlReadCallback(char* data, size_t size, size_t nmemb, void* user_data); static size_t curlHeaderCallback(char* data, size_t size, size_t nmemb, void* user_data); + static int curlProgressCallback(void* user_data, double dltotal, double dlnow, double ultotal, double ulnow); // Called from curlHeaderCallback. void setStatusAndReason(U32 status, std::string const& reason); diff --git a/indra/llmessage/aicurlthread.cpp b/indra/llmessage/aicurlthread.cpp index 0375f8bc3..986b1d36b 100644 --- a/indra/llmessage/aicurlthread.cpp +++ b/indra/llmessage/aicurlthread.cpp @@ -2354,6 +2354,24 @@ size_t BufferedCurlEasyRequest::curlHeaderCallback(char* data, size_t size, size return header_len; } +//static +int BufferedCurlEasyRequest::curlProgressCallback(void* user_data, double dltotal, double dlnow, double ultotal, double ulnow) +{ + if (ultotal > 0) // Zero just means it isn't known yet. + { + ThreadSafeBufferedCurlEasyRequest* lockobj = static_cast(user_data); + DoutEntering(dc::curl, "BufferedCurlEasyRequest::curlProgressCallback(" << (void*)lockobj << ", " << dltotal << ", " << dlnow << ", " << ultotal << ", " << ulnow << ")"); + + if (ulnow == ultotal) // Everything uploaded? + { + AICurlEasyRequest_wat self_w(*lockobj); + self_w->httptimeout()->upload_finished(); + } + } + + return 0; +} + #if defined(CWDEBUG) || defined(DEBUG_CURLIO) int debug_callback(CURL* handle, curl_infotype infotype, char* buf, size_t size, void* user_ptr) { diff --git a/indra/llmessage/aihttptimeout.cpp b/indra/llmessage/aihttptimeout.cpp index bfb0f767b..f79e2a450 100644 --- a/indra/llmessage/aihttptimeout.cpp +++ b/indra/llmessage/aihttptimeout.cpp @@ -157,10 +157,11 @@ void HTTPTimeout::upload_starting(void) // | void HTTPTimeout::upload_finished(void) { - // Disable this assert when there isn't enough debug output to do anything with it. -#if defined(CWDEBUG) || defined(DEBUG_CURLIO) - llassert(!mUploadFinished); // If we get here twice, then the 'upload finished' detection failed. -#endif + // This function can be called more than once. Ignore the second call. + if (mUploadFinished) + { + return; + } mUploadFinished = true; // Only accept a call to upload_starting() if being_redirected() is called after this point. mBeingRedirected = false;