From 284257a38392c85a2f7d7ac7e77e20a05242ec64 Mon Sep 17 00:00:00 2001 From: Mike Griese Date: Tue, 19 Oct 2021 15:29:18 -0500 Subject: [PATCH] Add even MORE logging for defterm (#11537) Considering the number of reports of "defterm isn't working (mysteriously)", I figured more logging current hurt. I also added a wprp profile for the defterm logging as well, which should capture conhost side things as well. From an elevated conhost: ``` wpr -start path\to\Terminal.wprp!Defterm.Verbose wpr -stop %USERPROFILE%\defterm-trace.etl ``` * [x] I work here * [x] relevant to: #10594, #11529, #11524. --- src/Terminal.wprp | 33 ++++++++++- .../TerminalConnection/ConptyConnection.cpp | 10 ++++ src/cascadia/WindowsTerminal/AppHost.cpp | 23 +++++--- src/host/srvinit.cpp | 57 +++++++++++++++++++ 4 files changed, 115 insertions(+), 8 deletions(-) diff --git a/src/Terminal.wprp b/src/Terminal.wprp index 80a6e730b..129d83ca0 100644 --- a/src/Terminal.wprp +++ b/src/Terminal.wprp @@ -13,6 +13,15 @@ + + + + + + + + + @@ -32,5 +41,27 @@ + + + + + + + + + + + + + + + + + + + + + + - \ No newline at end of file + diff --git a/src/cascadia/TerminalConnection/ConptyConnection.cpp b/src/cascadia/TerminalConnection/ConptyConnection.cpp index 3792724d5..9135f8024 100644 --- a/src/cascadia/TerminalConnection/ConptyConnection.cpp +++ b/src/cascadia/TerminalConnection/ConptyConnection.cpp @@ -372,6 +372,16 @@ namespace winrt::Microsoft::Terminal::TerminalConnection::implementation // window is expecting it to be on the first layout. else { +#pragma warning(suppress : 26477 26485 26494 26482 26446) // We don't control TraceLoggingWrite + TraceLoggingWrite( + g_hTerminalConnectionProvider, + "ConPtyConnectedToDefterm", + TraceLoggingDescription("Event emitted when ConPTY connection is started, for a defterm session"), + TraceLoggingGuid(_guid, "SessionGuid", "The WT_SESSION's GUID"), + TraceLoggingWideString(_clientName.c_str(), "Client", "The attached client process"), + TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance)); + THROW_IF_FAILED(ConptyResizePseudoConsole(_hPC.get(), dimensions)); } diff --git a/src/cascadia/WindowsTerminal/AppHost.cpp b/src/cascadia/WindowsTerminal/AppHost.cpp index aa84b9e9e..c5d7418a0 100644 --- a/src/cascadia/WindowsTerminal/AppHost.cpp +++ b/src/cascadia/WindowsTerminal/AppHost.cpp @@ -1323,14 +1323,23 @@ void AppHost::_WindowMoved() const auto root{ _logic.GetRoot() }; - // This is basically DismissAllPopups which is also in - // TerminalSettingsEditor/Utils.h - // There isn't a good place that's shared between these two files, but - // it's only 5 LOC so whatever. - const auto popups{ Media::VisualTreeHelper::GetOpenPopupsForXamlRoot(root.XamlRoot()) }; - for (const auto& p : popups) + try { - p.IsOpen(false); + // This is basically DismissAllPopups which is also in + // TerminalSettingsEditor/Utils.h + // There isn't a good place that's shared between these two files, but + // it's only 5 LOC so whatever. + const auto popups{ Media::VisualTreeHelper::GetOpenPopupsForXamlRoot(root.XamlRoot()) }; + for (const auto& p : popups) + { + p.IsOpen(false); + } + } + catch (...) + { + // We purposely don't log here, because this is exceptionally noisy, + // especially on startup, when we're moving the window into place + // but might not have a real xamlRoot yet. } } } diff --git a/src/host/srvinit.cpp b/src/host/srvinit.cpp index b91a12873..49acf6f6a 100644 --- a/src/host/srvinit.cpp +++ b/src/host/srvinit.cpp @@ -28,6 +28,8 @@ #include "../inc/conint.h" #include "../propslib/DelegationConfig.hpp" +#include "tracing.hpp" + #if TIL_FEATURE_RECEIVEINCOMINGHANDOFF_ENABLED #include "ITerminalHandoff.h" #endif // TIL_FEATURE_RECEIVEINCOMINGHANDOFF_ENABLED @@ -69,10 +71,20 @@ try if (SUCCEEDED(DelegationConfig::s_GetDefaultConsoleId(delegationClsid))) { Globals.handoffConsoleClsid = delegationClsid; + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_FoundDelegationConsole", + TraceLoggingGuid(Globals.handoffConsoleClsid.value(), "ConsoleClsid"), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); } if (SUCCEEDED(DelegationConfig::s_GetDefaultTerminalId(delegationClsid))) { Globals.handoffTerminalClsid = delegationClsid; + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_FoundDelegationTerminal", + TraceLoggingGuid(Globals.handoffTerminalClsid.value(), "TerminalClsid"), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); } } @@ -400,7 +412,16 @@ HRESULT ConsoleCreateIoThread(_In_ HANDLE Server, [[maybe_unused]] PCONSOLE_API_MSG connectMessage) try { + // Create a telemetry instance here - this singleton is responsible for + // setting up the g_hConhostV2EventTraceProvider, which is otherwise not + // initialized in the defterm handoff at this point. + (void)Telemetry::Instance(); + #if !TIL_FEATURE_RECEIVEINCOMINGHANDOFF_ENABLED + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_ReceiveHandoff_Disabled", + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); return HRESULT_FROM_WIN32(ERROR_NOT_SUPPORTED); #else // TIL_FEATURE_RECEIVEINCOMINGHANDOFF_ENABLED auto& g = ServiceLocator::LocateGlobals(); @@ -418,9 +439,19 @@ try if (!g.handoffTerminalClsid) { + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_ReceiveHandoff_NoTerminal", + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); return E_NOT_SET; } + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_ReceiveHandoff", + TraceLoggingGuid(g.handoffTerminalClsid.value(), "TerminalClsid"), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + // Capture handle to the inbox process into a unique handle holder. g.handoffInboxConsoleHandle.reset(hostProcessHandle); @@ -453,9 +484,19 @@ try RETURN_IF_WIN32_BOOL_FALSE(CreatePipe(outPipeTheirSide.addressof(), outPipeOurSide.addressof(), nullptr, 0)); + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_ReceiveHandoff_OpenedPipes", + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + wil::unique_handle clientProcess{ OpenProcess(PROCESS_QUERY_INFORMATION | PROCESS_VM_READ | SYNCHRONIZE, TRUE, static_cast(connectMessage->Descriptor.Process)) }; RETURN_LAST_ERROR_IF_NULL(clientProcess.get()); + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_ReceiveHandoff_OpenedClient", + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + wil::unique_handle refHandle; RETURN_IF_NTSTATUS_FAILED(DeviceHandle::CreateClientHandle(refHandle.addressof(), Server, @@ -466,7 +507,18 @@ try ::Microsoft::WRL::ComPtr handoff; + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_PrepareToCreateDelegationTerminal", + TraceLoggingGuid(g.handoffTerminalClsid.value(), "TerminalClsid"), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + RETURN_IF_FAILED(CoCreateInstance(g.handoffTerminalClsid.value(), nullptr, CLSCTX_LOCAL_SERVER, IID_PPV_ARGS(&handoff))); + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_CreatedDelegationTerminal", + TraceLoggingGuid(g.handoffTerminalClsid.value(), "TerminalClsid"), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); RETURN_IF_FAILED(handoff->EstablishPtyHandoff(inPipeTheirSide.get(), outPipeTheirSide.get(), @@ -475,6 +527,11 @@ try serverProcess, clientProcess.get())); + TraceLoggingWrite(g_hConhostV2EventTraceProvider, + "SrvInit_DelegateToTerminalSucceeded", + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + inPipeTheirSide.reset(); outPipeTheirSide.reset(); signalPipeTheirSide.reset();