From 5daf4983d2192b7be870bf5ae6a3afbb5945a9ce Mon Sep 17 00:00:00 2001 From: "Dustin L. Howett" Date: Fri, 21 Jul 2023 14:00:37 -0500 Subject: [PATCH] Consolidate and clean up all API logging (#15737) `s_TraceApi` was a magic function in Tracing that logged a different event based on what type it was called with. It was bad for two reasons: 1. I wanted to add a field to each trace indicating the originating process and thread. This would have required adding a `CONSOLE_API_MSG` parameter to _every instance_ of `s_TraceApi`, and even then it would have not been particularly consistent. 2. The design of Tracing, where the TraceLogging macros are hidden inside opaque functions, subverts the lightweight trace probe detection present in `TraceLoggingWrite`. Every tracing probe turned into a call to a cold function which, in 99% of cases, returned immediately. To that end, I've introduced a new macro _only_ to ApiDispatchers that emits a named probe with a set of preloaded information. It is a macro to avoid any unnecessary branching or the emission of any explicit tracing functions into the final binary. I have also removed the generic handler for timing any/all API calls, as we never used them and they were largely redundant with the information we were capturing from API-specific reports. I've also removed tracing from all APIs that do not mutate console state. With the notable exception of ReadConsoleInput, we will see logs only for things that change mutable console state. All these things together allows us to construct a process+API-focused timeline of console events, ala: ``` cmd.exe (20304) CookedRead pwsh 4 07/13/2023 22:02:53.751 cmd.exe (20304) API_GetConsoleMode True cmd.exe (20304) API_SetConsoleMode False 0x00000003 cmd.exe (20304) API_SetConsoleMode True 0x000001F7 pwsh.exe (4032) ConsoleAttachDetach 07/13/2023 22:03:17.393 True True pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_SetConsoleMode False 0x00000007 ``` This pull request also switches the ConsoleAttachDetach and CookedRead reports to use the PID and FILETIME markings for their pids and filetimes. This is compatible with the uint32 and uint64 fields that used to use those names, so anybody who was depending on them will experience no change in functionality. I also switched up their order to make them more ergonomic in WPA when combined with the other API_ tracing (as viewed above.) --- src/host/tracing.cpp | 243 +--------------------------------- src/host/tracing.hpp | 25 +--- src/server/ApiDispatchers.cpp | 115 +++++++++++----- src/server/ApiSorter.cpp | 1 - src/server/ProcessHandle.cpp | 25 ++-- src/server/ProcessHandle.h | 4 +- 6 files changed, 103 insertions(+), 310 deletions(-) diff --git a/src/host/tracing.cpp b/src/host/tracing.cpp index c0547075078..bf54edbed99 100644 --- a/src/host/tracing.cpp +++ b/src/host/tracing.cpp @@ -18,7 +18,7 @@ enum TraceKeywords Output = 0x008, // _DBGOUTPUT General = 0x100, Input = 0x200, - API = 0x400, + //API = 0x400, // No longer used UIA = 0x800, CookedRead = 0x1000, ConsoleAttachDetach = 0x2000, @@ -26,241 +26,8 @@ enum TraceKeywords }; DEFINE_ENUM_FLAG_OPERATORS(TraceKeywords); -// Routine Description: -// - Creates a tracing object to assist with automatically firing a stop event -// when this object goes out of scope. -// - Give it back to the caller and they will release it when the event period is over. -// Arguments: -// - onExit - Function to process when the object is destroyed (on exit) -Tracing::Tracing(std::function onExit) : - _onExit(onExit) -{ -} - -// Routine Description: -// - Destructs a tracing object, running any on exit routine, if necessary. -Tracing::~Tracing() -{ - if (_onExit) - { - _onExit(); - } -} - -// Routine Description: -// - Provides generic tracing for all API call types in the form of -// start/stop period events for timing and region-of-interest purposes -// while doing performance analysis. -// Arguments: -// - result - Reference to the area where the result code from the Api call -// will be stored for use in the stop event. -// - traceName - The name of the API call to list in the trace details -// Return Value: -// - An object for the caller to hold until the API call is complete. -// Then destroy it to signal that the call is over so the stop trace can be written. -Tracing Tracing::s_TraceApiCall(const NTSTATUS result, PCSTR traceName) -{ - // clang-format off - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "ApiCall", - TraceLoggingString(traceName, "ApiName"), - TraceLoggingOpcode(WINEVENT_OPCODE_START), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - - return Tracing([traceName, &result] { - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "ApiCall", - TraceLoggingString(traceName, "ApiName"), - TraceLoggingHResult(result, "Result"), - TraceLoggingOpcode(WINEVENT_OPCODE_STOP), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - }); - // clang-format on -} - ULONG Tracing::s_ulDebugFlag = 0x0; -void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_GETLARGESTWINDOWSIZE_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_GetLargestWindowSize", - TraceLoggingHexInt32(status, "ResultCode"), - TraceLoggingInt32(a->Size.X, "MaxWindowWidthInChars"), - TraceLoggingInt32(a->Size.Y, "MaxWindowHeightInChars"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - -void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_MSG* const a, const bool fSet) -{ - // Duplicate copies required by TraceLogging documentation ("don't get cute" examples) - // Using logic inside these macros can make problems. Do all logic outside macros. - - if (fSet) - { - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_SetConsoleScreenBufferInfo", - TraceLoggingHexInt32(status, "ResultCode"), - TraceLoggingInt32(a->Size.X, "BufferWidthInChars"), - TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"), - TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"), - TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"), - TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"), - TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - } - else - { - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_GetConsoleScreenBufferInfo", - TraceLoggingHexInt32(status, "ResultCode"), - TraceLoggingInt32(a->Size.X, "BufferWidthInChars"), - TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"), - TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"), - TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"), - TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"), - TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - } -} - -void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETSCREENBUFFERSIZE_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_SetConsoleScreenBufferSize", - TraceLoggingHexInt32(status, "ResultCode"), - TraceLoggingInt32(a->Size.X, "BufferWidthInChars"), - TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - -void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETWINDOWINFO_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_SetConsoleWindowInfo", - TraceLoggingHexInt32(status, "ResultCode"), - TraceLoggingBool(a->Absolute, "IsWindowRectAbsolute"), - TraceLoggingInt32(a->Window.Left, "WindowRectLeft"), - TraceLoggingInt32(a->Window.Right, "WindowRectRight"), - TraceLoggingInt32(a->Window.Top, "WindowRectTop"), - TraceLoggingInt32(a->Window.Bottom, "WindowRectBottom"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - -void Tracing::s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSOLE_MSG* const a) -{ - // clang-format off - if (a->Unicode) - { - const auto buf = static_cast(buffer); - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_WriteConsole", - TraceLoggingBoolean(a->Unicode, "Unicode"), - TraceLoggingUInt32(a->NumBytes, "NumBytes"), - TraceLoggingCountedWideString(buf, static_cast(a->NumBytes / sizeof(wchar_t)), "input buffer"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - } - else - { - const auto buf = static_cast(buffer); - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_WriteConsole", - TraceLoggingBoolean(a->Unicode, "Unicode"), - TraceLoggingUInt32(a->NumBytes, "NumBytes"), - TraceLoggingCountedString(buf, static_cast(a->NumBytes / sizeof(char)), "input buffer"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - } - // clang-format on -} - -void Tracing::s_TraceApi(const CONSOLE_SCREENBUFFERINFO_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_GetConsoleScreenBufferInfo", - TraceLoggingInt16(a->Size.X, "Size.X"), - TraceLoggingInt16(a->Size.Y, "Size.Y"), - TraceLoggingInt16(a->CursorPosition.X, "CursorPosition.X"), - TraceLoggingInt16(a->CursorPosition.Y, "CursorPosition.Y"), - TraceLoggingInt16(a->ScrollPosition.X, "ScrollPosition.X"), - TraceLoggingInt16(a->ScrollPosition.Y, "ScrollPosition.Y"), - TraceLoggingHexUInt16(a->Attributes, "Attributes"), - TraceLoggingInt16(a->CurrentWindowSize.X, "CurrentWindowSize.X"), - TraceLoggingInt16(a->CurrentWindowSize.Y, "CurrentWindowSize.Y"), - TraceLoggingInt16(a->MaximumWindowSize.X, "MaximumWindowSize.X"), - TraceLoggingInt16(a->MaximumWindowSize.Y, "MaximumWindowSize.Y"), - TraceLoggingHexUInt16(a->PopupAttributes, "PopupAttributes"), - TraceLoggingBoolean(a->FullscreenSupported, "FullscreenSupported"), - TraceLoggingHexUInt32FixedArray((UINT32 const*)a->ColorTable, _countof(a->ColorTable), "ColorTable"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); - static_assert(sizeof(UINT32) == sizeof(*a->ColorTable), "a->ColorTable"); -} - -void Tracing::s_TraceApi(const CONSOLE_MODE_MSG* const a, const std::wstring_view handleType) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_GetConsoleMode", - TraceLoggingHexUInt32(a->Mode, "Mode"), - TraceLoggingCountedWideString(handleType.data(), gsl::narrow_cast(handleType.size()), "Handle type"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - -void Tracing::s_TraceApi(const CONSOLE_SETTEXTATTRIBUTE_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_SetConsoleTextAttribute", - TraceLoggingHexUInt16(a->Attributes, "Attributes"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - -void Tracing::s_TraceApi(const CONSOLE_WRITECONSOLEOUTPUTSTRING_MSG* const a) -{ - TraceLoggingWrite( - g_hConhostV2EventTraceProvider, - "API_WriteConsoleOutput", - TraceLoggingInt16(a->WriteCoord.X, "WriteCoord.X"), - TraceLoggingInt16(a->WriteCoord.Y, "WriteCoord.Y"), - TraceLoggingHexUInt32(a->StringType, "StringType"), - TraceLoggingUInt32(a->NumRecords, "NumRecords"), - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingKeyword(TraceKeywords::API)); -} - void Tracing::s_TraceWindowViewport(const Viewport& viewport) { TraceLoggingWrite( @@ -413,10 +180,10 @@ void Tracing::s_TraceCookedRead(_In_ ConsoleProcessHandle* const pConsoleProcess TraceLoggingWrite( g_hConhostV2EventTraceProvider, "CookedRead", + TraceLoggingPid(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"), TraceLoggingCountedWideString(pwchCookedBuffer, cchCookedBufferLength, "ReadBuffer"), TraceLoggingULong(cchCookedBufferLength, "ReadBufferLength"), - TraceLoggingUInt32(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"), - TraceLoggingUInt64(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"), + TraceLoggingFileTime(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"), TraceLoggingKeyword(TIL_KEYWORD_TRACE), TraceLoggingKeyword(TraceKeywords::CookedRead)); } @@ -431,8 +198,8 @@ void Tracing::s_TraceConsoleAttachDetach(_In_ ConsoleProcessHandle* const pConso TraceLoggingWrite( g_hConhostV2EventTraceProvider, "ConsoleAttachDetach", - TraceLoggingUInt32(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"), - TraceLoggingUInt64(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"), + TraceLoggingPid(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"), + TraceLoggingFileTime(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"), TraceLoggingBool(bIsAttach, "IsAttach"), TraceLoggingBool(bIsUserInteractive, "IsUserInteractive"), TraceLoggingKeyword(TIL_KEYWORD_TRACE), diff --git a/src/host/tracing.hpp b/src/host/tracing.hpp index f1d1e4126a1..8be4bf21b82 100644 --- a/src/host/tracing.hpp +++ b/src/host/tracing.hpp @@ -35,25 +35,14 @@ Author(s): #define DBGOUTPUT(_params_) #endif +#define TraceLoggingConsoleCoord(value, name) \ + TraceLoggingStruct(2, name), \ + TraceLoggingInt32(value.X, "X"), \ + TraceLoggingInt32(value.Y, "Y") + class Tracing { public: - ~Tracing(); - - static Tracing s_TraceApiCall(const NTSTATUS result, PCSTR traceName); - - static void s_TraceApi(const NTSTATUS status, const CONSOLE_GETLARGESTWINDOWSIZE_MSG* const a); - static void s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_MSG* const a, const bool fSet); - static void s_TraceApi(const NTSTATUS status, const CONSOLE_SETSCREENBUFFERSIZE_MSG* const a); - static void s_TraceApi(const NTSTATUS status, const CONSOLE_SETWINDOWINFO_MSG* const a); - - static void s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSOLE_MSG* const a); - - static void s_TraceApi(const CONSOLE_SCREENBUFFERINFO_MSG* const a); - static void s_TraceApi(const CONSOLE_MODE_MSG* const a, const std::wstring_view handleType); - static void s_TraceApi(const CONSOLE_SETTEXTATTRIBUTE_MSG* const a); - static void s_TraceApi(const CONSOLE_WRITECONSOLEOUTPUTSTRING_MSG* const a); - static void s_TraceWindowViewport(const Microsoft::Console::Types::Viewport& viewport); static void s_TraceChars(_In_z_ const char* pszMessage, ...); @@ -69,8 +58,4 @@ class Tracing private: static ULONG s_ulDebugFlag; - - Tracing(std::function onExit); - - std::function _onExit; }; diff --git a/src/server/ApiDispatchers.cpp b/src/server/ApiDispatchers.cpp index 22f7449a7b8..ce3b81b8212 100644 --- a/src/server/ApiDispatchers.cpp +++ b/src/server/ApiDispatchers.cpp @@ -12,6 +12,29 @@ #include "../host/telemetry.hpp" #include "../host/cmdline.h" +// Assumes that it will find in the calling environment. +#define TraceConsoleAPICallWithOrigin(ApiName, ...) \ + TraceLoggingWrite( \ + g_hConhostV2EventTraceProvider, \ + "API_" ApiName, \ + TraceLoggingPid(TraceGetProcessId(m), "OriginatingProcess"), \ + TraceLoggingTid(TraceGetThreadId(m), "OriginatingThread"), \ + __VA_ARGS__ __VA_OPT__(, ) \ + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), \ + TraceLoggingKeyword(TIL_KEYWORD_TRACE)); + +static DWORD TraceGetProcessId(CONSOLE_API_MSG* const m) +{ + const auto p = m->GetProcessHandle(); + return p ? p->dwProcessId : 0; +} + +static DWORD TraceGetThreadId(CONSOLE_API_MSG* const m) +{ + const auto p = m->GetProcessHandle(); + return p ? p->dwThreadId : 0; +} + [[nodiscard]] HRESULT ApiDispatchers::ServerGetConsoleCP(_Inout_ CONSOLE_API_MSG* const m, _Inout_ BOOL* const /*pbReplyPending*/) { @@ -35,35 +58,22 @@ { Telemetry::Instance().LogApiCall(Telemetry::ApiCall::GetConsoleMode); const auto a = &m->u.consoleMsgL1.GetConsoleMode; - std::wstring_view handleType = L"unknown"; - - TraceLoggingWrite(g_hConhostV2EventTraceProvider, - "API_GetConsoleMode", - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingOpcode(WINEVENT_OPCODE_START)); - - auto tracing = wil::scope_exit([&]() { - Tracing::s_TraceApi(a, handleType); - TraceLoggingWrite(g_hConhostV2EventTraceProvider, - "API_GetConsoleMode", - TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), - TraceLoggingKeyword(TIL_KEYWORD_TRACE), - TraceLoggingOpcode(WINEVENT_OPCODE_STOP)); - }); const auto pObjectHandle = m->GetObjectHandle(); RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle); + + TraceConsoleAPICallWithOrigin( + "GetConsoleMode", + TraceLoggingBool(pObjectHandle->IsInputHandle(), "InputHandle")); + if (pObjectHandle->IsInputHandle()) { - handleType = L"input"; InputBuffer* pObj; RETURN_IF_FAILED(pObjectHandle->GetInputBuffer(GENERIC_READ, &pObj)); m->_pApiRoutines->GetConsoleInputModeImpl(*pObj, a->Mode); } else { - handleType = L"output"; SCREEN_INFORMATION* pObj; RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_READ, &pObj)); m->_pApiRoutines->GetConsoleOutputModeImpl(*pObj, a->Mode); @@ -79,6 +89,12 @@ const auto pObjectHandle = m->GetObjectHandle(); RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle); + + TraceConsoleAPICallWithOrigin( + "SetConsoleMode", + TraceLoggingBool(pObjectHandle->IsInputHandle(), "InputHandle"), + TraceLoggingHexULong(a->Mode, "Mode")); + if (pObjectHandle->IsInputHandle()) { InputBuffer* pObj; @@ -365,9 +381,6 @@ // Get input parameter buffer PVOID pvBuffer; ULONG cbBufferSize; - auto tracing = wil::scope_exit([&]() { - Tracing::s_TraceApi(pvBuffer, a); - }); RETURN_IF_FAILED(m->GetInputBuffer(&pvBuffer, &cbBufferSize)); std::unique_ptr waiter; @@ -385,6 +398,11 @@ const std::wstring_view buffer(reinterpret_cast(pvBuffer), cbBufferSize / sizeof(wchar_t)); size_t cchInputRead; + TraceConsoleAPICallWithOrigin( + "WriteConsoleW", + TraceLoggingUInt32(a->NumBytes, "NumBytes"), + TraceLoggingCountedWideString(buffer.data(), static_cast(buffer.size()), "Buffer")); + hr = m->_pApiRoutines->WriteConsoleWImpl(*pScreenInfo, buffer, cchInputRead, requiresVtQuirk, waiter); // We must set the reply length in bytes. Convert back from characters. @@ -395,6 +413,11 @@ const std::string_view buffer(reinterpret_cast(pvBuffer), cbBufferSize); size_t cchInputRead; + TraceConsoleAPICallWithOrigin( + "WriteConsoleA", + TraceLoggingUInt32(a->NumBytes, "NumBytes"), + TraceLoggingCountedString(buffer.data(), static_cast(buffer.size()), "Buffer")); + hr = m->_pApiRoutines->WriteConsoleAImpl(*pScreenInfo, buffer, cchInputRead, requiresVtQuirk, waiter); // Reply length is already in bytes (chars), don't need to convert. @@ -581,10 +604,6 @@ Telemetry::Instance().LogApiCall(Telemetry::ApiCall::GetConsoleScreenBufferInfoEx); const auto a = &m->u.consoleMsgL2.GetConsoleScreenBufferInfo; - auto tracing = wil::scope_exit([&]() { - Tracing::s_TraceApi(a); - }); - CONSOLE_SCREEN_BUFFER_INFOEX ex = { 0 }; ex.cbSize = sizeof(CONSOLE_SCREEN_BUFFER_INFOEX); @@ -640,6 +659,12 @@ ex.wAttributes = a->Attributes; ex.wPopupAttributes = a->PopupAttributes; + TraceConsoleAPICallWithOrigin( + "SetConsoleScreenBufferInfoEx", + TraceLoggingConsoleCoord(a->Size, "BufferSize"), + TraceLoggingConsoleCoord(a->CurrentWindowSize, "WindowSize"), + TraceLoggingConsoleCoord(a->MaximumWindowSize, "MaxWindowSize")); + return m->_pApiRoutines->SetConsoleScreenBufferInfoExImpl(*pObj, ex); } @@ -655,6 +680,10 @@ SCREEN_INFORMATION* pObj; RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj)); + TraceConsoleAPICallWithOrigin( + "SetConsoleScreenBufferSize", + TraceLoggingConsoleCoord(a->Size, "BufferSize")); + return m->_pApiRoutines->SetConsoleScreenBufferSizeImpl(*pObj, til::wrap_coord_size(a->Size)); } @@ -731,15 +760,16 @@ Telemetry::Instance().LogApiCall(Telemetry::ApiCall::SetConsoleTextAttribute); const auto a = &m->u.consoleMsgL2.SetConsoleTextAttribute; - auto tracing = wil::scope_exit([&]() { - Tracing::s_TraceApi(a); - }); - const auto pObjectHandle = m->GetObjectHandle(); RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle); SCREEN_INFORMATION* pObj; RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj)); + + TraceConsoleAPICallWithOrigin( + "SetConsoleTextAttribute", + TraceLoggingHexUInt16(a->Attributes, "Attributes")); + RETURN_HR(m->_pApiRoutines->SetConsoleTextAttributeImpl(*pObj, a->Attributes)); } @@ -755,6 +785,14 @@ SCREEN_INFORMATION* pObj; RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj)); + TraceConsoleAPICallWithOrigin( + "SetConsoleWindowInfo", + TraceLoggingBool(a->Absolute, "IsWindowRectAbsolute"), + TraceLoggingInt32(a->Window.Left, "WindowRectLeft"), + TraceLoggingInt32(a->Window.Right, "WindowRectRight"), + TraceLoggingInt32(a->Window.Top, "WindowRectTop"), + TraceLoggingInt32(a->Window.Bottom, "WindowRectBottom")); + return m->_pApiRoutines->SetConsoleWindowInfoImpl(*pObj, a->Absolute, til::wrap_small_rect(a->Window)); } @@ -911,10 +949,6 @@ { const auto a = &m->u.consoleMsgL2.WriteConsoleOutputString; - auto tracing = wil::scope_exit([&]() { - Tracing::s_TraceApi(a); - }); - switch (a->StringType) { case CONSOLE_ATTRIBUTE: @@ -951,6 +985,11 @@ { const std::string_view text(reinterpret_cast(pvBuffer), cbBufferSize); + TraceConsoleAPICallWithOrigin( + "WriteConsoleOutputCharacterA", + TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"), + TraceLoggingUInt32(a->NumRecords, "NumRecords")); + hr = m->_pApiRoutines->WriteConsoleOutputCharacterAImpl(*pScreenInfo, text, til::wrap_coord(a->WriteCoord), @@ -963,6 +1002,11 @@ { const std::wstring_view text(reinterpret_cast(pvBuffer), cbBufferSize / sizeof(wchar_t)); + TraceConsoleAPICallWithOrigin( + "WriteConsoleOutputCharacterW", + TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"), + TraceLoggingUInt32(a->NumRecords, "NumRecords")); + hr = m->_pApiRoutines->WriteConsoleOutputCharacterWImpl(*pScreenInfo, text, til::wrap_coord(a->WriteCoord), @@ -974,6 +1018,11 @@ { const std::span text(reinterpret_cast(pvBuffer), cbBufferSize / sizeof(WORD)); + TraceConsoleAPICallWithOrigin( + "WriteConsoleOutputAttribute", + TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"), + TraceLoggingUInt32(a->NumRecords, "NumRecords")); + hr = m->_pApiRoutines->WriteConsoleOutputAttributeImpl(*pScreenInfo, text, til::wrap_coord(a->WriteCoord), diff --git a/src/server/ApiSorter.cpp b/src/server/ApiSorter.cpp index 2593eb5806e..39cf676e497 100644 --- a/src/server/ApiSorter.cpp +++ b/src/server/ApiSorter.cpp @@ -174,7 +174,6 @@ PCONSOLE_API_MSG ApiSorter::ConsoleDispatchRequest(_Inout_ PCONSOLE_API_MSG Mess // alias API. NTSTATUS Status = S_OK; { - const auto trace = Tracing::s_TraceApiCall(Status, Descriptor->TraceName); Status = (*Descriptor->Routine)(Message, &ReplyPending); } if (Status != STATUS_BUFFER_TOO_SMALL) diff --git a/src/server/ProcessHandle.cpp b/src/server/ProcessHandle.cpp index b9cf2f1b359..51b6f221c6b 100644 --- a/src/server/ProcessHandle.cpp +++ b/src/server/ProcessHandle.cpp @@ -28,7 +28,7 @@ ConsoleProcessHandle::ConsoleProcessHandle(const DWORD dwProcessId, dwProcessId))), _policy(ConsoleProcessPolicy::s_CreateInstance(_hProcess.get())), _shimPolicy(_hProcess.get()), - _processCreationTime(0) + _processCreationTime{} { if (nullptr != _hProcess.get()) { @@ -77,24 +77,17 @@ const HANDLE ConsoleProcessHandle::GetRawHandle() const // Routine Description: // - Retrieves the process creation time (currently used in telemetry traces) // - The creation time is lazily populated on first call -const ULONG64 ConsoleProcessHandle::GetProcessCreationTime() const +const FILETIME ConsoleProcessHandle::GetProcessCreationTime() const { - if (_processCreationTime == 0 && _hProcess != nullptr) + if (_processCreationTime.dwHighDateTime == 0 && _processCreationTime.dwLowDateTime == 0 && _hProcess != nullptr) { - FILETIME ftCreationTime, ftDummyTime = { 0 }; - ULARGE_INTEGER creationTime = { 0 }; + FILETIME ftDummyTime = { 0 }; - if (::GetProcessTimes(_hProcess.get(), - &ftCreationTime, - &ftDummyTime, - &ftDummyTime, - &ftDummyTime)) - { - creationTime.HighPart = ftCreationTime.dwHighDateTime; - creationTime.LowPart = ftCreationTime.dwLowDateTime; - } - - _processCreationTime = creationTime.QuadPart; + ::GetProcessTimes(_hProcess.get(), + &_processCreationTime, + &ftDummyTime, + &ftDummyTime, + &ftDummyTime); } return _processCreationTime; diff --git a/src/server/ProcessHandle.h b/src/server/ProcessHandle.h index 02f7ad9ba05..58f9f9c52d2 100644 --- a/src/server/ProcessHandle.h +++ b/src/server/ProcessHandle.h @@ -53,14 +53,14 @@ class ConsoleProcessHandle CD_CONNECTION_INFORMATION GetConnectionInformation(IDeviceComm* deviceComm) const; - const ULONG64 GetProcessCreationTime() const; + const FILETIME GetProcessCreationTime() const; private: ULONG _ulTerminateCount; ULONG const _ulProcessGroupId; wil::unique_handle const _hProcess; - mutable ULONG64 _processCreationTime; + mutable FILETIME _processCreationTime; const ConsoleProcessPolicy _policy; const ConsoleShimPolicy _shimPolicy;