Стандартная библиотека Visual Studio 2015 и телеметрия

Преамбула

Программы на C и C++, как правило, проводят бо́льшую часть своей жизни внутри функции main() и функций, прямо или косвенно вызываемых из main(). Тем не менее, на самом деле выполнение программы начинается вовсе не с main(), а с некоторого кода из стандартной библиотеки, поставляемой вместе с компилятором. Таковой код, по идее, должен подготавливать окружение для других функций стандартной библиотеки, которые, возможно, позовёт main(), а также параметры самой main() (под Windows; Unix-системы имеют тенденцию передавать argc/argv/envp в подготовленном виде прямо при запуске процесса, но речь не о них). Симметрично, завершающий return в функции main() — вовсе не последняя инструкция программы, после него следует ещё немного кода из стандартной библиотеки.
В Visual Studio «настоящая» точка входа в программу называется mainCRTStartup. В комплекте с VS идут исходники стандартной библиотеки, в VS2015 определение mainCRTStartup находится в %PROGRAMFILES(X86)%VCcrtsrcvcruntimeexe_main.cpp, но, впрочем, всю работу выполняет exe_common.inl рядом. Давайте туда посмотрим.

...
        // If this module has any thread-local destructors, register the
        // callback function with the Unified CRT to run on exit.
        _tls_callback_type const * const tls_dtor_callback = __scrt_get_dyn_tls_dtor_callback();
        if (*tls_dtor_callback != nullptr && __scrt_is_nonwritable_in_current_image(tls_dtor_callback))
        {
            _register_thread_local_exe_atexit_callback(*tls_dtor_callback);
        }

        __telemetry_main_invoke_trigger(nullptr);

        //
        // Initialization is complete; invoke main...
        //

        int const main_result = invoke_main();

        //
        // main has returned; exit somehow...
        //

        __telemetry_main_return_trigger(nullptr);

        if (!__scrt_is_managed_app())
            exit(main_result);

        if (!has_cctor)
            _cexit();

        // Finally, we terminate the CRT:
        __scrt_uninitialize_crt(true, false);
        return main_result;
...

Идём глубже

Опытные параноики, несомненно, уже обратили внимание на вызовы __telemetry_main_invoke_trigger и __telemetry_main_return_trigger. Попробуем найти их исходники… а фигушки. При попытке зайти внутрь этих функций отладчик VS сообщает «telemetry.cpp не найден» (значит, файл с исходниками, который MS «забыла» включить в поставку, называется telemetry.cpp. Логично) и предлагает либо указать путь вручную, либо перейти к дизассемблированному коду.
Внимательный поиск других функций из telemetry.cpp находит ещё пару функций __vcrt_initialize_telemetry_provider и __vcrt_uninitialize_telemetry_provider, вызываемых в ходе, соответственно, инициализации и завершения.

Конечно, непредоставление исходников ещё не означает невозможности заглянуть внутрь. Разглядывание дизассемблированного кода приводит к переменной _Microsoft_CRTProvider типа const __vcrt_trace_logging_provider::_TlgProvider_t* const, а тип _TlgProvider_t уже не секретный и легко находится в SDK: %PROGRAMFILES(X86)%Windows Kits10Include10.0.10586.0sharedTraceLoggingProvider.h… а вот и документация ^[1]. (В документации написано «Windows 10», что, впрочем, совершенно не мешает коду работать под Windows 7.) Так, хорошо, а куда оно пишет все эти логи?

TraceLogging events are sent to ETW as described in this section.

То есть это очередная инкарнация подсистемы Event Tracing for Windows ^[2]. Ага.
Краткая справка для тех, кто впервые слышит аббревиатуру ETW: это инфраструктура для унифицированной обработки всевозможных логов и счётчиков, появившаяся ещё в Windows 2000 и получившая серьёзную прибавку в Vista. Желающие могут набрать в командной строке logman query providers для оценки масштаба.

Смотрим логи

Возьмём какую-нибудь простенькую программу, например:

#include <stdio.h>
int main()
{
	printf("Hello, World!n");
	return 0;
}

Результат компиляции командой cl /Os hello.c: yadi.sk/d/pa0S5qVoqw9Q4 ^[3]
Итак, в скомпилированном exe-шнике должна быть запись каких-то логов перед и после вызова main(). Подсистема ETW просто отбрасывает всё, для чего не было команды на ведение логов. Давайте включим логи: именем администратора,

logman create trace test_crt_telemetry -p {5EEC90AB-C022-44B2-A5DD-FD716A222A15} -o C:temptest_telemetry
logman start test_crt_telemetry

(logman и нужная далее tracerpt — стандартные утилиты из поставки Windows). Откуда я взял {5EEC90AB-C022-44B2-A5DD-FD716A222A15}? Отладчик VS показал при просмотре уже упоминавшейся переменной _Microsoft_CRTProvider.
Запускаем hello.exe, видим классическое приветствие. Сбрасываем логи в файл,

