AuroraRuntime/Source/Logging/AuLogger.cpp

/***
    Copyright (C) 2022 J Reece Wilson (a/k/a "Reece"). All rights reserved.

    File: AuLogger.cpp
    Date: 2022-1-21
    Author: Reece
***/
#include <Source/RuntimeInternal.hpp>
#include "AuLogger.hpp"
#include <Source/Grug/AuGrug.hpp>
#include <Source/Console/Hooks/Hooks.hpp>

namespace Aurora::Logging
{
    using namespace Console;

    static AuList<AuTuple<Logger *, AuUInt8, ConsoleMessage>> gLogTasks;
    static AuThreadPrimitives::MutexSOO gGlobalSpin;
    static AuThreadPrimitives::MutexSOO gTaskSpin;
    static AuList<Logger *> gFlushableLoggers;

    Logger::Logger(const AuList<AuSPtr<IBasicSink>> &sinks) : sinks(sinks)
    {
        AuMemset(shouldFilter, 0, sizeof(shouldFilter));
        {
            AU_LOCK_GUARD(gGlobalSpin);
            SysAssert(AuTryInsert(gFlushableLoggers, this));
        }
    }

    Logger::~Logger()
    {
        Disable();
    }

    void Logger::WriteLines(AuUInt8 uLevel, const ConsoleMessage &msg)
    {
        try
        {
            if (msg.line.find('\n') == AuString::npos &&
                ((!this->bEnableMitigations) || 
                 (msg.line.find('\r') == AuString::npos &&
                  msg.line.find('\33') == AuString::npos))) [[likely]]
            {
                WriteNowConst(uLevel, msg);
            }
            else [[unlikely]]
            {
                Parse::SplitNewlines(msg.line,
                    [&](const AuROString &line)
                    {
                        ConsoleMessage dup = msg;
                        dup.line = line;

                        if (WriteNow(uLevel, dup))
                        {
                            AddToPushQueueConst(uLevel, dup);
                        }
                    });
            }
        }
        catch (...)
        {
            // Loggers experiencing something fucky is a liablity
            Hooks::WriteLoggerFailedWarning();
        }
    }

    void Logger::WriteMessage(AuUInt8 uLevel, const ConsoleMessage &msg)
    {

        // Accounts for atomic shutdown
        {
            AU_LOCK_GUARD(spin);

            if (shouldFilter[uLevel])
            {
                return;
            }
        }

        WriteLines(uLevel, msg);
    }

    bool Logger::ExchangeMitigationState(bool bMitigationsEnabled)
    {
        return AuExchange(this->bEnableMitigations, bMitigationsEnabled);
    }

    void Logger::AddToPushQueue(AuUInt8 uLevel, /*const*/ ConsoleMessage &msg)
    {
        AddToPushQueueConst(uLevel, msg);
    }

    void Logger::AddToPushQueueConst(AuUInt8 uLevel, const ConsoleMessage &msg)
    {
        {
            AU_LOCK_GUARD(gTaskSpin);

            auto nice = gLogTasks.size() + 1;
            if (gLogTasks.capacity() < nice)
            {
                gLogTasks.reserve(nice * 10);
            }

            while (!AuTryInsert(gLogTasks, AuMakeTuple(this, uLevel, AuConstReference(msg))))
            {
                SysPushErrorMem("Push failed - trying again");
                gTaskSpin->Unlock();
                AuThreading::ContextYield();
                gTaskSpin->Lock();
            }
        }

        Grug::DrachenlordScreech();
    }

    void Logger::PushFilter(AuUInt8 uLevel, bool bShouldFilter)
    {
        AU_LOCK_GUARD(spin);

        while (!AuTryInsert(this->filters, AuMakeTuple(uLevel, shouldFilter)))
        {
            SysPushErrorMem("Push failed - trying again. wont be able to handle pop - wont syspanic yet");
            AuThreading::ContextYield();
        }

        AuMemset(this->shouldFilter, 0, sizeof(this->shouldFilter));

        for (auto &tuple : this->filters)
        {
            auto uLevel = AuGet<0>(tuple);
            auto shouldFilter = AuGet<1>(tuple);
            this->shouldFilter[uLevel] = shouldFilter;
        }
    }

    void Logger::PopFilter()
    {
        AU_LOCK_GUARD(this->spin);
        this->filters.pop_back();
    }

    void ForceFlushLoggers()
    {
        AU_DEBUG_MEMCRUNCH;
        decltype(gLogTasks) logTasks;
        AU_LOCK_GUARD(gGlobalSpin);

        {
            AU_LOCK_GUARD(gTaskSpin);
            AuSwap(logTasks, gLogTasks);
            gLogTasks.reserve(12 * 1024);
        }

        if (logTasks.empty())
        {
            return;
        }

        for (const auto &logEntry : logTasks)
        {
            auto &logger = AuGet<0>(logEntry);
            auto &uLevel = AuGet<1>(logEntry);
            auto &message = AuGet<2>(logEntry);

            try
            {
                logger->WriteLater(uLevel, message);
            }
            catch (...)
            {

            }
        }
    
    }

