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.
2021-10-19 15:29:18 -05:00 · 2021-10-19 15:29:18 -05:00 · 284257a383
parent 0d5af3fedc
commit 284257a383
4 changed files with 115 additions and 8 deletions
--- a/src/Terminal.wprp
+++ b/src/Terminal.wprp
@ -13,6 +13,15 @@
    <EventProvider Id="EventProvider_TerminalRemoting" Name="d6f04aad-629f-539a-77c1-73f5c3e4aa7b" />
    <EventProvider Id="EventProvider_TerminalDirectX" Name="c93e739e-ae50-5a14-78e7-f171e947535d" />
    <EventProvider Id="EventProvider_TerminalUIA" Name="e7ebce59-2161-572d-b263-2f16a6afb9e5"/>
+    <!-- Console providers here -->
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.Launcher" Name="770aa552-671a-5e97-579b-151709ec0dbd"/>
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.Host" Name="fe1ff234-1f09-50a8-d38d-c44fab43e818"/>
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.Server" Name="1A541C01-589A-496E-85A7-A9E02170166D"/>
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.VirtualTerminal.Parser" Name="c9ba2a84-d3ca-5e19-2bd6-776a0910cb9d"/>
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.Render.VtEngine" Name="c9ba2a95-d3ca-5e19-2bd6-776a0910cb9d"/>
+    <EventProvider Id="EventProvider-Microsoft.Windows.Console.UIA" Name="e7ebce59-2161-572d-b263-2f16a6afb9e5"/>
+
+    <!-- Profile for General Terminal logging -->
    <Profile Id="Terminal.Verbose.File" Name="Terminal" Description="Terminal" LoggingMode="File" DetailLevel="Verbose">
      <Collectors>
        <EventCollectorId Value="EventCollector_Terminal">
@ -32,5 +41,27 @@
    <Profile Id="Terminal.Light.File" Name="Terminal" Description="Terminal" Base="Terminal.Verbose.File" LoggingMode="File" DetailLevel="Light" />
    <Profile Id="Terminal.Verbose.Memory" Name="Terminal" Description="Terminal" Base="Terminal.Verbose.File" LoggingMode="Memory" DetailLevel="Verbose" />
    <Profile Id="Terminal.Light.Memory" Name="Terminal" Description="Terminal" Base="Terminal.Verbose.File" LoggingMode="Memory" DetailLevel="Light" />
+
+    <!-- Profile for DefTerm logging. Includes some conhost logging. -->
+    <Profile Id="DefTerm.Verbose.File" Name="DefTerm" Description="DefTerm" LoggingMode="File" DetailLevel="Verbose">
+      <Collectors>
+        <EventCollectorId Value="EventCollector_Terminal">
+          <EventProviders>
+            <EventProviderId Value="EventProvider_TerminalControl" />
+            <EventProviderId Value="EventProvider_TerminalConnection" />
+            <EventProviderId Value="EventProvider_TerminalSettingsModel" />
+            <EventProviderId Value="EventProvider_TerminalApp" />
+            <EventProviderId Value="EventProvider_TerminalWin32Host" />
+            <EventProviderId Value="EventProvider_TerminalRemoting" />
+            <EventProviderId Value="EventProvider-Microsoft.Windows.Console.Launcher" />
+            <EventProviderId Value="EventProvider-Microsoft.Windows.Console.Host" />
+            <EventProviderId Value="EventProvider-Microsoft.Windows.Console.Server" />
+          </EventProviders>
+        </EventCollectorId>
+      </Collectors>
+    </Profile>
+    <Profile Id="DefTerm.Light.File" Name="DefTerm" Description="DefTerm" Base="DefTerm.Verbose.File" LoggingMode="File" DetailLevel="Light" />
+    <Profile Id="DefTerm.Verbose.Memory" Name="DefTerm" Description="DefTerm" Base="DefTerm.Verbose.File" LoggingMode="Memory" DetailLevel="Verbose" />
+    <Profile Id="DefTerm.Light.Memory" Name="DefTerm" Description="DefTerm" Base="DefTerm.Verbose.File" LoggingMode="Memory" DetailLevel="Light" />
  </Profiles>
-</WindowsPerformanceRecorder>
+</WindowsPerformanceRecorder>
--- 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));
        }

--- 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.
        }
    }
 }
--- 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<DWORD>(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<ITerminalHandoff> 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();