logman stop test_crt_telemetry

и смотрим, что туда записалось:

tracerpt -summary summary.txt -o dumpfile.xml C:temptest_telemetry_000001.etl

<Events>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="Microsoft.CRTProvider" Guid="{5eec90ab-c022-44b2-a5dd-fd716a222a15}" />
		<EventID>17</EventID>
		<Version>0</Version>
		<Level>5</Level>
		<Task>0</Task>
		<Opcode>0</Opcode>
		<Keywords>0x200000000000</Keywords>
		<TimeCreated SystemTime="2016-04-11T00:57:29.437589800Z" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="7656" ThreadID="5796" ProcessorID="0" KernelTime="0" UserTime="0" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:temphello.exe</Data>
	</EventData>
	<RenderingInfo Culture="ru-RU">
		<Task>InvokeMainViaCRT</Task>
	</RenderingInfo>
</Event>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="Microsoft.CRTProvider" Guid="{5eec90ab-c022-44b2-a5dd-fd716a222a15}" />
		<EventID>77</EventID>
		<Version>0</Version>
		<Level>5</Level>
		<Task>0</Task>
		<Opcode>0</Opcode>
		<Keywords>0x200000000000</Keywords>
		<TimeCreated SystemTime="2016-04-11T00:57:29.437734300Z" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="7656" ThreadID="5796" ProcessorID="0" KernelTime="0" UserTime="0" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:temphello.exe</Data>
	</EventData>
	<RenderingInfo Culture="ru-RU">
		<Task>ExitMainViaCRT</Task>
	</RenderingInfo>
</Event>

Да, логи есть. Данных, впрочем, не особенно много: помимо собственно сообщения о вызове/возврате main() и стандартных заголовков ETW, пишется только имя exe-шника.

Кстати, а если оставить запись логов включённой и поработать? Можно поймать, например,

	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:Program FilesPython 3.5python35.dll</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Invoked.&quot;">Main Invoked.</Data>
		<Data Name="FileName">C:Program FilesPython 3.5python.exe</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:Program FilesPython 3.5python.exe</Data>
	</EventData>
	<EventData>
		<Data Name="&quot;Main Returned.&quot;">Main Returned.</Data>
		<Data Name="FileName">C:Program FilesPython 3.5python35.dll</Data>
	</EventData>

Python идёт в ногу с прогрессом!Пардон, Python 3 идёт в ногу с прогрессом!

Don't panic

Что мы имеем в итоге?

• В любом бинарнике, скомпилированном VS2015 из программы на C или C++, есть код, который может писать логи. (зануда-mode: если не предпринимать специальных усилий по отключению стандартной библиотеки. Впрочем, если на Си ещё можно писать без неё, то на C++ — только до первого исключения)
• Логи куцые, там нет ничего особенно интересного, что система и без того бы не знала. Можно различить случаи "main() штатно вернула управление" и «кто-то вызвал exit или abort», но это скорее интересно разработчику для отладки. Параноики могут расслабиться.
• Но сам прецедент интересный.
• По умолчанию логи никуда не пишутся. Их нужно включать специально. Однако, команда включения может вообще ничего не знать ни о программе, ни о предметной области (ни logman, ни tracerpt не в курсе о конкретном Microsoft.CRTProvider — вся структура логов выше пишется вместе с логами).
• Проверить, включены ли логи, можно следующим кодом:

  #include <Windows.h>
  #include <evntprov.h>
  
  static void NTAPI EnableCallback(LPCGUID, ULONG isEnabled, UCHAR, ULONGLONG, ULONGLONG, PEVENT_FILTER_DESCRIPTOR, PVOID context)
  {
  	*(bool*)context = (bool)isEnabled;
  }
  
  int main()
  {
  	static const GUID providerId = { 0x5eec90ab, 0xc022, 0x44b2, 0xa5, 0xdd, 0xfd, 0x71, 0x6a, 0x22, 0x2a, 0x15 };
  	REGHANDLE hProvider;
  	bool enabled = false;
  	EventRegister(&providerId, &EnableCallback, &enabled, &hProvider);
  	EventUnregister(hProvider);
  	printf("Microsoft.CRTProvider logging is %sn", enabled ? "on" : "off");
  	return 0;
  }

  (под XP работать не будет в силу отсутствия необходимых API. Впрочем, по ровно той же причине логгинг под XP всегда отключён. exe-шник для ленивых: yadi.sk/d/pvQkFUqKqwJSV ^[4])

• Такие логи логичнее всего было бы использовать как вспомогательное средство отладки. Но сам по себе запуск под отладчиком не включает логи. Конечно, не исключено, что какой-нибудь флажок в настройках включает функциональность, которой нужны логи… или логи нужны для какой-нибудь хитрой отладочной утилиты… но тогда непонятно, почему код остаётся при компиляции с релизной библиотекой.

Автор: grechnik

Источник ^[5]