Skip to content

Commit

Permalink
Add telemetry events (#229)
Browse files Browse the repository at this point in the history 
## Why is this change being made?
Present Telemetry is broken and doesn't generate events. Also, it is limited and not captures all fixups and features.

## What changed?
More tracelogging events are added to capture telemetry across all fixups and features.

## How was the change tested?
Event generation is verified through TRTT
  • Loading branch information
@npuvvada
npuvvada committed Feb 24, 2023
1 parent 75996d7 commit c4daede
Show file tree
Hide file tree
Showing 24 changed files with 368 additions and 112 deletions.
6 changes: 6 additions & 0 deletions PsfLauncher/PsfPowershellScriptRunner.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
#include <wil\resource.h>
#include <known_folders.h>
#include "proc_helper.h"
#include "psf_tracelogging.h"

#ifndef SW_SHOW
#define SW_SHOW 5
Expand All @@ -13,6 +14,7 @@
#define SW_HIDE 0
#endif


class PsfPowershellScriptRunner
{
public:
Expand Down Expand Up @@ -157,6 +159,10 @@ class PsfPowershellScriptRunner
std::wstring exitCodeStr = std::to_wstring(exitCode);
MessageBoxEx(NULL, (script.scriptPath + std::wstring(L" execution failed with Exit Code ") + exitCodeStr + std::wstring(L". To fix this, please run ") + script.scriptPath + std::wstring(L" standalone in a PowerShell window and confirm that the value of $LASTEXITCODE is 0 (Success) before using it with PSF.")).c_str(), L"Package Support Framework", MB_OK | MB_ICONWARNING, 0);
}

const wchar_t* scriptType = (&script == &(this->m_startingScriptInformation)) ? L"StartScript" : L"EndScript";
psf::TraceLogScriptInformation(scriptType, script.scriptPath.c_str(), script.commandString.c_str(), script.waitForScriptToFinish,
script.timeout, script.shouldRunOnce, script.showWindowAction, exitCode);
}

ScriptInformation MakeScriptInformation(const psf::json_object* scriptInformation, bool stopOnScriptError, std::wstring scriptExecutionMode, std::filesystem::path currentDirectory, std::filesystem::path packageRoot, std::filesystem::path packageWritableRoot)
Expand Down
79 changes: 23 additions & 56 deletions PsfLauncher/main.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,6 @@
#include <fstream>
#include <string>
#include <sstream>

#include <windows.h>
#include <shellapi.h>
#include <combaseapi.h>
Expand All @@ -18,13 +17,13 @@
#include "Telemetry.h"
#include "PsfPowershellScriptRunner.h"
#include <TraceLoggingProvider.h>
#include "psf_tracelogging.h"
#include <psf_constants.h>
#include <psf_runtime.h>
#include <wil\result.h>
#include <wil\resource.h>
#include <debug.h>


TRACELOGGING_DECLARE_PROVIDER(g_Log_ETW_ComponentProvider);
TRACELOGGING_DEFINE_PROVIDER(
g_Log_ETW_ComponentProvider,
Expand All @@ -34,6 +33,8 @@ TRACELOGGING_DEFINE_PROVIDER(

using namespace std::literals;

LARGE_INTEGER psfLoad_startCounter;

// Forward declarations
void LogApplicationAndProcessesCollection();
int launcher_main(PCWSTR args, int cmdShow) noexcept;
Expand All @@ -45,14 +46,16 @@ std::wstring ReplaceVariablesInString(std::wstring inputString, bool ReplaceEnvi
static inline bool check_suffix_if(iwstring_view str, iwstring_view suffix) noexcept;

int __stdcall wWinMain(_In_ HINSTANCE, _In_opt_ HINSTANCE, _In_ PWSTR args, _In_ int cmdShow)
{
{
QueryPerformanceCounter(&psfLoad_startCounter);
return launcher_main(args, cmdShow);
}

int launcher_main(PCWSTR args, int cmdShow) noexcept try
{
Log("\tIn Launcher_main()");

TraceLoggingRegister(g_Log_ETW_ComponentProvider);
auto appConfig = PSFQueryCurrentAppLaunchConfig(true);
THROW_HR_IF_MSG(ERROR_NOT_FOUND, !appConfig, "Error: could not find matching appid in config.json and appx manifest");

Expand All @@ -72,7 +75,8 @@ int launcher_main(PCWSTR args, int cmdShow) noexcept try
}
#endif

LogApplicationAndProcessesCollection();
std::string currentExeFixes;
psf::TraceLogApplicationsConfigdata(currentExeFixes);

auto dirPtr = appConfig->try_get("workingDirectory");
auto dirStr = dirPtr ? dirPtr->as_string().wide() : L"";
Expand Down Expand Up @@ -180,33 +184,48 @@ int launcher_main(PCWSTR args, int cmdShow) noexcept try
powershellScriptRunner.RunEndingScript();
Log("Process Launch complete.");
}
LARGE_INTEGER psfLoad_endCounter, frequency;
QueryPerformanceFrequency(&frequency);
QueryPerformanceCounter(&psfLoad_endCounter);
double elapsedTime = (psfLoad_endCounter.QuadPart - psfLoad_startCounter.QuadPart) / (double)frequency.QuadPart;

psf::TraceLogPerformance(currentExeFixes,elapsedTime);

TraceLoggingUnregister(g_Log_ETW_ComponentProvider);
return 0;
}
catch (...)
{
::PSFReportError(widen(message_from_caught_exception()).c_str());
psf::TraceLogExceptions("PSFLauncherException", widen(message_from_caught_exception()).c_str());;
return win32_from_caught_exception();
}

void GetAndLaunchMonitor(const psf::json_object& monitor, std::filesystem::path packageRoot, int cmdShow, LPCWSTR dirStr)
{
std::wstringstream traceDataStream;
traceDataStream << " config:\n";
bool asAdmin = false;
bool wait = false;
auto monitorExecutable = monitor.try_get("executable");
traceDataStream << " executable: " << monitorExecutable->as_string().wide() << " ;";
auto monitorArguments = monitor.try_get("arguments");
traceDataStream << " arguments: " << monitorArguments->as_string().wide() << " ;";
auto monitorAsAdmin = monitor.try_get("asadmin");
auto monitorWait = monitor.try_get("wait");
if (monitorAsAdmin)
{
asAdmin = monitorAsAdmin->as_boolean().get();
}
traceDataStream << " asadmin: " << (asAdmin ? "true" : "false") << " ;";

if (monitorWait)
{
wait = monitorWait->as_boolean().get();
}
traceDataStream << " wait: " << (wait ? "true" : "false") << " ;";

psf::TraceLogPSFMonitorConfigData(traceDataStream.str().c_str());
Log("\tCreating the monitor: %ls", monitorExecutable->as_string().wide());
LaunchMonitorInBackground(packageRoot, monitorExecutable->as_string().wide(), monitorArguments->as_string().wide(), wait, asAdmin, cmdShow, dirStr);
}
Expand Down Expand Up @@ -303,58 +322,6 @@ static inline bool check_suffix_if(iwstring_view str, iwstring_view suffix) noex
return ((str.length() >= suffix.length()) && (str.substr(str.length() - suffix.length()) == suffix));
}

void LogApplicationAndProcessesCollection()
{
auto configRoot = PSFQueryConfigRoot();

if (auto applications = configRoot->as_object().try_get("applications"))
{
for (auto& applicationsConfig : applications->as_array())
{
auto exeStr = applicationsConfig.as_object().try_get("executable")->as_string().wide();
auto idStr = applicationsConfig.as_object().try_get("id")->as_string().wide();
TraceLoggingWrite(
g_Log_ETW_ComponentProvider,
"ApplicationsConfigdata",
TraceLoggingWideString(exeStr, "applications_executable"),
TraceLoggingWideString(idStr, "applications_id"),
TraceLoggingBoolean(TRUE, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA));
}
}

if (auto processes = configRoot->as_object().try_get("processes"))
{
for (auto& processConfig : processes->as_array())
{
auto exeStr = processConfig.as_object().get("executable").as_string().wide();
TraceLoggingWrite(
g_Log_ETW_ComponentProvider,
"ProcessesExecutableConfigdata",
TraceLoggingWideString(exeStr, "processes_executable"),
TraceLoggingBoolean(TRUE, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA));

if (auto fixups = processConfig.as_object().try_get("fixups"))
{
for (auto& fixupConfig : fixups->as_array())
{
auto dllStr = fixupConfig.as_object().try_get("dll")->as_string().wide();
TraceLoggingWrite(
g_Log_ETW_ComponentProvider,
"ProcessesFixUpConfigdata",
TraceLoggingWideString(dllStr, "processes_fixups"),
TraceLoggingBoolean(TRUE, "UTCReplace_AppSessionGuid"),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA));
}
}
}
}
}

bool IsCurrentOSRS2OrGreater()
{
OSVERSIONINFOEXW osvi = { sizeof(osvi), 0, 0, 0, 0, {0}, 0, 0 };
Expand Down
11 changes: 8 additions & 3 deletions PsfRuntime/ArgRedirection.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -66,7 +66,7 @@ bool IsUnderUserAppDataAndReplace(const CharT* fileName, CharT* cmdLine, bool Ap

// checks each space separated command line parameter and changes from native local app data folder to per user per app data folder if the file referred in command line parameter is present in per user per app data folder, else it remains the same
template <typename CharT>
void convertCmdLineParameters(CharT* inputCmdLine, CharT* cnvtCmdLine)
bool convertCmdLineParameters(CharT* inputCmdLine, CharT* cnvtCmdLine)
{
CharT* next_token;
size_t cmdLinelen = strlenImpl(inputCmdLine);
Expand All @@ -79,12 +79,13 @@ void convertCmdLineParameters(CharT* inputCmdLine, CharT* cnvtCmdLine)
else
{
strcatImpl(cnvtCmdLine, MAX_CMDLINE_PATH, inputCmdLine);
return;
return false;
}

CharT* token = strtokImpl(cmdLine.get(), (CharT*)L" ", &next_token);
bool redirectResult = false;
size_t remBufSize;
bool isCmdLineRedirected = false;

while (token != nullptr)
{
Expand All @@ -99,12 +100,16 @@ void convertCmdLineParameters(CharT* inputCmdLine, CharT* cnvtCmdLine)
remBufSize = MAX_CMDLINE_PATH - strlenImpl(cnvtCmdLine);
strcatImpl(cnvtCmdLine, remBufSize, token);
}
else
{
isCmdLineRedirected = true;
}
token = strtokImpl((CharT*)nullptr, (CharT*)L" ", &next_token);
if (token != nullptr)
{
remBufSize = MAX_CMDLINE_PATH - strlenImpl(cnvtCmdLine);
strcatImpl(cnvtCmdLine, remBufSize, (CharT*)L" ");
}
}
return;
return isCmdLineRedirected;
}
11 changes: 9 additions & 2 deletions PsfRuntime/Config.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@

#include "Config.h"
#include "JsonConfig.h"
#include "psf_tracelogging.h"

using namespace std::literals;

Expand Down Expand Up @@ -294,6 +295,7 @@ void load_json()
catch (...)
{
Log("Non-fatal error enumerating directories while looking for config.json.");
psf::TraceLogExceptions("PSFConfigException", L"Non-fatal error enumerating directories while looking for config.json.");
}
}
}
Expand Down Expand Up @@ -321,10 +323,12 @@ void load_json()
msgStream << "Error: " << g_JsonHandler.error_message << "\n";
}
msgStream << "File Offest: " << result.Offset();
psf::TraceLogExceptions("PSFConfigException", msgStream.str().c_str());
throw std::runtime_error(msgStream.str());
}
else if (!g_JsonHandler.root)
{
psf::TraceLogExceptions("PSFConfigException", "config.json has no contents");
throw std::runtime_error("config.json has no contents");
}

