Merge pull request #2654 from DarkLordZach/lm-log-rewrite

lm: Rewrite logger to use core reporting services

src/core/CMakeLists.txt

@@ -335,6 +335,8 @@ add_library(core STATIC
     hle/service/ldr/ldr.h
     hle/service/lm/lm.cpp
     hle/service/lm/lm.h
+    hle/service/lm/manager.cpp
+    hle/service/lm/manager.h
     hle/service/mig/mig.cpp
     hle/service/mig/mig.h
     hle/service/mii/mii.cpp

src/core/core.cpp

@@ -35,6 +35,7 @@
 #include "core/hle/service/apm/controller.h"
 #include "core/hle/service/filesystem/filesystem.h"
 #include "core/hle/service/glue/manager.h"
+#include "core/hle/service/lm/manager.h"
 #include "core/hle/service/service.h"
 #include "core/hle/service/sm/sm.h"
 #include "core/loader/loader.h"
@@ -250,6 +251,8 @@ struct System::Impl {
         telemetry_session->AddField(Telemetry::FieldType::Performance, "Mean_Frametime_MS",
                                     perf_stats->GetMeanFrametime());
 
+        lm_manager.Flush();
+
         is_powered_on = false;
         exit_lock = false;
 
@@ -338,6 +341,7 @@ struct System::Impl {
     bool is_powered_on = false;
     bool exit_lock = false;
 
+    Reporter reporter;
     std::unique_ptr<Memory::CheatEngine> cheat_engine;
     std::unique_ptr<Tools::Freezer> memory_freezer;
     std::array<u8, 0x20> build_id{};
@@ -348,8 +352,9 @@ struct System::Impl {
     /// APM (Performance) services
     Service::APM::Controller apm_controller{core_timing};
 
-    /// Glue services
+    /// Service State
     Service::Glue::ARPManager arp_manager;
+    Service::LM::Manager lm_manager{reporter};
 
     /// Service manager
     std::shared_ptr<Service::SM::ServiceManager> service_manager;
@@ -357,8 +362,6 @@ struct System::Impl {
     /// Telemetry session for this emulation session
     std::unique_ptr<Core::TelemetrySession> telemetry_session;
 
-    Reporter reporter;
-
     ResultStatus status = ResultStatus::Success;
     std::string status_details = "";
 
@@ -634,6 +637,14 @@ const Service::APM::Controller& System::GetAPMController() const {
     return impl->apm_controller;
 }
 
+Service::LM::Manager& System::GetLogManager() {
+    return impl->lm_manager;
+}
+
+const Service::LM::Manager& System::GetLogManager() const {
+    return impl->lm_manager;
+}
+
 void System::SetExitLock(bool locked) {
     impl->exit_lock = locked;
 }

src/core/core.h

@@ -57,6 +57,10 @@ namespace Glue {
 class ARPManager;
 }
 
+namespace LM {
+class Manager;
+} // namespace LM
+
 namespace SM {
 class ServiceManager;
 } // namespace SM
@@ -327,6 +331,10 @@ public:
 
     const Service::APM::Controller& GetAPMController() const;
 
+    Service::LM::Manager& GetLogManager();
+
+    const Service::LM::Manager& GetLogManager() const;
+
     void SetExitLock(bool locked);
 
     bool GetExitLock() const;

src/core/hle/service/lm/lm.cpp

@@ -6,8 +6,10 @@
 #include <string>
 
 #include "common/logging/log.h"
+#include "common/scope_exit.h"
 #include "core/hle/ipc_helpers.h"
 #include "core/hle/service/lm/lm.h"
+#include "core/hle/service/lm/manager.h"
 #include "core/hle/service/service.h"
 #include "core/memory.h"
 
@@ -15,65 +17,16 @@ namespace Service::LM {
 
 class ILogger final : public ServiceFramework<ILogger> {
 public:
-    ILogger() : ServiceFramework("ILogger") {
+    ILogger(Manager& manager) : ServiceFramework("ILogger"), manager(manager) {
         static const FunctionInfo functions[] = {
-            {0x00000000, &ILogger::Initialize, "Initialize"},
-            {0x00000001, &ILogger::SetDestination, "SetDestination"},
+            {0, &ILogger::Log, "Log"},
+            {1, &ILogger::SetDestination, "SetDestination"},
         };
         RegisterHandlers(functions);
     }
 
 private:
-    struct MessageHeader {
-        enum Flags : u32_le {
-            IsHead = 1,
-            IsTail = 2,
-        };
-        enum Severity : u32_le {
-            Trace,
-            Info,
-            Warning,
-            Error,
-            Critical,
-        };
-
-        u64_le pid;
-        u64_le threadContext;
-        union {
-            BitField<0, 16, Flags> flags;
-            BitField<16, 8, Severity> severity;
-            BitField<24, 8, u32> verbosity;
-        };
-        u32_le payload_size;
-
-        bool IsHeadLog() const {
-            return flags & Flags::IsHead;
-        }
-        bool IsTailLog() const {
-            return flags & Flags::IsTail;
-        }
-    };
-    static_assert(sizeof(MessageHeader) == 0x18, "MessageHeader is incorrect size");
-
-    /// Log field type
-    enum class Field : u8 {
-        Skip = 1,
-        Message = 2,
-        Line = 3,
-        Filename = 4,
-        Function = 5,
-        Module = 6,
-        Thread = 7,
-    };
-
-    /**
-     * ILogger::Initialize service function
-     *  Inputs:
-     *      0: 0x00000000
-     *  Outputs:
-     *      0: ResultCode
-     */
-    void Initialize(Kernel::HLERequestContext& ctx) {
+    void Log(Kernel::HLERequestContext& ctx) {
         // This function only succeeds - Get that out of the way
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(RESULT_SUCCESS);
@@ -85,140 +38,70 @@ private:
         Memory::ReadBlock(addr, &header, sizeof(MessageHeader));
         addr += sizeof(MessageHeader);
 
-        if (header.IsHeadLog()) {
-            log_stream.str("");
-            log_stream.clear();
-        }
-
-        // Parse out log metadata
-        u32 line{};
-        std::string module;
-        std::string message;
-        std::string filename;
-        std::string function;
-        std::string thread;
+        FieldMap fields;
         while (addr < end_addr) {
-            const Field field{static_cast<Field>(Memory::Read8(addr++))};
-            const std::size_t length{Memory::Read8(addr++)};
+            const auto field = static_cast<Field>(Memory::Read8(addr++));
+            const auto length = Memory::Read8(addr++);
 
             if (static_cast<Field>(Memory::Read8(addr)) == Field::Skip) {
                 ++addr;
             }
 
-            switch (field) {
-            case Field::Skip:
-                break;
-            case Field::Message:
-                message = Memory::ReadCString(addr, length);
-                break;
-            case Field::Line:
-                line = Memory::Read32(addr);
-                break;
-            case Field::Filename:
-                filename = Memory::ReadCString(addr, length);
-                break;
-            case Field::Function:
-                function = Memory::ReadCString(addr, length);
-                break;
-            case Field::Module:
-                module = Memory::ReadCString(addr, length);
-                break;
-            case Field::Thread:
-                thread = Memory::ReadCString(addr, length);
-                break;
-            }
+            SCOPE_EXIT({ addr += length; });
 
-            addr += length;
-        }
+            if (field == Field::Skip) {
+                continue;
+            }
 
-        // Empty log - nothing to do here
-        if (log_stream.str().empty() && message.empty()) {
-            return;
+            std::vector<u8> data(length);
+            Memory::ReadBlock(addr, data.data(), length);
+            fields.emplace(field, std::move(data));
         }
 
-        // Format a nicely printable string out of the log metadata
-        if (!filename.empty()) {
-            log_stream << filename << ':';
-        }
-        if (!module.empty()) {
-            log_stream << module << ':';
-        }
-        if (!function.empty()) {
-            log_stream << function << ':';
-        }
-        if (line) {
-            log_stream << std::to_string(line) << ':';
-        }
-        if (!thread.empty()) {
-            log_stream << thread << ':';
-        }
-        if (log_stream.str().length() > 0 && log_stream.str().back() == ':') {
-            log_stream << ' ';
-        }
-        log_stream << message;
-
-        if (header.IsTailLog()) {
-            switch (header.severity) {
-            case MessageHeader::Severity::Trace:
-                LOG_DEBUG(Debug_Emulated, "{}", log_stream.str());
-                break;
-            case MessageHeader::Severity::Info:
-                LOG_INFO(Debug_Emulated, "{}", log_stream.str());
-                break;
-            case MessageHeader::Severity::Warning:
-                LOG_WARNING(Debug_Emulated, "{}", log_stream.str());
-                break;
-            case MessageHeader::Severity::Error:
-                LOG_ERROR(Debug_Emulated, "{}", log_stream.str());
-                break;
-            case MessageHeader::Severity::Critical:
-                LOG_CRITICAL(Debug_Emulated, "{}", log_stream.str());
-                break;
-            }
-        }
+        manager.Log({header, std::move(fields)});
     }
 
-    // This service function is intended to be used as a way to
-    // redirect logging output to different destinations, however,
-    // given we always want to see the logging output, it's sufficient
-    // to do nothing and return success here.
     void SetDestination(Kernel::HLERequestContext& ctx) {
-        LOG_DEBUG(Service_LM, "called");
+        IPC::RequestParser rp{ctx};
+        const auto destination = rp.PopEnum<DestinationFlag>();
+
+        LOG_DEBUG(Service_LM, "called, destination={:08X}", static_cast<u32>(destination));
+
+        manager.SetDestination(destination);
 
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(RESULT_SUCCESS);
     }
 
-    std::ostringstream log_stream;
+    Manager& manager;
 };
 
 class LM final : public ServiceFramework<LM> {
 public:
-    explicit LM() : ServiceFramework{"lm"} {
+    explicit LM(Manager& manager) : ServiceFramework{"lm"}, manager(manager) {
+        // clang-format off
         static const FunctionInfo functions[] = {
-            {0x00000000, &LM::OpenLogger, "OpenLogger"},
+            {0, &LM::OpenLogger, "OpenLogger"},
         };
+        // clang-format on
+
         RegisterHandlers(functions);
     }
 
-    /**
-     * LM::OpenLogger service function
-     *  Inputs:
-     *      0: 0x00000000
-     *  Outputs:
-     *      0: ResultCode
-     */
+private:
     void OpenLogger(Kernel::HLERequestContext& ctx) {
         LOG_DEBUG(Service_LM, "called");
 
         IPC::ResponseBuilder rb{ctx, 2, 0, 1};
         rb.Push(RESULT_SUCCESS);
-        rb.PushIpcInterface<ILogger>();
+        rb.PushIpcInterface<ILogger>(manager);
     }
+
+    Manager& manager;
 };
 
-void InstallInterfaces(SM::ServiceManager& service_manager) {
-    std::make_shared<LM>()->InstallAsService(service_manager);
+void InstallInterfaces(Core::System& system) {
+    std::make_shared<LM>(system.GetLogManager())->InstallAsService(system.ServiceManager());
 }
 
 } // namespace Service::LM

src/core/hle/service/lm/lm.h

@@ -4,13 +4,13 @@
 
 #pragma once
 
-namespace Service::SM {
-class ServiceManager;
+namespace Core {
+class System;
 }
 
 namespace Service::LM {
 
 /// Registers all LM services with the specified service manager.
-void InstallInterfaces(SM::ServiceManager& service_manager);
+void InstallInterfaces(Core::System& system);
 
 } // namespace Service::LM

src/core/hle/service/lm/manager.cpp

@@ -0,0 +1,133 @@
+// Copyright 2019 yuzu emulator team
+// Licensed under GPLv2 or any later version
+// Refer to the license.txt file included.
+
+#include "common/assert.h"
+#include "common/logging/log.h"
+#include "common/string_util.h"
+#include "core/hle/service/lm/manager.h"
+#include "core/reporter.h"
+
+namespace Service::LM {
+
+std::ostream& operator<<(std::ostream& os, DestinationFlag dest) {
+    std::vector<std::string> array;
+    const auto check_single_flag = [dest, &array](DestinationFlag check, std::string name) {
+        if ((static_cast<u32>(check) & static_cast<u32>(dest)) != 0) {
+            array.emplace_back(std::move(name));
+        }
+    };
+
+    check_single_flag(DestinationFlag::Default, "Default");
+    check_single_flag(DestinationFlag::UART, "UART");
+    check_single_flag(DestinationFlag::UARTSleeping, "UART (Sleeping)");
+
+    os << "[";
+    for (const auto& entry : array) {
+        os << entry << ", ";
+    }
+    return os << "]";
+}
+
+std::ostream& operator<<(std::ostream& os, MessageHeader::Severity severity) {
+    switch (severity) {
+    case MessageHeader::Severity::Trace:
+        return os << "Trace";
+    case MessageHeader::Severity::Info:
+        return os << "Info";
+    case MessageHeader::Severity::Warning:
+        return os << "Warning";
+    case MessageHeader::Severity::Error:
+        return os << "Error";
+    case MessageHeader::Severity::Critical:
+        return os << "Critical";
+    default:
+        return os << fmt::format("{:08X}", static_cast<u32>(severity));
+    }
+}
+
+std::ostream& operator<<(std::ostream& os, Field field) {
+    switch (field) {
+    case Field::Skip:
+        return os << "Skip";
+    case Field::Message:
+        return os << "Message";
+    case Field::Line:
+        return os << "Line";
+    case Field::Filename:
+        return os << "Filename";
+    case Field::Function:
+        return os << "Function";
+    case Field::Module:
+        return os << "Module";
+    case Field::Thread:
+        return os << "Thread";
+    default:
+        return os << fmt::format("{:08X}", static_cast<u32>(field));
+    }
+}
+
+std::string FormatField(Field type, const std::vector<u8>& data) {
+    switch (type) {
+    case Field::Skip:
+        return "";
+    case Field::Line:
+        if (data.size() >= sizeof(u32)) {
+            u32 line;
+            std::memcpy(&line, data.data(), sizeof(u32));
+            return fmt::format("{}", line);
+        }
+        return "[ERROR DECODING LINE NUMBER]";
+    case Field::Message:
+    case Field::Filename:
+    case Field::Function:
+    case Field::Module:
+    case Field::Thread:
+        return Common::StringFromFixedZeroTerminatedBuffer(
+            reinterpret_cast<const char*>(data.data()), data.size());
+    default:
+        UNIMPLEMENTED();
+    }
+}
+
+Manager::Manager(Core::Reporter& reporter) : reporter(reporter) {}
+
+Manager::~Manager() = default;
+
+void Manager::SetEnabled(bool enabled) {
+    this->enabled = enabled;
+}
+
+void Manager::SetDestination(DestinationFlag destination) {
+    this->destination = destination;
+}
+
+void Manager::Log(LogMessage message) {
+    if (message.header.IsHeadLog()) {
+        InitializeLog();
+    }
+
+    current_log.emplace_back(std::move(message));
+
+    if (current_log.back().header.IsTailLog()) {
+        FinalizeLog();
+    }
+}
+
+void Manager::Flush() {
+    FinalizeLog();
+}
+
+void Manager::InitializeLog() {
+    current_log.clear();
+
+    LOG_INFO(Service_LM, "Initialized new log session");
+}
+
+void Manager::FinalizeLog() {
+    reporter.SaveLogReport(static_cast<u32>(destination), std::move(current_log));
+
+    LOG_INFO(Service_LM, "Finalized current log session");
+}
+
+} // namespace Service::LM

src/core/hle/service/lm/manager.h

@@ -0,0 +1,106 @@
+// Copyright 2019 yuzu emulator team
+// Licensed under GPLv2 or any later version
+// Refer to the license.txt file included.
+
+#pragma once
+
+#include <map>
+#include <ostream>
+#include <vector>
+#include "common/bit_field.h"
+#include "common/common_types.h"
+#include "common/swap.h"
+
+namespace Core {
+class Reporter;
+}
+
+namespace Service::LM {
+
+enum class DestinationFlag : u32 {
+    Default = 1,
+    UART = 2,
+    UARTSleeping = 4,
+
+    All = 0xFFFF,
+};
+
+struct MessageHeader {
+    enum Flags : u32_le {
+        IsHead = 1,
+        IsTail = 2,
+    };
+    enum Severity : u32_le {
+        Trace,
+        Info,
+        Warning,
+        Error,
+        Critical,
+    };
+
+    u64_le pid;
+    u64_le thread_context;
+    union {
+        BitField<0, 16, Flags> flags;
+        BitField<16, 8, Severity> severity;
+        BitField<24, 8, u32> verbosity;
+    };
+    u32_le payload_size;
+
+    bool IsHeadLog() const {
+        return flags & IsHead;
+    }
+    bool IsTailLog() const {
+        return flags & IsTail;
+    }
+};
+static_assert(sizeof(MessageHeader) == 0x18, "MessageHeader is incorrect size");
+
+enum class Field : u8 {
+    Skip = 1,
+    Message = 2,
+    Line = 3,
+    Filename = 4,
+    Function = 5,
+    Module = 6,
+    Thread = 7,
+};
+
+std::ostream& operator<<(std::ostream& os, DestinationFlag dest);
+std::ostream& operator<<(std::ostream& os, MessageHeader::Severity severity);
+std::ostream& operator<<(std::ostream& os, Field field);
+
+using FieldMap = std::map<Field, std::vector<u8>>;
+
+struct LogMessage {
+    MessageHeader header;
+    FieldMap fields;
+};
+
+std::string FormatField(Field type, const std::vector<u8>& data);
+
+class Manager {
+public:
+    explicit Manager(Core::Reporter& reporter);
+    ~Manager();
+
+    void SetEnabled(bool enabled);
+    void SetDestination(DestinationFlag destination);
+
+    void Log(LogMessage message);
+
+    void Flush();
+
+private:
+    void InitializeLog();
+    void FinalizeLog();
+
+    bool enabled = true;
+    DestinationFlag destination = DestinationFlag::All;
+
+    std::vector<LogMessage> current_log;
+
+    Core::Reporter& reporter;
+};
+
+} // namespace Service::LM

src/core/hle/service/service.cpp

@@ -226,7 +226,7 @@ void Init(std::shared_ptr<SM::ServiceManager>& sm, Core::System& system) {
     LBL::InstallInterfaces(*sm);
     LDN::InstallInterfaces(*sm);
     LDR::InstallInterfaces(*sm, system);
-    LM::InstallInterfaces(*sm);
+    LM::InstallInterfaces(system);
     Migration::InstallInterfaces(*sm);
     Mii::InstallInterfaces(*sm);
     MM::InstallInterfaces(*sm);

src/core/reporter.cpp

@@ -7,6 +7,7 @@
 
 #include <fmt/chrono.h>
 #include <fmt/format.h>
+#include <fmt/ostream.h>
 #include <json.hpp>
 
 #include "common/file_util.h"
@@ -17,6 +18,7 @@
 #include "core/hle/kernel/hle_ipc.h"
 #include "core/hle/kernel/process.h"
 #include "core/hle/result.h"
+#include "core/hle/service/lm/manager.h"
 #include "core/reporter.h"
 #include "core/settings.h"
 
@@ -354,6 +356,55 @@ void Reporter::SaveErrorReport(u64 title_id, ResultCode result,
     SaveToFile(std::move(out), GetPath("error_report", title_id, timestamp));
 }
 
+void Reporter::SaveLogReport(u32 destination, std::vector<Service::LM::LogMessage> messages) const {
+    if (!IsReportingEnabled()) {
+        return;
+    }
+
+    const auto timestamp = GetTimestamp();
+    json out;
+
+    out["yuzu_version"] = GetYuzuVersionData();
+    out["report_common"] =
+        GetReportCommonData(system.CurrentProcess()->GetTitleID(), RESULT_SUCCESS, timestamp);
+
+    out["log_destination"] =
+        fmt::format("{}", static_cast<Service::LM::DestinationFlag>(destination));
+
+    auto json_messages = json::array();
+    std::transform(messages.begin(), messages.end(), std::back_inserter(json_messages),
+                   [](const Service::LM::LogMessage& message) {
+                       json out;
+                       out["is_head"] = fmt::format("{}", message.header.IsHeadLog());
+                       out["is_tail"] = fmt::format("{}", message.header.IsTailLog());
+                       out["pid"] = fmt::format("{:016X}", message.header.pid);
+                       out["thread_context"] =
+                           fmt::format("{:016X}", message.header.thread_context);
+                       out["payload_size"] = fmt::format("{:016X}", message.header.payload_size);
+                       out["flags"] = fmt::format("{:04X}", message.header.flags.Value());
+                       out["severity"] = fmt::format("{}", message.header.severity.Value());
+                       out["verbosity"] = fmt::format("{:02X}", message.header.verbosity);
+
+                       auto fields = json::array();
+                       std::transform(message.fields.begin(), message.fields.end(),
+                                      std::back_inserter(fields), [](const auto& kv) {
+                                          json out;
+                                          out["type"] = fmt::format("{}", kv.first);
+                                          out["data"] =
+                                              Service::LM::FormatField(kv.first, kv.second);
+                                          return out;
+                                      });
+
+                       out["fields"] = std::move(fields);
+                       return out;
+                   });
+
+    out["log_messages"] = std::move(json_messages);
+
+    SaveToFile(std::move(out),
+               GetPath("log_report", system.CurrentProcess()->GetTitleID(), timestamp));
+}
+
 void Reporter::SaveFilesystemAccessReport(Service::FileSystem::LogMode log_mode,
                                           std::string log_message) const {
     if (!IsReportingEnabled())

src/core/reporter.h

@@ -20,6 +20,10 @@ namespace Service::FileSystem {
 enum class LogMode : u32;
 }
 
+namespace Service::LM {
+struct LogMessage;
+} // namespace Service::LM
+
 namespace Core {
 
 class System;
@@ -29,18 +33,22 @@ public:
     explicit Reporter(System& system);
     ~Reporter();
 
+    // Used by fatal services
     void SaveCrashReport(u64 title_id, ResultCode result, u64 set_flags, u64 entry_point, u64 sp,
                          u64 pc, u64 pstate, u64 afsr0, u64 afsr1, u64 esr, u64 far,
                          const std::array<u64, 31>& registers, const std::array<u64, 32>& backtrace,
                          u32 backtrace_size, const std::string& arch, u32 unk10) const;
 
+    // Used by syscall svcBreak
     void SaveSvcBreakReport(u32 type, bool signal_debugger, u64 info1, u64 info2,
                             std::optional<std::vector<u8>> resolved_buffer = {}) const;
 
+    // Used by HLE service handler
     void SaveUnimplementedFunctionReport(Kernel::HLERequestContext& ctx, u32 command_id,
                                          const std::string& name,
                                          const std::string& service_name) const;
 
+    // Used by stub applet implementation
     void SaveUnimplementedAppletReport(u32 applet_id, u32 common_args_version, u32 library_version,
                                        u32 theme_color, bool startup_sound, u64 system_tick,
                                        std::vector<std::vector<u8>> normal_channel,
@@ -55,6 +63,7 @@ public:
     void SavePlayReport(PlayReportType type, u64 title_id, std::vector<std::vector<u8>> data,
                         std::optional<u64> process_id = {}, std::optional<u128> user_id = {}) const;
 
+    // Used by error applet
     void SaveErrorReport(u64 title_id, ResultCode result,
                          std::optional<std::string> custom_text_main = {},
                          std::optional<std::string> custom_text_detail = {}) const;
@@ -62,6 +71,11 @@ public:
     void SaveFilesystemAccessReport(Service::FileSystem::LogMode log_mode,
                                     std::string log_message) const;
 
+    // Used by lm services
+    void SaveLogReport(u32 destination, std::vector<Service::LM::LogMessage> messages) const;
+
+    // Can be used anywhere to generate a backtrace and general info report at any point during
+    // execution. Not intended to be used for anything other than debugging or testing.
     void SaveUserReport() const;
 
 private: