Unable to see any console output on windows, plus set_pattern not working?

[Lord-Kamina]

I continue in my efforts to convert our old logger over to spdlog, and for the most part have been successful. Currently, on my mac the app is producing both a logfile and colored output to the console as I expect it to.

However, I decided to run some tests in windows, because I also wanted to try some code that was before just disabled on windows builds. After much trial and error, it should be working but alas, I get no output on the console.

Let me first walk you through the relevant parts of my code...

I have a SpdLogger class, that constructs and configures the various loggers. You'll noticed there's an odd loop where several loggers are created, what that does is iterate over an enum containing all valid logger names, construct each of them and register them with spdlog, as well as in an unordered_map I can use to look the pointers up without blocking the spdlog registry.

Then there's the StdErrGreabber struct, which essentially captures output to stderr, and formats and redirects it to stdout.

The getLogger function is called in the various SpdLogger::debug/trace/etc functions.

The writeHeader function is using its own special logger to prevent duplicate output.

On macOS, I am getting:

• Colored output on the console, using my defined pattern, "[%T]:::%^%n / %l%$::: %v"
• Output to my logfile, using the same pattern.

On windows, I am getting:

• No output on the console (or rather, there is only output from std::clog calls, and nothing from spdlog)
• Output to my logfile, using the default spdlog pattern instead of my custom format string. (don't know if these two problemas are in any way related)

Below are the relevant code snippets. P.S. I tried turning off color because I read an old issue saying using color on windows could cause output to be lost, but it didn't really make any difference.

#if (BOOST_OS_WINDOWS)

// ALL THESE DEFINES ARE ESSENTIALLY AIMED AT HAVING A SOMEWHAT UNIFORM COLOR SCHEME ON BOTH WINDOWS AND UNIX.

#define LOGGER_BLUE 0x0001
#define LOGGER_GREEN 0x0002
#define LOGGER_RED 0x0004
#define LOGGER_INTENSITY 0x0008
#define LOGGER_BACKGROUND(color) color<<4

using LoggerColor = std::uint16_t;

#else
#include <string_view>
#include <spdlog/sinks/ansicolor_sink.h>
using LoggerColor = std::string_view;
#define logger_colors(color) stdout_sink->color
#endif

#if defined(__unix__) || defined(__APPLE__)
#include <unistd.h>
#elif (BOOST_OS_WINDOWS)
#if defined(_MSC_VER)
#pragma warning(disable : 4996)
#endif
#include <errhandlingapi.h>
#include <fcntl.h>
#include <fileapi.h>
#include <io.h>
#include <ProcessEnv.h>
#include <stdio.h>
#define pipe(fd) _pipe(fd, 4096, _O_BINARY)

namespace logger_color_codes {
    LoggerColor black = 0;
    LoggerColor red = LOGGER_RED | LOGGER_INTENSITY; // Actually light_red.
    LoggerColor green = LOGGER_GREEN;
    LoggerColor yellow = LOGGER_RED | LOGGER_GREEN | LOGGER_INTENSITY; // Not gonna use it for now.
    LoggerColor blue = LOGGER_BLUE;
    LoggerColor magenta = LOGGER_BLUE | LOGGER_RED | LOGGER_INTENSITY; // Actually light_magenta according to windows, normal magenta is actually purple.
    LoggerColor cyan = LOGGER_BLUE | LOGGER_GREEN | LOGGER_INTENSITY; // Actually light_cyan according to windows, normal cyan is actually light blue.
    LoggerColor white = LOGGER_BLUE | LOGGER_GREEN | LOGGER_RED | LOGGER_INTENSITY;

    LoggerColor yellow_bold = LOGGER_RED | LOGGER_GREEN; // Actually brown, default win console colors are atrocious.
    LoggerColor red_bold = LOGGER_RED; // Actually normal red (which is darker).
    LoggerColor bold_on_red = white | LOGGER_BACKGROUND(LOGGER_RED); 
}
#define logger_colors(color) logger_color_codes::color

#endif

namespace {
#if (!BOOST_OS_WINDOWS)
    constexpr int stderr_fd = STDERR_FILENO;
#else
    int stderr_fd;
#endif
}

using IOStream = boost::iostreams::stream<boost::iostreams::file_descriptor_sink>;

// Capture stderr spam from other libraries and log it properly
// Note: std::cerr retains its normal functionality but other means of writing stderr get redirected to std::clog
#include <future>
struct StderrGrabber {
    IOStream stream;
    std::streambuf* backup;
    std::future<void> logger;
#if (BOOST_OS_WINDOWS)
    int handle_fd;
#endif
    StderrGrabber(): backup(std::cerr.rdbuf()) {
#if (BOOST_OS_WINDOWS)
    if (AttachConsole(ATTACH_PARENT_PROCESS) == 0) {
        SpdLogger::trace(LogSystem::LOGGER, "Failed to attach to console, error code={}, will try to create a new console.", GetLastError());
        if (AllocConsole() == 0) {
            SpdLogger::trace(LogSystem::LOGGER, "Failed to initialize console, error code={}", GetLastError());
        }
    }
    freopen_s ((FILE**)stdout, "CONOUT$", "w", stdout); 
    freopen_s ((FILE**)stderr, "CONOUT$", "w", stderr); 
    stderr_fd = fileno(stderr);
    SpdLogger::trace(LogSystem::LOGGER, "stderr fileno={}, stdout fileno={}, handle_fd={}", stderr_fd, fileno(stdout), handle_fd);
//  HANDLE stderrHandle = (HANDLE)_get_osfhandle(stderr_fd);
//  GetStdHandle(STD_ERROR_HANDLE);
//  if (stderrHandle == INVALID_HANDLE_VALUE) {
//      SpdLogger::warn(LogSystem::STDERR, "Failed to get stderr handle, error code={}", GetLastError());
//      return;
//  }
//  stderr_handle = _open_osfhandle((intptr_t)stderrHandle, _O_TEXT);
    handle_fd = dup(stderr_fd);
    stream.open((HANDLE)_get_osfhandle(handle_fd), boost::iostreams::close_handle);
#else
    stream.open(dup(stderr_fd), boost::iostreams::close_handle);
#endif
        std::cerr.rdbuf(stream.rdbuf());  // Make std::cerr write to our stream (which connects to normal stderr)
        int fd[2];
        if (pipe(fd) == -1) SpdLogger::notice(LogSystem::STDERR, "`pipe` returned an error: {}", std::strerror(errno));
        dup2(fd[1], stderr_fd);  // Close stderr and replace it with a copy of pipe begin
        close(fd[1]);  // Close the original pipe begin
        SpdLogger::info(LogSystem::STDERR, "Standard error output redirected here.");
        logger = std::async(std::launch::async, [fdpipe = fd[0]] {
            std::string line;
            unsigned count = 0;
            for (char ch; read(fdpipe, &ch, 1) == 1;) {
                line += ch;
                if (ch != '\n') continue;
                SpdLogger::info(LogSystem::STDERR, fmt::format("stderr redirect: {}", line));
                std::clog << "stderr/info: " + line << std::flush;
                line.clear(); ++count;
            }
            close(fdpipe);  // Close this end of pipe
            if (count > 0) {
                SpdLogger::notice(LogSystem::STDERR, "{} messages redirected to log.", count);
                std::clog << "stderr/notice: " << count << " messages logged to stderr/info\n" << std::flush;
            }
        });
    }
    ~StderrGrabber() {
#if (BOOST_OS_WINDOWS)
//  handle = fileno(stream->handle());
    dup2(handle_fd, stderr_fd);
    FreeConsole();
#else
    int handle = stream->handle();
        dup2(handle, stderr_fd);  // Restore stderr (closes the pipe, terminating the thread)
#endif
        std::cerr.rdbuf(backup);  // Restore original rdbuf (that writes to normal stderr)
    }
};

SpdLogger::SpdLogger (spdlog::level::level_enum const& consoleLevel) {
    Profiler prof("spdLogger-init");
    spdlog::init_thread_pool(2048, 1);

    auto time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
    std::string logHeader(fmt::format(
        "{0:*^80}\n"
        "{1:*^80}\n",
            fmt::format(" {} {} starting, {:%Y/%m/%d @ %H:%M:%S} ", PACKAGE, VERSION, fmt::localtime(time)),
            fmt::format(" Logging any events of level {}, or higher. ", spdlog::level::to_string_view(consoleLevel))));
    std::clog << "logger/debug: " << logHeader << std::endl;
    spdlog::filename_t filename = getLogFilename_new().u8string();

//  auto stderror_graber_sink = std::make_shared<spdlog::sinks::ostream_sink_mt>();
    m_sink = std::make_shared<spdlog::sinks::dist_sink_mt>();

    auto stdout_sink = std::make_shared<spdlog::sinks::stdout_color_sink_mt>();
    stdout_sink->set_color(spdlog::level::critical, logger_colors(bold_on_red)); // Error.
    stdout_sink->set_color(spdlog::level::err, logger_colors(yellow_bold)); // Warning.
    stdout_sink->set_color(spdlog::level::warn, logger_colors(green)); // Notice.
    stdout_sink->set_color(spdlog::level::info, logger_colors(white));
    stdout_sink->set_color(spdlog::level::debug, logger_colors(blue));
    stdout_sink->set_color(spdlog::level::trace, logger_colors(cyan));

    if (Platform::currentOS() == Platform::HostOS::OS_WIN) { stdout_sink->set_color_mode(spdlog::color_mode::never); }

    spdlog::file_event_handlers handlers;
    handlers.after_open = [logHeader](spdlog::filename_t filename, std::FILE *fstream) { writeLogHeader(filename, fstream, logHeader); };

    m_sink->add_sink(stdout_sink);
    m_sink->set_pattern("[%T]:::%^%n / %l%$::: %v");
    m_sink->set_level(spdlog::level::trace);

    m_defaultLogger = std::make_shared<spdlog::async_logger>(LogSystem{LogSystem::LOGGER}.toString(), m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);
    m_defaultLogger->set_pattern("[%T]:::%^%n / %l%$::: %v");
    m_defaultLogger->set_level(spdlog::level::trace);

    auto file_sink = std::make_shared<spdlog::sinks::rotating_file_sink_mt>(filename, 1024 * 1024 * 2, 5, true, handlers);
    m_sink->add_sink(file_sink);

    auto headerLogger = std::make_shared<spdlog::async_logger>(PACKAGE, stdout_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);
    headerLogger->log(spdlog::level::warn, logHeader);

    for (const auto& system: LogSystem()) {
        if (system == LogSystem::LOGGER) continue;
        std::unique_lock lock(m_LoggerRegistryMutex);
        auto newLogger = m_defaultLogger->clone(system);
        spdlog::register_logger(newLogger);
        builtLoggers.try_emplace(system, newLogger);
        newLogger->log(spdlog::level::trace, fmt::format("Logger subsystem initialized, system: {}", system));
    }

    grabber = std::make_unique<StderrGrabber>();
}

void SpdLogger::writeLogHeader(spdlog::filename_t filename, std::FILE* fd, std::string header) {
    fs::path _filename{filename};
    if (fs::exists(_filename) && fs::file_size(_filename) >30) {
        trace(LogSystem::LOGGER, "Not writing header to {}. File is not empty, probably a previous log being rotated.", filename);
        std::clog << "logger/debug: Not writing header to " << filename << ". Size > 0, so probably a log being rotated." << std::endl; 
        return;
    }
    if (fd == nullptr) {
        error(LogSystem::LOGGER, "Unable to write to logfile at {}, invalid fstream.", filename);
        return;
        }
    header.append("\n");
    int ret = std::fputs(header.c_str(), fd);
    if (ret == EOF) {
        error(LogSystem::LOGGER, "Unable to write to logfile at {}, error: {}", filename, std::strerror(errno));
    }
}

SpdLogger::~SpdLogger() {
    notice(LogSystem::LOGGER, "More details might be available in {}", getLogFilename_new().u8string());
    grabber.reset();
    spdlog::shutdown();
}

const loggerPtr SpdLogger::getLogger(LogSystem loggerName) {
    if (loggerName == LogSystem::LOGGER) {
        return m_defaultLogger;
    }
    loggerPtr ret;
    Profiler prof("getLogger");
    try {
        std::shared_lock lock(m_LoggerRegistryMutex);
        ret = builtLoggers.at(loggerName);
    } catch (std::out_of_range const&) {
        // logger not found, did we already build it?
        auto ptr = spdlog::get(loggerName.toString());
        if (ptr) {
            std::unique_lock lock(m_LoggerRegistryMutex);
            builtLoggers.try_emplace(loggerName, ptr);
            ret = builtLoggers.at(loggerName);
        }
        else {
            std::unique_lock lock(m_LoggerRegistryMutex);
            auto newLogger = std::make_shared<spdlog::async_logger>(loggerName, m_sink, spdlog::thread_pool(), spdlog::async_overflow_policy::block);
            spdlog::register_logger(newLogger);
            builtLoggers.try_emplace(loggerName, newLogger);
            ret = newLogger;
        }
    }
    if (ret == nullptr) {
        throw std::runtime_error(fmt::format("Couldn't find nor construct logger for subsystem={}", loggerName.toString()));
    }
    return ret;
}

[tt4g]

The STDOUT/STDERR handle got by stdout_color_sink is considered invalid.

https://github.com/gabime/spdlog/blob/63f0875000bf90867aa7c76a831bd834cb7d4b5e/include/spdlog/sinks/wincolor_sink-inl.h#L162-L170

You should not call AttachConsole() or AllocConsole() at least after stdout_color_sink.

[Lord-Kamina]

The STDOUT/STDERR handle got by stdout_color_sink is considered invalid.

https://github.com/gabime/spdlog/blob/63f0875000bf90867aa7c76a831bd834cb7d4b5e/include/spdlog/sinks/wincolor_sink-inl.h#L162-L170

You should not call AttachConsole() or AllocConsole() at least after stdout_color_sink.

If I don't call those functions there's still no output from spdlog, but then there's also no output from std::clog either.

Maybe I need to use SetStdHandle as well?

[tt4g]

Maybe I need to use SetStdHandle as well?

As far as the official documentation is concerned, yes: https://learn.microsoft.com/en-us/windows/console/console-handles This is not a spdlog question, so I suggest you ask it in the Microsoft Community or on StackOverflow.

[Lord-Kamina]

I posted it here because it's only speedlog that's not working but it probably has to do with orders of initialization so thanks for that.

And, do you have any idea what could be going on with the log formatting not working on windows?

[tt4g]

And, do you have any idea what could be going on with the log formatting not working on windows?

Are you talking about color by ANSI escape sequences? Windows is not supported: #3103 #3111

[Lord-Kamina]

And, do you have any idea what could be going on with the log formatting not working on windows?

Are you talking about color by ANSI escape sequences? Windows is not supported: #3103 #3111

No. On windows I am planning to use the windows console color api (that's what all the nasty defines are about) but that's not the question. The problem is spdlog is not applying my custom format string to messages written to the logfile.

Here's where I'm at: I managed to fix the issue of there not being any output at all to the console by moving the 'AttachConsole'/'AllocConsole' calls to another class that is initialized pretty much first thing when going into main (and before any spdlog calls), and now spdlog is indeed producing output to the console as expected. I don't have color but I'm hoping that will be fixed when I revert manually setting the color_mode to never.

However, when I write to the logfile on windows, spdlog is not using my custom pattern for the log message ("[%T]:::%^%n / %l%$::: %v") but instead it's using the default spdlog format, what would be equivalent to %+, even though logs to the console are using the expected pattern, and even though I tried manually changing the pattern on both the logger itself as well as the sink.

P.S. This is a behavior I'm only seeing on Windows so far.

[tt4g]

The problem is spdlog is not applying my custom format string to messages written to the logfile.

Not a console? I thought it was expected behavior that the format defaults to file since you didn't call file_sink->set_pattern().