Expand Down Expand Up @@ -497,11 +501,12 @@ PSFAPI const psf::json_object* __stdcall PSFQueryAppLaunchConfig(_In_ const wcha
{
Log("\tNo Matches");
}

psf::TraceLogExceptions("PSFConfigException", (L"No matching app config found for appId " + std::wstring(applicationId)).c_str());
return nullptr;
}
catch (...)
{
psf::TraceLogExceptions("PSFConfigException", (L"PSFQueryAppLaunchConfig Exception " + std::wstring(applicationId)).c_str());
return nullptr;
}

Expand Down Expand Up @@ -578,11 +583,11 @@ PSFAPI const psf::json_object* __stdcall PSFQueryExeConfig(const wchar_t* execut
}
}
}

return nullptr;
}
catch (...)
{
psf::TraceLogExceptions("PSFConfigException", (L"PSFQueryExeConfig Exception " + std::wstring(executable)).c_str());
return nullptr;
}

Expand Down Expand Up @@ -629,6 +634,7 @@ PSFAPI const psf::json_value* __stdcall PSFQueryConfig(const wchar_t* executable
}
catch (...)
{
psf::TraceLogExceptions("PSFConfigException", (L"PSFQueryConfig failed. executable: " + std::wstring(executable) + L"dll: " + std::wstring(dll)).c_str());
return nullptr;
}

Expand All @@ -638,6 +644,7 @@ PSFAPI const psf::json_value* __stdcall PSFQueryDllConfig(const wchar_t* dll) no
}
catch (...)
{
psf::TraceLogExceptions("PSFConfigException", (L"PSFQueryConfig failed. dll: " + std::wstring(dll)).c_str());
return nullptr;
}

Expand Down
10 changes: 9 additions & 1 deletion PsfRuntime/CreateProcessHook.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@

#include "Config.h"
#include "ArgRedirection.h"
#include "psf_tracelogging.h"

using namespace std::literals;

Expand Down Expand Up @@ -166,7 +167,11 @@ BOOL WINAPI CreateProcessFixup(
{
// Redirect createProcess arguments if any in native app data to per user per app data
memset(cnvtCmdLine.get(), 0, MAX_CMDLINE_PATH);
convertCmdLineParameters(commandLine, cnvtCmdLine.get());
bool cmdLineConverted = convertCmdLineParameters(commandLine, cnvtCmdLine.get());
if (cmdLineConverted == true)
{
psf::TraceLogArgumentRedirection(commandLine, cnvtCmdLine.get());
}
}

if (!CreateProcessImpl(
Expand All @@ -181,6 +186,7 @@ BOOL WINAPI CreateProcessFixup(
startupInfo,
processInformation))
{
psf::TraceLogExceptions("PSFRuntimeException", "Create Process failure");
return FALSE;
}

Expand Down Expand Up @@ -301,6 +307,7 @@ BOOL WINAPI CreateProcessFixup(
}
catch (...)
{
psf::TraceLogExceptions("PSFRuntimeException", "Non-fatal error enumerating directories while looking for PsfRuntime");
Log("Non-fatal error enumerating directories while looking for PsfRuntime.");
}
}
Expand Down Expand Up @@ -354,6 +361,7 @@ BOOL WINAPI CreateProcessFixup(
catch (...)
{
::SetLastError(win32_from_caught_exception());
psf::TraceLogExceptions("PSFRuntimeException", "Create Process Hook failure");
return FALSE;
}

Expand Down
Loading

0 comments on commit c4daede

Please sign in to comment.