From e7f03a77bfe4173cd33b5242eb27aa9469c4702c Mon Sep 17 00:00:00 2001 From: Rider Linden Date: Mon, 18 Apr 2016 14:31:14 -0700 Subject: MAINT-6336: Better retry and timeout logic when logging in to the vivox server and connecting to a session. --- indra/newview/llvoicevivox.cpp | 123 ++++++++++++++++++++++++++--------------- 1 file changed, 78 insertions(+), 45 deletions(-) diff --git a/indra/newview/llvoicevivox.cpp b/indra/newview/llvoicevivox.cpp index c9661dfb11..e015d4fa5e 100755 --- a/indra/newview/llvoicevivox.cpp +++ b/indra/newview/llvoicevivox.cpp @@ -80,39 +80,49 @@ extern LLMenuBarGL* gMenuBarView; extern void handle_voice_morphing_subscribe(); -const F32 VOLUME_SCALE_VIVOX = 0.01f; +namespace { + const F32 VOLUME_SCALE_VIVOX = 0.01f; -const F32 SPEAKING_TIMEOUT = 1.f; + const F32 SPEAKING_TIMEOUT = 1.f; -static const std::string VOICE_SERVER_TYPE = "Vivox"; + static const std::string VOICE_SERVER_TYPE = "Vivox"; -// Don't retry connecting to the daemon more frequently than this: -const F32 CONNECT_THROTTLE_SECONDS = 1.0f; + // Don't retry connecting to the daemon more frequently than this: + const F32 CONNECT_THROTTLE_SECONDS = 1.0f; -// Don't send positional updates more frequently than this: -const F32 UPDATE_THROTTLE_SECONDS = 0.5f; + // Don't send positional updates more frequently than this: + const F32 UPDATE_THROTTLE_SECONDS = 0.5f; -const F32 LOGIN_RETRY_SECONDS = 10.0f; -const int MAX_LOGIN_RETRIES = 12; + const F32 LOGIN_ATTEMPT_TIMEOUT = 5.0f; + const int LOGIN_RETRY_MAX = 5; + const F32 LOGIN_RETRY_TIMEOUT = 4.0f; -// Cosine of a "trivially" small angle -const F32 MINUSCULE_ANGLE_COS = 0.999f; + const int PROVISION_RETRY_MAX = 5; + const F32 PROVISION_RETRY_TIMEOUT = 2.0; -// Defines the maximum number of times(in a row) "stateJoiningSession" case for spatial channel is reached in stateMachine() -// which is treated as normal. The is the number of frames to wait for a channel join before giving up. This was changed -// from the original count of 50 for two reason. Modern PCs have higher frame rates and sometimes the SLVoice process -// backs up processing join requests. There is a log statement that records when channel joins take longer than 100 frames. -const int MAX_NORMAL_JOINING_SPATIAL_NUM = 1500; + // Cosine of a "trivially" small angle + const F32 MINUSCULE_ANGLE_COS = 0.999f; -// How often to check for expired voice fonts in seconds -const F32 VOICE_FONT_EXPIRY_INTERVAL = 10.f; -// Time of day at which Vivox expires voice font subscriptions. -// Used to replace the time portion of received expiry timestamps. -static const std::string VOICE_FONT_EXPIRY_TIME = "T05:00:00Z"; + const F32 SESSION_JOIN_TIMEOUT = 10.0f; -// Maximum length of capture buffer recordings in seconds. -const F32 CAPTURE_BUFFER_MAX_TIME = 10.f; + // Defines the maximum number of times(in a row) "stateJoiningSession" case for spatial channel is reached in stateMachine() + // which is treated as normal. The is the number of frames to wait for a channel join before giving up. This was changed + // from the original count of 50 for two reason. Modern PCs have higher frame rates and sometimes the SLVoice process + // backs up processing join requests. There is a log statement that records when channel joins take longer than 100 frames. + const int MAX_NORMAL_JOINING_SPATIAL_NUM = 1500; + // How often to check for expired voice fonts in seconds + const F32 VOICE_FONT_EXPIRY_INTERVAL = 10.f; + // Time of day at which Vivox expires voice font subscriptions. + // Used to replace the time portion of received expiry timestamps. + static const std::string VOICE_FONT_EXPIRY_TIME = "T05:00:00Z"; + + // Maximum length of capture buffer recordings in seconds. + const F32 CAPTURE_BUFFER_MAX_TIME = 10.f; + + const int ERROR_VIVOX_OBJECT_NOT_FOUND = 1001; + const int ERROR_VIVOX_NOT_LOGGED_IN = 1007; +} static int scale_mic_volume(float volume) { @@ -129,8 +139,6 @@ static int scale_speaker_volume(float volume) } -const int ERROR_VIVOX_OBJECT_NOT_FOUND = 1001; -const int ERROR_VIVOX_NOT_LOGGED_IN = 1007; /////////////////////////////////////////////////////////////////////////////////////////////// @@ -546,7 +554,7 @@ void LLVivoxVoiceClient::voiceControlCoro() // if we hit this and mRelogRequested is true, that indicates // that we attempted to relog into Vivox and were rejected. // Rather than just quit out of voice, we will tear it down (above) - // and then reconstruct the voice connecino from scratch. + // and then reconstruct the voice connecion from scratch. if (mRelogRequested) { while (isGatewayRunning()) @@ -784,13 +792,15 @@ bool LLVivoxVoiceClient::provisionVoiceAccount() if (status == LLCore::HttpStatus(404)) { - if (++retryCount > 5) + if (++retryCount > PROVISION_RETRY_MAX) { - LL_WARNS("Voice") << "Could not access voice provision cap after 5 attempts." << LL_ENDL; + LL_WARNS("Voice") << "Could not access voice provision cap after " << PROVISION_RETRY_MAX << " attempts." << LL_ENDL; return false; } - LL_WARNS("Voice") << "Provision CAP 404. Retrying in 1.0" << LL_ENDL; - llcoro::suspendUntilTimeout(1.0); + + F32 timeout = pow(PROVISION_RETRY_TIMEOUT, static_cast(retryCount)); + LL_WARNS("Voice") << "Provision CAP 404. Retrying in " << timeout << " seconds." << LL_ENDL; + llcoro::suspendUntilTimeout(timeout); continue; } @@ -888,21 +898,29 @@ bool LLVivoxVoiceClient::breakVoiceConnection(bool corowait) bool LLVivoxVoiceClient::loginToVivox() { - int loginRetryCount(0); LLEventPump &voicePump = LLEventPumps::instance().obtain("vivoxClientPump"); + LLSD timeoutResult; + timeoutResult["login"] = LLSD::String("timeout"); + + LLEventTimeout voicePumpTimeout(voicePump); + + int loginRetryCount(0); + bool response_ok(false); bool account_login(false); bool send_login(true); do { + mIsLoggingIn = true; if (send_login) loginSendMessage(); send_login = false; + voicePumpTimeout.eventAfter(LOGIN_ATTEMPT_TIMEOUT, timeoutResult); LLSD result = llcoro::suspendUntilEventOn(voicePump); LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; @@ -910,16 +928,16 @@ bool LLVivoxVoiceClient::loginToVivox() { std::string loginresp = result["login"]; - if (loginresp == "retry") + if ((loginresp == "retry") || (loginresp == "timeout")) { - if (!loginRetryCount) + if ((!loginRetryCount) && (loginresp != "timeout")) { // on first retry notify user notifyStatusObservers(LLVoiceClientStatusObserver::STATUS_LOGIN_RETRY); } - if ((++loginRetryCount > MAX_LOGIN_RETRIES) || (!result["login_retry"])) + if ((++loginRetryCount > LOGIN_RETRY_MAX) || (loginresp == "timeout")) { - LL_WARNS("Voice") << "too many login retries, giving up." << LL_ENDL; + LL_WARNS("Voice") << "too many login retries or timeout connecting, giving up." << LL_ENDL; LLSD args; std::stringstream errs; errs << mVoiceAccountServerURI << "\n:UDP: 3478, 3479, 5060, 5062, 12000-17000"; @@ -942,8 +960,10 @@ bool LLVivoxVoiceClient::loginToVivox() account_login = false; send_login = true; - LL_INFOS("Voice") << "will retry login in " << LOGIN_RETRY_SECONDS << " seconds." << LL_ENDL; - llcoro::suspendUntilTimeout(LOGIN_RETRY_SECONDS); + F32 timeout = pow(LOGIN_RETRY_TIMEOUT, static_cast(loginRetryCount)) - 1.0f; + + LL_INFOS("Voice") << "will retry login in " << timeout << " seconds." << LL_ENDL; + llcoro::suspendUntilTimeout(timeout); } else if (loginresp == "failed") { @@ -982,7 +1002,6 @@ bool LLVivoxVoiceClient::loginToVivox() void LLVivoxVoiceClient::logoutOfVivox(bool wait) { - LLEventPump &voicePump = LLEventPumps::instance().obtain("vivoxClientPump"); if (!mIsLoggedIn) return; @@ -995,7 +1014,14 @@ void LLVivoxVoiceClient::logoutOfVivox(bool wait) if (wait) { - LLSD result = llcoro::suspendUntilEventOn(voicePump); + LLEventPump &voicePump = LLEventPumps::instance().obtain("vivoxClientPump"); + LLSD timeoutResult; + timeoutResult["logout"] = LLSD::String("timeout"); + + LLEventTimeout voicePumpTimeout(voicePump); + + voicePumpTimeout.eventAfter(LOGIN_ATTEMPT_TIMEOUT, timeoutResult); + LLSD result = llcoro::suspendUntilEventOn(voicePumpTimeout); LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; @@ -1194,13 +1220,20 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) bool added(true); bool joined(false); + LLSD timeoutResult; + timeoutResult["session"] = LLSD::String("timeout"); + + LLEventTimeout voicePumpTimeout(voicePump); + + // It appears that I need to wait for BOTH the SessionGroup.AddSession response and the SessionStateChangeEvent with state 4 // before continuing from this state. They can happen in either order, and if I don't wait for both, things can get stuck. // For now, the SessionGroup.AddSession response handler sets mSessionHandle and the SessionStateChangeEvent handler transitions to stateSessionJoined. // This is a cheap way to make sure both have happened before proceeding. do { - result = llcoro::suspendUntilEventOn(voicePump); + voicePumpTimeout.eventAfter(SESSION_JOIN_TIMEOUT, timeoutResult); + result = llcoro::suspendUntilEventOn(voicePumpTimeout); LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; if (result.has("session")) @@ -1219,10 +1252,10 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) added = true; else if (message == "joined") joined = true; - else if ((message == "failed") || (message == "removed")) + else if ((message == "failed") || (message == "removed") || (message == "timeout")) { // we will get a removed message if a voice call is declined. - if (message == "failed") + if (message == "failed") { int reason = result["reason"].asInteger(); LL_WARNS("Voice") << "Add and join failed for reason " << reason << LL_ENDL; @@ -1638,8 +1671,8 @@ int LLVivoxVoiceClient::voiceRecordBuffer() LLSD result; captureBufferRecordStartSendMessage(); - notifyVoiceFontObservers(); + do { result = llcoro::suspendUntilEventOn(voicePump); @@ -1667,11 +1700,11 @@ int LLVivoxVoiceClient::voicePlaybackBuffer() LLEventPump &voicePump = LLEventPumps::instance().obtain("vivoxClientPump"); LLEventTimeout timeout(voicePump); - timeout.eventAfter(CAPTURE_BUFFER_MAX_TIME, timeoutResult); LLSD result; do { + timeout.eventAfter(CAPTURE_BUFFER_MAX_TIME, timeoutResult); captureBufferPlayStartSendMessage(mPreviewVoiceFont); // Store the voice font being previewed, so that we know to restart if it changes. @@ -1682,7 +1715,7 @@ int LLVivoxVoiceClient::voicePlaybackBuffer() // Update UI, should really use a separate callback. notifyVoiceFontObservers(); - result = llcoro::suspendUntilEventOn(voicePump); + result = llcoro::suspendUntilEventOn(timeout); LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; } while (!result.has("recplay")); -- cgit v1.2.3 From 86a3e1a3dc59c964d78c509e99a59d52eea32b34 Mon Sep 17 00:00:00 2001 From: Rider Linden Date: Tue, 19 Apr 2016 14:10:57 -0700 Subject: MAINT-6336: Crasher on disconnect in DDoS. --- indra/newview/llvoicevivox.cpp | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/indra/newview/llvoicevivox.cpp b/indra/newview/llvoicevivox.cpp index e015d4fa5e..518b5bdc65 100755 --- a/indra/newview/llvoicevivox.cpp +++ b/indra/newview/llvoicevivox.cpp @@ -1223,15 +1223,14 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) LLSD timeoutResult; timeoutResult["session"] = LLSD::String("timeout"); - LLEventTimeout voicePumpTimeout(voicePump); - - // It appears that I need to wait for BOTH the SessionGroup.AddSession response and the SessionStateChangeEvent with state 4 // before continuing from this state. They can happen in either order, and if I don't wait for both, things can get stuck. // For now, the SessionGroup.AddSession response handler sets mSessionHandle and the SessionStateChangeEvent handler transitions to stateSessionJoined. // This is a cheap way to make sure both have happened before proceeding. do { + LLEventTimeout voicePumpTimeout(voicePump); + voicePumpTimeout.eventAfter(SESSION_JOIN_TIMEOUT, timeoutResult); result = llcoro::suspendUntilEventOn(voicePumpTimeout); -- cgit v1.2.3 From 16e06b4b50af3f4f4e3c91f8db1e4f59a44d8422 Mon Sep 17 00:00:00 2001 From: Rider Linden Date: Tue, 19 Apr 2016 14:17:28 -0700 Subject: MAINT-6336: more loging for test build. --- indra/newview/llvoicevivox.cpp | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/indra/newview/llvoicevivox.cpp b/indra/newview/llvoicevivox.cpp index 518b5bdc65..17e538fcfa 100755 --- a/indra/newview/llvoicevivox.cpp +++ b/indra/newview/llvoicevivox.cpp @@ -1161,6 +1161,8 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) // The old session may now need to be deleted. reapSession(oldSession); + LL_INFOS("Voice") << "Done reap test." << LL_ENDL; + if (!mAudioSession->mHandle.empty()) { // Connect to a session by session handle @@ -1175,6 +1177,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) notifyStatusObservers(LLVoiceClientStatusObserver::STATUS_JOINING); + LL_INFOS("Voice") << "suspend after notify STATUS_JOINING." << LL_ENDL; llcoro::suspend(); LLSD result; @@ -1195,6 +1198,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) if (!mVoiceEnabled && mIsInitialized) { + LL_INFOS("Voice") << "Voice no longer enabled. Exiting." << LL_ENDL; mIsJoiningSession = false; // User bailed out during connect -- jump straight to teardown. terminateAudioSession(true); @@ -1203,6 +1207,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) } else if (mSessionTerminateRequested) { + LL_INFOS("Voice") << "Terminate requested" << LL_ENDL; if (mAudioSession && !mAudioSession->mHandle.empty()) { // Only allow direct exits from this state in p2p calls (for cancelling an invite). @@ -1229,12 +1234,13 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) // This is a cheap way to make sure both have happened before proceeding. do { + LL_INFOS("Voice") << "Top of add join loop." << LL_ENDL; LLEventTimeout voicePumpTimeout(voicePump); voicePumpTimeout.eventAfter(SESSION_JOIN_TIMEOUT, timeoutResult); result = llcoro::suspendUntilEventOn(voicePumpTimeout); - LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; + LL_INFOS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; if (result.has("session")) { if (result.has("handle")) @@ -1275,6 +1281,9 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) } } while (!added || !joined); + + LL_INFOS("Voice") << "Left voice loop." << LL_ENDL; + mIsJoiningSession = false; if (mSpatialJoiningNum > 100) -- cgit v1.2.3 From d96004e4af162a6338029db8ea2bbc914c072c19 Mon Sep 17 00:00:00 2001 From: Rider Linden Date: Wed, 20 Apr 2016 10:21:35 -0700 Subject: MAINT-6336: Crasher showing up in voice was a Bound Listener that should have been a Temp Bound listener. --- indra/llcommon/lleventfilter.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/indra/llcommon/lleventfilter.h b/indra/llcommon/lleventfilter.h index e822a664f5..8e01326823 100755 --- a/indra/llcommon/lleventfilter.h +++ b/indra/llcommon/lleventfilter.h @@ -181,7 +181,7 @@ protected: private: bool tick(const LLSD&); - LLBoundListener mMainloop; + LLTempBoundListener mMainloop; Action mAction; }; -- cgit v1.2.3 From 8f4be8bb869e3cde034607cbe0cb8272005f08b8 Mon Sep 17 00:00:00 2001 From: Rider Linden Date: Thu, 21 Apr 2016 09:16:50 -0700 Subject: MAINT-6336: Removed or demoted some of the chatty log messages I was using to track progress. --- indra/newview/llvoicevivox.cpp | 15 ++++----------- 1 file changed, 4 insertions(+), 11 deletions(-) diff --git a/indra/newview/llvoicevivox.cpp b/indra/newview/llvoicevivox.cpp index 17e538fcfa..ca0509c524 100755 --- a/indra/newview/llvoicevivox.cpp +++ b/indra/newview/llvoicevivox.cpp @@ -1161,8 +1161,6 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) // The old session may now need to be deleted. reapSession(oldSession); - LL_INFOS("Voice") << "Done reap test." << LL_ENDL; - if (!mAudioSession->mHandle.empty()) { // Connect to a session by session handle @@ -1177,7 +1175,6 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) notifyStatusObservers(LLVoiceClientStatusObserver::STATUS_JOINING); - LL_INFOS("Voice") << "suspend after notify STATUS_JOINING." << LL_ENDL; llcoro::suspend(); LLSD result; @@ -1198,7 +1195,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) if (!mVoiceEnabled && mIsInitialized) { - LL_INFOS("Voice") << "Voice no longer enabled. Exiting." << LL_ENDL; + LL_DEBUGS("Voice") << "Voice no longer enabled. Exiting." << LL_ENDL; mIsJoiningSession = false; // User bailed out during connect -- jump straight to teardown. terminateAudioSession(true); @@ -1207,7 +1204,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) } else if (mSessionTerminateRequested) { - LL_INFOS("Voice") << "Terminate requested" << LL_ENDL; + LL_DEBUGS("Voice") << "Terminate requested" << LL_ENDL; if (mAudioSession && !mAudioSession->mHandle.empty()) { // Only allow direct exits from this state in p2p calls (for cancelling an invite). @@ -1234,13 +1231,12 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) // This is a cheap way to make sure both have happened before proceeding. do { - LL_INFOS("Voice") << "Top of add join loop." << LL_ENDL; LLEventTimeout voicePumpTimeout(voicePump); voicePumpTimeout.eventAfter(SESSION_JOIN_TIMEOUT, timeoutResult); result = llcoro::suspendUntilEventOn(voicePumpTimeout); - LL_INFOS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; + LL_DEBUGS("Voice") << "event=" << ll_pretty_print_sd(result) << LL_ENDL; if (result.has("session")) { if (result.has("handle")) @@ -1268,7 +1264,7 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) if ((reason == ERROR_VIVOX_NOT_LOGGED_IN) || (reason == ERROR_VIVOX_OBJECT_NOT_FOUND)) { - LL_INFOS("Voice") << "Requesting reprovision and login." << LL_ENDL; + LL_DEBUGS("Voice") << "Requesting reprovision and login." << LL_ENDL; requestRelog(); } @@ -1281,9 +1277,6 @@ bool LLVivoxVoiceClient::addAndJoinSession(const sessionStatePtr_t &nextSession) } } while (!added || !joined); - - LL_INFOS("Voice") << "Left voice loop." << LL_ENDL; - mIsJoiningSession = false; if (mSpatialJoiningNum > 100) -- cgit v1.2.3