    void ForceFlushLoggersNoLock()
    {
        AU_DEBUG_MEMCRUNCH;
        decltype(gLogTasks) logTasks;

        {
            AuSwap(logTasks, gLogTasks);
            gLogTasks.reserve(1024);
        }

        if (logTasks.empty())
        {
            return;
        }

        for (const auto &logEntry : logTasks)
        {
            auto &logger = AuGet<0>(logEntry);
            auto &uLevel = AuGet<1>(logEntry);
            auto &message = AuGet<2>(logEntry);

            try
            {
                logger->WriteLater(uLevel, message);
            }
            catch (...)
            {

            }
        }
    }

    static void ForceFlushLogger(Logger *logger)
    {
        for (const auto &sink : logger->sinks)
        {
            if (!sink)
            {
                continue;
            }

            try
            {
                sink->OnFlush();
            }
            catch (...)
            {
                SysPushErrorCatch();
            }
        }
    }

    void ForceFlushFlushNoLock()
    {
        for (const auto &logger : gFlushableLoggers)
        {
            ForceFlushLogger(logger);
        }
    }

    void ForceFlushFlush()
    {
        AU_LOCK_GUARD(gGlobalSpin);

        ForceFlushFlushNoLock();
    }

    void Logger::Disable()
    {
        AU_LOCK_GUARD(gGlobalSpin);

        ForceFlushLoggersNoLock();
        ForceFlushLogger(this);

        {
            AU_LOCK_GUARD(spin);
            AuMemset(shouldFilter, 1, sizeof(shouldFilter));
        }

        {
            AuTryRemove(gFlushableLoggers, this);
        }
    }


    void Logger::WriteNowConst(AuUInt8 uLevel, const ConsoleMessage &msg)
    {
        bool bDelegateLater {};

        try
        {
            for (const auto &sink : this->sinks)
            {
                if (!sink)
                {
                    continue;
                }

                try
                {
                    bDelegateLater |= sink->OnMessageNonblocking(uLevel, msg);
                }
                catch (...)
                {
                    SysPushErrorCatch("Failed to pump a logger");
                }
            }
        }
        catch (...)
        {
            bDelegateLater = true;
            SysPushErrorCatch();
        }
        
        if (bDelegateLater)
        {
            AddToPushQueueConst(uLevel, msg);
        }
    }

    bool Logger::WriteNow(AuUInt8 uLevel, ConsoleMessage &msg)
    {
        if (this->bEnableMitigations)
        {
            // Nuke \r and \x1b / \33 / \e sequences using UTF-8 aware replaceall
            // \r -> dont let a bad actor override cat and unformatted console logs
            // \e -> dont let a bad actor communicate with a potentially vulnerable TTY emulator
            if (msg.line.find('\r') != AuString::npos) [[unlikely]]
            {
                AuCodepointsReplaceAll(msg.line, "\r", "\\r");
            }

            if (msg.line.find('\33') != AuString::npos) [[unlikely]]
            {
                AuCodepointsReplaceAll(msg.line, "\33", "\\e");
            }
        }

        bool bDelegateLater {};
        try
        {
            for (const auto &sink : this->sinks)
            {
                if (!sink)
                {
                    continue;
                }

                try
                {
                    bDelegateLater |= sink->OnMessageNonblocking(uLevel, msg);
                }
                catch (...)
                {
                    SysPushErrorCatch("Failed to pump a logger");
                }
            }
        }
        catch (...)
        {
            bDelegateLater = true;
            SysPushErrorCatch();
        }

        return bDelegateLater;
    }

    void Logger::WriteLater(AuUInt8 uLevel, const ConsoleMessage &msg)
    {
        try
        {
            for (const auto &sink : this->sinks)
            {
                if (!sink)
                {
                    continue;
                }

                try
                {
                    sink->OnMessageBlocking(uLevel, msg);
                }
                catch (...)
                {
                    SysPushErrorCatch("Failed to pump a logger");
                }
            }
        }
        catch (...)
        {
            SysPushErrorCatch();
        }
    }

    void InitLoggers()
    {
        gLogTasks.reserve(1000);
    }

    void DeinitLoggers()
    {
        ForceFlushLoggers();
        gUserLogger.reset();
    }

    AUKN_SYM ILogger *NewLoggerNew(const AuList<AuSPtr<IBasicSink>> &sinks)
    {
        try
        {
            auto pLogger = _new Logger(sinks);
            if (!pLogger)
            {
                return nullptr;
            }

            return pLogger;
        }
        catch (...)
        {
            SysPushErrorCatch();
            return {};
        }
    }

    AUKN_SYM void NewLoggerRelease(ILogger *pLogger)
    {
        AuSafeDelete<Logger *>(pLogger);
    }
}