From c9b8dc13fd53b24fb688bcc118ea0d400207a581 Mon Sep 17 00:00:00 2001 From: Jake Stine Date: Mon, 4 Jan 2021 07:09:42 -0800 Subject: [PATCH 1/2] Console: Fix problems when using CLI from MSYS2/GitBash/ConEmu - Fix issue where console output is lost when running from MSYS2/GitBash CLI - Fix issue where pipe redirections would be overridden and otuput would always go to the attached console (this affected windows cmd prompt as well as other shell CLIs) - Simplify some logic regarding registering of the standard output writer --- src/common/log.cpp | 295 +++++++++++++++++++++++++++++++-------------- 1 file changed, 206 insertions(+), 89 deletions(-) diff --git a/src/common/log.cpp b/src/common/log.cpp index 734a8e55f..cc904534d 100644 --- a/src/common/log.cpp +++ b/src/common/log.cpp @@ -129,9 +129,138 @@ static void FormatLogMessageForDisplay(const char* channelName, const char* func printCallback(message, pCallbackUserData); } -#if defined(WIN32) +#if defined(_WIN32) +// Windows obscures access to POSIX style write() and file handles. +#include +#define STDOUT_FILENO (_fileno(stdout)) +#define STDERR_FILENO (_fileno(stderr)) +#define write(fd, buf,count) _write(fd,buf,(int)count) +#endif -static void ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, +static void StandardOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, + LOGLEVEL level, const char* message) +{ + static const char* const colorCodes[LOGLEVEL_COUNT] = { + "\033[0m", // NONE + "\033[1;31m", // ERROR + "\033[1;33m", // WARNING + "\033[1;35m", // PERF + "\033[1;37m", // INFO + "\033[1;32m", // VERBOSE + "\033[0;37m", // DEV + "\033[1;36m", // PROFILE + "\033[0;32m", // DEBUG + "\033[0;34m", // TRACE + }; + + if (int outputFd = (level <= LOGLEVEL_WARNING) ? STDERR_FILENO : STDOUT_FILENO; outputFd >= 0) { + write(outputFd, colorCodes[level], std::strlen(colorCodes[level])); + + Log::FormatLogMessageForDisplay( + channelName, functionName, level, message, + [](const char* text, void* outputFd) { write((int)(intptr_t)outputFd, text, std::strlen(text)); }, + (void*)(intptr_t)outputFd); + + write(outputFd, colorCodes[0], std::strlen(colorCodes[0])); + write(outputFd, "\n", 1); + } +} + + +#if defined(_WIN32) +static bool s_msw_console_allocated = false; +static HANDLE s_msw_prev_stdin = {}; +static HANDLE s_msw_prev_stdout = {}; +static HANDLE s_msw_prev_stderr = {}; + +#include + +void msw_ReopenStandardPipes() +{ + if (s_msw_console_allocated) + return; + + s_msw_console_allocated = true; + + // By affecting only unbound pipes, it allows the program to accept input from stdin or honor + // tee of stdout/stderr. Typical use case from GitBash terminal is to use `tee` to filter and pipe + // several different levels of trace into various files, all very neat and fast and not requiring + // any modification to the emulator beyond allowing for basic standard pipe redirection to work in + // the way it was designed to work over 40 yrs ago. + + // open outputs as binary to suppress Windows newline corruption (\r mess) + std::FILE* fp; + if (!s_msw_prev_stdin ) { freopen_s(&fp, "CONIN$", "r" , stdin ); } + if (!s_msw_prev_stdout ) { freopen_s(&fp, "CONOUT$", "wb", stdout); } + if (!s_msw_prev_stderr ) { freopen_s(&fp, "CONOUT$", "wb", stderr); } + + // Windows Console Oddities - The only way to get windows built-in console is to render UTF chars from + // the correct alt. fonts is to set either _O_U8TEXT or _O_U16TEXT. However, this imposes a requirement + // that we must write UTF16 to the console using widechar versions of printf and friends (eg, wprintf)... + // EVEN IF YOU WANT TO USE UTF8. Worse, printf() doesn't do the smart thing and assume UTF8 and then + // convert it to UTF16 for us when the output file is in U16TEXT mode. Nope! It throws an ASSERTION and + // forces us to call wprintf, which makes this all totally useless and not cross-platform. + + // Lesson: if you want nice UTF font display in your console window, don't use Windows Console. + // Use mintty or conemu instead. + + //_setmode(_fileno(stdout), _O_U8TEXT); + //_setmode(_fileno(stderr), _O_U8TEXT); +} + +void msw_FreeLegacyConsole() +{ + if (!s_msw_console_allocated) + return; + + s_msw_console_allocated = false; + + // restore previous handles prior to creating the console. + ::SetStdHandle(STD_INPUT_HANDLE , s_msw_prev_stdin ); + ::SetStdHandle(STD_OUTPUT_HANDLE, s_msw_prev_stdout); + ::SetStdHandle(STD_ERROR_HANDLE , s_msw_prev_stderr); + + ::FreeConsole(); +} + +bool msw_AttachLegacyConsole() +{ + if (::AttachConsole(ATTACH_PARENT_PROCESS)) + return true; + + // ERROR_ACCESS_DENIED means a windows Console is already attached. + if (auto err = ::GetLastError(); err == ERROR_ACCESS_DENIED) { + return true; + } + return false; +} + +// Creates an old-fashioned console window. +bool msw_AllocLegacyConsole() +{ + // A potentially fancy solution which I haven't had time to experiment with yet is to spawn our own + // terminal application and bind our standard pipes to it, instead of using AllocConsole(). This would + // allow binding to any number of more modern terminal/console apps, all of which handle UTF8 better + // than the windows legacy console (but would also depend on the user having them installed and PATH + // accessible, so definitely not without annoying caveats) --jstine + + if (!::AllocConsole()) { + // Console could fail to allocate on an Appveyor/Jenkins environment, for example, because + // when being run as a service the console may be unable to bind itself to a user login session. + // It may also fail if a console is already allocated <-- this is a problem since in this case + // we still want to set + + if (auto err = ::GetLastError(); err == ERROR_ACCESS_DENIED) { + // ERROR_ACCESS_DENIED means a windows Console is already attached. + // whatever the console is, who knows, so let's early-out, and not mess with its font settings. + return true; + } + } + + return true; +} + +static void msw_ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { if (!s_consoleOutputEnabled || level > s_consoleOutputLevelFilter || @@ -179,7 +308,7 @@ static void ConsoleOutputLogCallback(void* pUserParam, const char* channelName, } } -static void DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, +static void msw_DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { if (!s_debugOutputEnabled || level > s_debugOutputLevelFilter || s_debugOutputChannelFilter.Find(channelName) >= 0) @@ -190,15 +319,10 @@ static void DebugOutputLogCallback(void* pUserParam, const char* channelName, co OutputDebugStringA("\n"); } +#endif -#elif defined(__ANDROID__) - -static void ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, - LOGLEVEL level, const char* message) -{ -} - -static void DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, +#if defined(__ANDROID__) +static void android_DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { if (!s_debugOutputEnabled || level > s_debugOutputLevelFilter || s_debugOutputChannelFilter.Find(functionName) >= 0) @@ -219,103 +343,96 @@ static void DebugOutputLogCallback(void* pUserParam, const char* channelName, co __android_log_write(logPriority[level], channelName, message); } +#endif -#else - -static void ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, +static void PlatformStandardOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { +#if defined(__ANDROID__) + return; +#endif + if (!s_consoleOutputEnabled || level > s_consoleOutputLevelFilter || s_consoleOutputChannelFilter.Find(channelName) >= 0) return; - static const char* colorCodes[LOGLEVEL_COUNT] = { - "\033[0m", // NONE - "\033[1;31m", // ERROR - "\033[1;33m", // WARNING - "\033[1;35m", // PERF - "\033[1;37m", // INFO - "\033[1;32m", // VERBOSE - "\033[0;37m", // DEV - "\033[1;36m", // PROFILE - "\033[0;32m", // DEBUG - "\033[0;34m", // TRACE - }; - - int outputFd = (level <= LOGLEVEL_WARNING) ? STDERR_FILENO : STDOUT_FILENO; - - write(outputFd, colorCodes[level], std::strlen(colorCodes[level])); - - Log::FormatLogMessageForDisplay( - channelName, functionName, level, message, - [](const char* text, void* outputFd) { write((int)(intptr_t)outputFd, text, std::strlen(text)); }, - (void*)(intptr_t)outputFd); - - write(outputFd, colorCodes[0], std::strlen(colorCodes[0])); - write(outputFd, "\n", 1); +#if defined(_WIN32) + if (s_msw_console_allocated) { + msw_ConsoleOutputLogCallback(pUserParam, channelName, functionName, level, message); + } + else { + StandardOutputLogCallback(pUserParam, channelName, functionName, level, message); + } +#endif } static void DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { +#if defined(_WIN32) + msw_DebugOutputLogCallback(pUserParam, channelName, functionName, level, message); +#endif + +#if defined(__ANDROID__) + android_DebugOutputLogCallback(pUserParam, channelName, functionName, level, message); +#endif } -#endif void SetConsoleOutputParams(bool Enabled, const char* ChannelFilter, LOGLEVEL LevelFilter) { - if (s_consoleOutputEnabled != Enabled) - { - s_consoleOutputEnabled = Enabled; - if (Enabled) - RegisterCallback(ConsoleOutputLogCallback, NULL); - else - UnregisterCallback(ConsoleOutputLogCallback, NULL); - -#if defined(WIN32) - // On windows, no console is allocated by default on a windows based application - static bool console_was_allocated = false; - static std::FILE* stdin_fp = nullptr; - static std::FILE* stdout_fp = nullptr; - static std::FILE* stderr_fp = nullptr; - if (Enabled) - { - if (GetConsoleWindow() == NULL) - { - DebugAssert(!console_was_allocated); - - // Attach to the parent console if we're running from a command window - if (!AttachConsole(ATTACH_PARENT_PROCESS)) - { - if (!AllocConsole()) - return; - } - - console_was_allocated = true; - - std::FILE* fp; - freopen_s(&fp, "CONIN$", "r", stdin); - freopen_s(&fp, "CONOUT$", "w", stdout); - freopen_s(&fp, "CONOUT$", "w", stderr); - } - } - else - { - if (console_was_allocated) - { - std::FILE* fp; - freopen_s(&fp, "NUL:", "w", stderr); - freopen_s(&fp, "NUL:", "w", stdout); - freopen_s(&fp, "NUL:", "w", stdin); - FreeConsole(); - console_was_allocated = false; - } - } -#endif - } - s_consoleOutputChannelFilter = (ChannelFilter != NULL) ? ChannelFilter : ""; s_consoleOutputLevelFilter = LevelFilter; + + if (s_consoleOutputEnabled == Enabled) + return; + + s_consoleOutputEnabled = Enabled; + + if (Enabled) + RegisterCallback(PlatformStandardOutputLogCallback, NULL); + else + UnregisterCallback(PlatformStandardOutputLogCallback, NULL); + +#if defined(WIN32) + if (Enabled) { + // Windows Console behavior is very tricky, and depends on: + // - Whether the application is built with defined(_CONSOLE) or not. + // - Whether the application is started via a Microsoft shell (Cmd.exe) or a Unix'y shell + // (MSYS2, Git Bash, ConEum, ConsoleX, etc) + // - The instance of the MSVCRT currently in-use, which depends on whether the code is run + // from a DLL and whether that DLL was linked with static or dynamic CRT runtimes. + // - if the DLL uses dynamic CRT, then behavior also depends on whether that dynamic CRT version + // matches the one used by the main program. + // + // To maintain some level of personal sanity, I'll disregard all the DLL/CRT caveats for now. + // + // Microsoft CMD.EXE "does us a favor" and DETACHES the standard console pipes when it spawns + // windowed applications, but only if redirections are not specified at the command line. + // This creates all kinds of confusion and havok that could easy fill pages of the screen with + // comments. The TL;DR version is: + // - only call AllocConsole() if the stdout/stderr pipes are DETACHED (null) - this avoids + // clobbering pipe redirections specified from any shell (cmd/bash) and avoids creating + // spurious console windows when running from MSYS/ConEmu/GitBash. + // - Only use Microsoft's over-engineered Console text-coloring APIs if we called AllocConsole, + // because those APIs result in a whole lot of black screen if you call them while attached to + // a terminal app (ConEmu, ConsoleX, etc). + + s_msw_prev_stdin = ::GetStdHandle(STD_INPUT_HANDLE ); + s_msw_prev_stdout = ::GetStdHandle(STD_OUTPUT_HANDLE); + s_msw_prev_stderr = ::GetStdHandle(STD_ERROR_HANDLE ); + + if (!s_msw_prev_stdout || !s_msw_prev_stdin) { + if (msw_AttachLegacyConsole() || msw_AllocLegacyConsole()) { + msw_ReopenStandardPipes(); + } + } + } + else + { + msw_FreeLegacyConsole(); + } +#endif } void SetDebugOutputParams(bool enabled, const char* channelFilter /* = nullptr */, From f26b094cf75a2c2aa24deb45d60c8e4e49f442d7 Mon Sep 17 00:00:00 2001 From: Jake Stine Date: Thu, 7 Jan 2021 07:05:33 -0800 Subject: [PATCH 2/2] Console: Use ANSI escape codes and remove entirely Win32's legacy WriteConsoleA code. Also fixes android build failure (missing unistd.h) --- src/common/log.cpp | 114 +++++++++++---------------------------------- 1 file changed, 26 insertions(+), 88 deletions(-) diff --git a/src/common/log.cpp b/src/common/log.cpp index cc904534d..bdce4b590 100644 --- a/src/common/log.cpp +++ b/src/common/log.cpp @@ -11,6 +11,7 @@ #include "windows_headers.h" #elif defined(__ANDROID__) #include +#include #else #include #endif @@ -140,6 +141,10 @@ static void FormatLogMessageForDisplay(const char* channelName, const char* func static void StandardOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { + if (!s_consoleOutputEnabled || level > s_consoleOutputLevelFilter || + s_consoleOutputChannelFilter.Find(channelName) >= 0) + return; + static const char* const colorCodes[LOGLEVEL_COUNT] = { "\033[0m", // NONE "\033[1;31m", // ERROR @@ -260,60 +265,9 @@ bool msw_AllocLegacyConsole() return true; } -static void msw_ConsoleOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, - LOGLEVEL level, const char* message) -{ - if (!s_consoleOutputEnabled || level > s_consoleOutputLevelFilter || - s_consoleOutputChannelFilter.Find(channelName) >= 0) - return; - - if (level > LOGLEVEL_COUNT) - level = LOGLEVEL_TRACE; - - HANDLE hConsole = GetStdHandle((level <= LOGLEVEL_WARNING) ? STD_ERROR_HANDLE : STD_OUTPUT_HANDLE); - if (hConsole != INVALID_HANDLE_VALUE) - { - static const WORD levelColors[LOGLEVEL_COUNT] = { - FOREGROUND_RED | FOREGROUND_BLUE | FOREGROUND_GREEN, // NONE - FOREGROUND_RED | FOREGROUND_INTENSITY, // ERROR - FOREGROUND_RED | FOREGROUND_GREEN | FOREGROUND_INTENSITY, // WARNING - FOREGROUND_RED | FOREGROUND_BLUE | FOREGROUND_INTENSITY, // PERF - FOREGROUND_RED | FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_INTENSITY, // INFO - FOREGROUND_GREEN | FOREGROUND_INTENSITY, // VERBOSE - FOREGROUND_RED | FOREGROUND_BLUE | FOREGROUND_GREEN, // DEV - FOREGROUND_BLUE | FOREGROUND_GREEN | FOREGROUND_INTENSITY, // PROFILE - FOREGROUND_GREEN, // DEBUG - FOREGROUND_BLUE, // TRACE - }; - - CONSOLE_SCREEN_BUFFER_INFO oldConsoleScreenBufferInfo; - GetConsoleScreenBufferInfo(hConsole, &oldConsoleScreenBufferInfo); - SetConsoleTextAttribute(hConsole, levelColors[level]); - - // write message in the formatted way - FormatLogMessageForDisplay( - channelName, functionName, level, message, - [](const char* text, void* hConsole) { - DWORD written; - WriteConsoleA(static_cast(hConsole), text, static_cast(std::strlen(text)), &written, nullptr); - }, - (void*)hConsole); - - // write newline - DWORD written; - WriteConsoleA(hConsole, "\r\n", 2, &written, nullptr); - - // restore color - SetConsoleTextAttribute(hConsole, oldConsoleScreenBufferInfo.wAttributes); - } -} - static void msw_DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { - if (!s_debugOutputEnabled || level > s_debugOutputLevelFilter || s_debugOutputChannelFilter.Find(channelName) >= 0) - return; - FormatLogMessageForDisplay( channelName, functionName, level, message, [](const char* text, void*) { OutputDebugStringA(text); }, nullptr); @@ -325,9 +279,6 @@ static void msw_DebugOutputLogCallback(void* pUserParam, const char* channelName static void android_DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { - if (!s_debugOutputEnabled || level > s_debugOutputLevelFilter || s_debugOutputChannelFilter.Find(functionName) >= 0) - return; - static const int logPriority[LOGLEVEL_COUNT] = { ANDROID_LOG_INFO, // NONE ANDROID_LOG_ERROR, // ERROR @@ -345,30 +296,12 @@ static void android_DebugOutputLogCallback(void* pUserParam, const char* channel } #endif -static void PlatformStandardOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, - LOGLEVEL level, const char* message) -{ -#if defined(__ANDROID__) - return; -#endif - - if (!s_consoleOutputEnabled || level > s_consoleOutputLevelFilter || - s_consoleOutputChannelFilter.Find(channelName) >= 0) - return; - -#if defined(_WIN32) - if (s_msw_console_allocated) { - msw_ConsoleOutputLogCallback(pUserParam, channelName, functionName, level, message); - } - else { - StandardOutputLogCallback(pUserParam, channelName, functionName, level, message); - } -#endif -} - static void DebugOutputLogCallback(void* pUserParam, const char* channelName, const char* functionName, LOGLEVEL level, const char* message) { + if (!s_debugOutputEnabled || level > s_debugOutputLevelFilter || s_debugOutputChannelFilter.Find(channelName) >= 0) + return; + #if defined(_WIN32) msw_DebugOutputLogCallback(pUserParam, channelName, functionName, level, message); #endif @@ -390,11 +323,11 @@ void SetConsoleOutputParams(bool Enabled, const char* ChannelFilter, LOGLEVEL Le s_consoleOutputEnabled = Enabled; if (Enabled) - RegisterCallback(PlatformStandardOutputLogCallback, NULL); + RegisterCallback(StandardOutputLogCallback, NULL); else - UnregisterCallback(PlatformStandardOutputLogCallback, NULL); + UnregisterCallback(StandardOutputLogCallback, NULL); -#if defined(WIN32) +#if defined(_WIN32) && !defined(_CONSOLE) if (Enabled) { // Windows Console behavior is very tricky, and depends on: // - Whether the application is built with defined(_CONSOLE) or not. @@ -407,16 +340,21 @@ void SetConsoleOutputParams(bool Enabled, const char* ChannelFilter, LOGLEVEL Le // // To maintain some level of personal sanity, I'll disregard all the DLL/CRT caveats for now. // - // Microsoft CMD.EXE "does us a favor" and DETACHES the standard console pipes when it spawns - // windowed applications, but only if redirections are not specified at the command line. - // This creates all kinds of confusion and havok that could easy fill pages of the screen with - // comments. The TL;DR version is: - // - only call AllocConsole() if the stdout/stderr pipes are DETACHED (null) - this avoids - // clobbering pipe redirections specified from any shell (cmd/bash) and avoids creating - // spurious console windows when running from MSYS/ConEmu/GitBash. - // - Only use Microsoft's over-engineered Console text-coloring APIs if we called AllocConsole, - // because those APIs result in a whole lot of black screen if you call them while attached to - // a terminal app (ConEmu, ConsoleX, etc). + // Console Mode (_CONSOLE) vs Windowed Application + // Microsoft CMD.EXE "does us a favor" and DETACHES the standard console pipes when it spawns + // windowed applications, but only if redirections are not specified at the command line. + // This creates all kinds of confusion and havok that could easy fill pages of the screen with + // comments. The TL;DR version is: + // - only call AllocConsole() if the stdout/stderr pipes are DETACHED (null) - this avoids + // clobbering pipe redirections specified from any shell (cmd/bash) and avoids creating + // spurious console windows when running from MSYS/ConEmu/GitBash. + // - Only use Microsoft's over-engineered Console text-coloring APIs if we called AllocConsole, + // because those APIs result in a whole lot of black screen if you call them while attached to + // a terminal app (ConEmu, ConsoleX, etc). + // - Ignore all of this if defined(_CONSOLE), in that case the OS behavior straightforward and a + // console is always allocated/attached. This is its own annoyance, and thus why few devs use + // it, even for console apps, because actually we DON'T want the console window popping up + // every time we run some console app in the background. --jstine s_msw_prev_stdin = ::GetStdHandle(STD_INPUT_HANDLE ); s_msw_prev_stdout = ::GetStdHandle(STD_OUTPUT_HANDLE);