Преамбула
Программы на 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
… а вот и документация. (В документации написано «Windows 10», что, впрочем, совершенно не мешает коду работать под Windows 7.) Так, хорошо, а куда оно пишет все эти логи?
TraceLogging events are sent to ETW as described in this section.
То есть это очередная инкарнация подсистемы Event Tracing for Windows. Ага.
Краткая справка для тех, кто впервые слышит аббревиатуру 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
Итак, в скомпилированном 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=""Main Invoked."">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=""Main Returned."">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=""Main Invoked."">Main Invoked.</Data>
<Data Name="FileName">C:Program FilesPython 3.5python35.dll</Data>
</EventData>
<EventData>
<Data Name=""Main Invoked."">Main Invoked.</Data>
<Data Name="FileName">C:Program FilesPython 3.5python.exe</Data>
</EventData>
<EventData>
<Data Name=""Main Returned."">Main Returned.</Data>
<Data Name="FileName">C:Program FilesPython 3.5python.exe</Data>
</EventData>
<EventData>
<Data Name=""Main Returned."">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)
- Такие логи логичнее всего было бы использовать как вспомогательное средство отладки. Но сам по себе запуск под отладчиком не включает логи. Конечно, не исключено, что какой-нибудь флажок в настройках включает функциональность, которой нужны логи… или логи нужны для какой-нибудь хитрой отладочной утилиты… но тогда непонятно, почему код остаётся при компиляции с релизной библиотекой.
Автор: grechnik