p#682 Improve logging for system events and session (#6086)

10 files changed, 100 insertions, 12 deletions

diff --git a/indra/llcommon/llwatchdog.cpp b/indra/llcommon/llwatchdog.cpp
index 66b565c763..886f19366c 100644
--- a/indra/llcommon/llwatchdog.cpp
+++ b/indra/llcommon/llwatchdog.cpp
@@ -116,6 +116,11 @@ bool LLWatchdogTimeout::isAlive() const
     return (mTimer.getStarted() && !mTimer.hasExpired());
 }
 
+bool LLWatchdogTimeout::started() const
+{
+    return mTimer.getStarted();
+}
+
 void LLWatchdogTimeout::reset()
 {
     mTimer.setTimerExpirySec(mTimeout);
diff --git a/indra/llcommon/llwatchdog.h b/indra/llcommon/llwatchdog.h
index f138fbccb0..d55bf434f3 100644
--- a/indra/llcommon/llwatchdog.h
+++ b/indra/llcommon/llwatchdog.h
@@ -47,6 +47,7 @@ public:
     // This may mean that resources used by
     // isAlive and other method may need synchronization.
     virtual bool isAlive() const = 0;
+    virtual bool started() const = 0;
     virtual void reset() = 0;
     virtual void start();
     virtual void stop();
@@ -66,6 +67,7 @@ public:
     virtual ~LLWatchdogTimeout();
 
     bool isAlive() const override;
+    bool started() const override;
     void reset() override;
     void start() override { start(""); }
     void stop() override;
diff --git a/indra/llui/llfloater.cpp b/indra/llui/llfloater.cpp
index 9361358ced..6de2c18620 100644
--- a/indra/llui/llfloater.cpp
+++ b/indra/llui/llfloater.cpp
@@ -569,6 +569,8 @@ void LLFloater::storeRectControl()
 
 void LLFloater::storeVisibilityControl()
 {
+    // Todo: this is a bit pricey, gets called each frame
+    // on LLAppViewer::idle(), optimize!
     if( !sQuitting && mVisibilityControl.size() > 1 )
     {
         getControlGroup()->setBOOL( mVisibilityControl, getVisible() );
diff --git a/indra/llwebrtc/llwebrtc.cpp b/indra/llwebrtc/llwebrtc.cpp
index 3d58e4e1ce..80f2c46332 100644
--- a/indra/llwebrtc/llwebrtc.cpp
+++ b/indra/llwebrtc/llwebrtc.cpp
@@ -748,6 +748,7 @@ void LLWebRTCImpl::updateDevices()
         char name[webrtc::kAdmMaxDeviceNameSize];
         char guid[webrtc::kAdmMaxGuidSize];
         mDeviceModule->PlayoutDeviceName(index, name, guid);
+        RTC_LOG(LS_VERBOSE) << "updateDevices: playout device [" << index << "] name='" << name << "' guid='" << guid << "'";
         mPlayoutDeviceList.emplace_back(name, guid);
     }
 
@@ -766,9 +767,12 @@ void LLWebRTCImpl::updateDevices()
         char name[webrtc::kAdmMaxDeviceNameSize];
         char guid[webrtc::kAdmMaxGuidSize];
         mDeviceModule->RecordingDeviceName(index, name, guid);
+        RTC_LOG(LS_VERBOSE) << "updateDevices: recording device [" << index << "] name='" << name << "' guid='" << guid << "'";
         mRecordingDeviceList.emplace_back(name, guid);
     }
 
+    RTC_LOG(LS_INFO) << "updateDevices, playout count: " << renderDeviceCount << "; capture count: " << captureDeviceCount;
+
     for (auto &observer : mVoiceDevicesObserverList)
     {
         observer->OnDevicesChanged(mPlayoutDeviceList, mRecordingDeviceList);
diff --git a/indra/llwindow/llwindowcallbacks.cpp b/indra/llwindow/llwindowcallbacks.cpp
index 7331f50ba0..4b804c82cc 100644
--- a/indra/llwindow/llwindowcallbacks.cpp
+++ b/indra/llwindow/llwindowcallbacks.cpp
@@ -190,7 +190,7 @@ bool LLWindowCallbacks::handleTimerEvent(LLWindow *window)
     return false;
 }
 
-bool LLWindowCallbacks::handleDeviceChange(LLWindow *window)
+bool LLWindowCallbacks::handleDeviceChange(LLWindow *window, const std::string& change_type)
 {
     return false;
 }
diff --git a/indra/llwindow/llwindowcallbacks.h b/indra/llwindow/llwindowcallbacks.h
index 59dcdd3ade..6d1990e92b 100644
--- a/indra/llwindow/llwindowcallbacks.h
+++ b/indra/llwindow/llwindowcallbacks.h
@@ -68,7 +68,7 @@ public:
     virtual void handleWindowUnblock(LLWindow *window);                         // window coming back after taking over CPU for a while
     virtual void handleDataCopy(LLWindow *window, S32 data_type, void *data);
     virtual bool handleTimerEvent(LLWindow *window);
-    virtual bool handleDeviceChange(LLWindow *window);
+    virtual bool handleDeviceChange(LLWindow *window, const std::string& change_type);
     virtual bool handleDPIChanged(LLWindow *window, F32 ui_scale_factor, S32 window_width, S32 window_height);
     virtual bool handleDisplayChanged();
     virtual bool handleWindowDidChangeScreen(LLWindow *window);
diff --git a/indra/llwindow/llwindowwin32.cpp b/indra/llwindow/llwindowwin32.cpp
index 6230cc3026..562dfc55ab 100644
--- a/indra/llwindow/llwindowwin32.cpp
+++ b/indra/llwindow/llwindowwin32.cpp
@@ -452,6 +452,16 @@ struct LLWindowWin32::LLWindowWin32Thread : public LL::ThreadPool
             }
         });
     }
+
+    // For mainWindowProc, it should not unpause watchdog if it was paused
+    void pingWindowTimeout(std::string_view state)
+    {
+        if (mWindowTimeout && mWindowTimeout->started())
+        {
+            mWindowTimeout->setTimeout(WINDOW_TIMEOUT_SEC);
+            mWindowTimeout->ping(state);
+        }
+    }
 private:
     // These timeout related functions are strictly for the thread.
     void resumeTimeout(std::string_view state)
@@ -2413,18 +2423,45 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
         case WM_DEVICECHANGE:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_DEVICECHANGE");
+            window_imp->mWindowThread->pingWindowTimeout("WM_DEVICECHANGE");
+
+            // Log detailed device change information
+            std::string change_type = "UNKNOWN";
+            switch (w_param)
+            {
+            case DBT_DEVICEARRIVAL:           change_type = "DBT_DEVICEARRIVAL"; break;
+            case DBT_DEVICEREMOVECOMPLETE:    change_type = "DBT_DEVICEREMOVECOMPLETE"; break;
+            case DBT_DEVNODES_CHANGED:        change_type = "DBT_DEVNODES_CHANGED"; break;
+            case DBT_DEVICEQUERYREMOVE:       change_type = "DBT_DEVICEQUERYREMOVE"; break;
+            case DBT_DEVICEQUERYREMOVEFAILED: change_type = "DBT_DEVICEQUERYREMOVEFAILED"; break;
+            case DBT_DEVICEREMOVEPENDING:     change_type = "DBT_DEVICEREMOVEPENDING"; break;
+            case DBT_CONFIGCHANGED:           change_type = "DBT_CONFIGCHANGED"; break;
+            }
+
             if (w_param == DBT_DEVNODES_CHANGED || w_param == DBT_DEVICEARRIVAL)
             {
-                WINDOW_IMP_POST(window_imp->mCallbacks->handleDeviceChange(window_imp));
+                WINDOW_IMP_POST(window_imp->mCallbacks->handleDeviceChange(window_imp, change_type));
 
                 return 1;
             }
+            else if (l_param)
+            {
+                const auto* hdr = reinterpret_cast<const DEV_BROADCAST_HDR*>(l_param);
+                if (hdr->dbch_devicetype == DBT_DEVTYP_DEVICEINTERFACE)
+                {
+                    // Might need to register for monitor device notifications
+                    // to get this message when monitor is suspended or resumed.
+                    // TODO: log monitor suspending and resuming.
+                    LL_INFOS("Window") << "DEVICEINTERFACE: " << change_type << LL_ENDL;
+                }
+            }
             break;
         }
 
         case WM_PAINT:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_PAINT");
+            window_imp->mWindowThread->pingWindowTimeout("WM_PAINT");
             GetUpdateRect(window_imp->mWindowHandle, &update_rect, FALSE);
             update_width = update_rect.right - update_rect.left + 1;
             update_height = update_rect.bottom - update_rect.top + 1;
@@ -2467,6 +2504,15 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
             break;
         }
 
+        case WM_POWERBROADCAST:
+        {
+            // Might need to register for power broadcast interface
+            // Todo: log monitor suspending and resuming.
+            LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_POWERBROADCAST");
+            LL_INFOS("Window") << "Received WM_POWERBROADCAST with wParam: 0x" << std::hex << (uintptr_t)w_param << " lParam: 0x" << (uintptr_t)l_param << std::dec << LL_ENDL;
+            break;
+        }
+
         case WM_ACTIVATEAPP:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_ACTIVATEAPP");
@@ -2540,6 +2586,7 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
         case WM_CLOSE:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_CLOSE");
+            window_imp->mWindowThread->pingWindowTimeout("WM_CLOSE");
             // todo: WM_CLOSE can be caused by user and by task manager,
             // distinguish these cases.
             // For now assume it is always user.
@@ -2577,6 +2624,7 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
             // Comes after WM_QUERYENDSESSION
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_ENDSESSION");
             LL_INFOS("Window") << "Received WM_ENDSESSION with wParam: " << (U32)w_param << " lParam: " << (U32)l_param << LL_ENDL;
+            window_imp->mWindowThread->pingWindowTimeout("WM_ENDSESSION");
             unsigned int end_session_flags = (U32)l_param;
 
             if (w_param == TRUE // if true, session is ending
@@ -3112,6 +3160,7 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
         case WM_DPICHANGED:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_DPICHANGED");
+            window_imp->mWindowThread->pingWindowTimeout("WM_DPICHANGED");
             LPRECT lprc_new_scale;
             F32 new_scale = F32(LOWORD(w_param)) / F32(USER_DEFAULT_SCREEN_DPI);
             lprc_new_scale = (LPRECT)l_param;
@@ -3132,7 +3181,9 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
 
         case WM_DISPLAYCHANGE:
         {
+            window_imp->mWindowThread->pingWindowTimeout("WM_DISPLAYCHANGE");
             WINDOW_IMP_POST(window_imp->mCallbacks->handleDisplayChanged());
+            break;
         }
 
         case WM_SETFOCUS:
@@ -3170,6 +3221,9 @@ LRESULT CALLBACK LLWindowWin32::mainWindowProc(HWND h_wnd, UINT u_msg, WPARAM w_
         case WM_SETTINGCHANGE:
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("mwp - WM_SETTINGCHANGE");
+            // Can be called on OS user switching
+            LL_INFOS("Window") << "WM_SETTINGCHANGE, with wParam: 0x" << std::hex << (uintptr_t)w_param << " lParam: 0x" << (uintptr_t)l_param << std::dec << LL_ENDL;
+            window_imp->mWindowThread->pingWindowTimeout("WM_SETTINGCHANGE");
             if (w_param == SPI_SETMOUSEVANISH)
             {
                 if (!SystemParametersInfo(SPI_GETMOUSEVANISH, 0, &window_imp->mMouseVanish, 0))
@@ -5014,6 +5068,13 @@ inline LLWindowWin32::LLWindowWin32Thread::LLWindowWin32Thread()
     : LL::ThreadPool("Window Thread", 1, MAX_QUEUE_SIZE, false)
 {
     LL::ThreadPool::start();
+
+    // Set thread name for the window thread
+    // This will make it distinguishable in Visual Studio debugger
+    post([this]()
+    {
+        SetThreadDescription(GetCurrentThread(), L"LLWindowWin32 Thread");
+    });
 }
 
 /**
@@ -5195,7 +5256,7 @@ void LLWindowWin32::LLWindowWin32Thread::run()
     }
 
     // Normally won't exist yet, but in case of re-init, make sure it's cleaned up
-    resumeTimeout("WindowThread");
+    resumeTimeout("Window:WindowThread");
 
     while (! getQueue().done())
     {
@@ -5206,23 +5267,25 @@ void LLWindowWin32::LLWindowWin32Thread::run()
 
         if (mWindowHandleThrd != 0)
         {
-            pingTimeout("messages");
             MSG msg;
             BOOL status;
             if (mhDCThrd == 0)
             {
+                pingTimeout("Window:PeekMessage");
                 LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("w32t - PeekMessage");
                 logger.onChange("PeekMessage(", std::hex, mWindowHandleThrd, ")");
                 status = PeekMessage(&msg, mWindowHandleThrd, 0, 0, PM_REMOVE);
             }
             else
             {
+                pingTimeout("Window:GetMessage");
                 LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("w32t - GetMessage");
                 logger.always("GetMessage(", std::hex, mWindowHandleThrd, ")");
                 status = GetMessage(&msg, NULL, 0, 0);
             }
             if (status > 0)
             {
+                pingTimeout("Window:TranslateMessage");
                 logger.always("got MSG (", std::hex, msg.hwnd, ", ", msg.message,
                               ", ", msg.wParam, ")");
                 TranslateMessage(&msg);
@@ -5234,7 +5297,7 @@ void LLWindowWin32::LLWindowWin32Thread::run()
 
         {
             LL_PROFILE_ZONE_NAMED_CATEGORY_WIN32("w32t - Function Queue");
-            pingTimeout("queue");
+            pingTimeout("Window:Queue");
             logger.onChange("runPending()");
             //process any pending functions
             getQueue().runPending();
diff --git a/indra/newview/llappviewer.cpp b/indra/newview/llappviewer.cpp
index 0b46e2ccc3..0a2b8a7d3d 100644
--- a/indra/newview/llappviewer.cpp
+++ b/indra/newview/llappviewer.cpp
@@ -2989,13 +2989,20 @@ bool LLAppViewer::initConfiguration()
 
     if (mSecondInstance)
     {
-        // This is the second instance of SL. Mute voice,
-        // but make sure the setting is *not* persisted.
+        // This is the second concurrent instance of SL.
+        // Disable voice for this session only, user should
+        // be able to enable voice manually, after that it
+        // works the same way as on primary instance.
         LLControlVariable* enable_voice = gSavedSettings.getControl("EnableVoiceChat");
-        if (enable_voice)
+        if (enable_voice && enable_voice->getValue().asBoolean())
         {
+            LL_DEBUGS("AppInit") << "Disabling voice for this session only" << LL_ENDL;
+            // Will be saved as mValues[2] which does not get written to the file.
+            // This feels like a hack, but otherwise way too many controls have to
+            // be tracked manually instead of using xmls' control_name.
             const bool DO_NOT_PERSIST = false;
-            enable_voice->setValue(LLSD(false), DO_NOT_PERSIST);
+            LLSD::Boolean new_value = false;
+            enable_voice->setValue(new_value, DO_NOT_PERSIST);
         }
     }
 
diff --git a/indra/newview/llviewerwindow.cpp b/indra/newview/llviewerwindow.cpp
index dea96e2012..b06c129974 100644
--- a/indra/newview/llviewerwindow.cpp
+++ b/indra/newview/llviewerwindow.cpp
@@ -1777,7 +1777,7 @@ bool LLViewerWindow::handleTimerEvent(LLWindow *window)
     return false;
 }
 
-bool LLViewerWindow::handleDeviceChange(LLWindow *window)
+bool LLViewerWindow::handleDeviceChange(LLWindow *window, const std::string& change_type)
 {
     // give a chance to use a joystick after startup (hot-plugging)
     if (!LLViewerJoystick::getInstance()->isJoystickInitialized() )
@@ -1785,6 +1785,10 @@ bool LLViewerWindow::handleDeviceChange(LLWindow *window)
         LLViewerJoystick::getInstance()->init(true);
         return true;
     }
+    else
+    {
+        LL_INFOS("Window") << "Device change event: " << change_type << LL_ENDL;
+    }
     return false;
 }
 
@@ -1806,6 +1810,7 @@ bool LLViewerWindow::handleDPIChanged(LLWindow *window, F32 ui_scale_factor, S32
 
 bool LLViewerWindow::handleDisplayChanged()
 {
+    LL_INFOS("Window") << "Display change event" << LL_ENDL;
     LLFontGL::sResolutionGeneration++;
     return false;
 }
diff --git a/indra/newview/llviewerwindow.h b/indra/newview/llviewerwindow.h
index 5f1afe2cbe..c748f051dd 100644
--- a/indra/newview/llviewerwindow.h
+++ b/indra/newview/llviewerwindow.h
@@ -231,7 +231,7 @@ public:
     /*virtual*/ void handleWindowUnblock(LLWindow *window);
     /*virtual*/ void handleDataCopy(LLWindow *window, S32 data_type, void *data);
     /*virtual*/ bool handleTimerEvent(LLWindow *window);
-    /*virtual*/ bool handleDeviceChange(LLWindow *window);
+    /*virtual*/ bool handleDeviceChange(LLWindow *window, const std::string& change_type);
     /*virtual*/ bool handleDPIChanged(LLWindow *window, F32 ui_scale_factor, S32 window_width, S32 window_height);
     /*virtual*/ bool handleDisplayChanged();
     /*virtual*/ bool handleWindowDidChangeScreen(LLWindow *window);