From 83f8c1a25ef9a65eac0d000e41373bc212c5ba1c Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Wed, 20 Jan 2021 18:25:15 +1100 Subject: [PATCH] lm: Recode LM service Rework the service to spit out to logs instead of a seperate file as well as fix any crashes caused by lm. --- src/core/CMakeLists.txt | 2 - src/core/core.cpp | 12 - src/core/core.h | 7 - src/core/hle/service/lm/lm.cpp | 327 +++++++++++++++++++++++++--- src/core/hle/service/lm/manager.cpp | 134 ------------ src/core/hle/service/lm/manager.h | 106 --------- src/core/reporter.cpp | 50 ----- src/core/reporter.h | 3 - 8 files changed, 291 insertions(+), 350 deletions(-) delete mode 100644 src/core/hle/service/lm/manager.cpp delete mode 100644 src/core/hle/service/lm/manager.h diff --git a/src/core/CMakeLists.txt b/src/core/CMakeLists.txt index 2f6b22747..9c9b3195b 100644 --- a/src/core/CMakeLists.txt +++ b/src/core/CMakeLists.txt @@ -400,8 +400,6 @@ 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/manager.cpp diff --git a/src/core/core.cpp b/src/core/core.cpp index 1a2002dec..86bdc7f6b 100644 --- a/src/core/core.cpp +++ b/src/core/core.cpp @@ -36,7 +36,6 @@ #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/hle/service/time/time_manager.h" @@ -293,8 +292,6 @@ struct System::Impl { perf_stats->GetMeanFrametime()); } - lm_manager.Flush(); - is_powered_on = false; exit_lock = false; @@ -398,7 +395,6 @@ struct System::Impl { /// Service State Service::Glue::ARPManager arp_manager; - Service::LM::Manager lm_manager{reporter}; Service::Time::TimeManager time_manager; /// Service manager @@ -720,14 +716,6 @@ 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; -} - Service::Time::TimeManager& System::GetTimeManager() { return impl->time_manager; } diff --git a/src/core/core.h b/src/core/core.h index 579a774e4..3a8e040c1 100644 --- a/src/core/core.h +++ b/src/core/core.h @@ -62,10 +62,6 @@ namespace Glue { class ARPManager; } -namespace LM { -class Manager; -} // namespace LM - namespace SM { class ServiceManager; } // namespace SM @@ -351,9 +347,6 @@ public: [[nodiscard]] Service::APM::Controller& GetAPMController(); [[nodiscard]] const Service::APM::Controller& GetAPMController() const; - [[nodiscard]] Service::LM::Manager& GetLogManager(); - [[nodiscard]] const Service::LM::Manager& GetLogManager() const; - [[nodiscard]] Service::Time::TimeManager& GetTimeManager(); [[nodiscard]] const Service::Time::TimeManager& GetTimeManager() const; diff --git a/src/core/hle/service/lm/lm.cpp b/src/core/hle/service/lm/lm.cpp index 8e49b068c..f4f6533ad 100644 --- a/src/core/hle/service/lm/lm.cpp +++ b/src/core/hle/service/lm/lm.cpp @@ -5,22 +5,71 @@ #include #include +#include +#include +#include #include "common/logging/log.h" #include "common/scope_exit.h" #include "core/core.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" namespace Service::LM { +enum class LogSeverity : u8 { + Trace = 0, + Info = 1, + Warning = 2, + Error = 3, + Fatal = 4, +}; + +// To keep flags out of hashing as well as the payload size +struct LogPacketHeaderEntry { + u64_le pid{}; + u64_le tid{}; + LogSeverity severity{}; + u8 verbosity{}; + + auto operator<=>(const LogPacketHeaderEntry&) const = default; +}; +} // namespace Service::LM + +namespace std { +template <> +struct hash { + std::size_t operator()(const Service::LM::LogPacketHeaderEntry& k) const { + std::size_t seed{}; + boost::hash_combine(seed, k.pid); + boost::hash_combine(seed, k.tid); + boost::hash_combine(seed, k.severity); + boost::hash_combine(seed, k.verbosity); + return seed; + }; +}; +} // namespace std + +namespace Service::LM { + +enum class LogDestination : u32 { + TargetManager = 1 << 0, + Uart = 1 << 1, + UartSleep = 1 << 2, + All = 0xffff, +}; +DECLARE_ENUM_FLAG_OPERATORS(LogDestination); + +enum class LogPacketFlags : u8 { + Head = 1 << 0, + Tail = 1 << 1, + LittleEndian = 1 << 2, +}; +DECLARE_ENUM_FLAG_OPERATORS(LogPacketFlags); class ILogger final : public ServiceFramework { public: - explicit ILogger(Core::System& system_) - : ServiceFramework{system_, "ILogger"}, manager{system_.GetLogManager()}, - memory{system_.Memory()} { + explicit ILogger(Core::System& system_) : ServiceFramework{system_, "ILogger"} { static const FunctionInfo functions[] = { {0, &ILogger::Log, "Log"}, {1, &ILogger::SetDestination, "SetDestination"}, @@ -30,54 +79,260 @@ public: private: void Log(Kernel::HLERequestContext& ctx) { + std::size_t offset{}; + const auto data = ctx.ReadBuffer(); + // This function only succeeds - Get that out of the way IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); - // Read MessageHeader, despite not doing anything with it right now - MessageHeader header{}; - VAddr addr{ctx.BufferDescriptorX()[0].Address()}; - const VAddr end_addr{addr + ctx.BufferDescriptorX()[0].size}; - memory.ReadBlock(addr, &header, sizeof(MessageHeader)); - addr += sizeof(MessageHeader); - - FieldMap fields; - while (addr < end_addr) { - const auto field = static_cast(memory.Read8(addr++)); - const auto length = memory.Read8(addr++); - - if (static_cast(memory.Read8(addr)) == Field::Skip) { - ++addr; - } - - SCOPE_EXIT({ addr += length; }); - - if (field == Field::Skip) { - continue; - } - - std::vector data(length); - memory.ReadBlock(addr, data.data(), length); - fields.emplace(field, std::move(data)); + if (data.size() < sizeof(LogPacketHeader)) { + LOG_ERROR(Service_LM, "Data size is too small for header! size={}", data.size()); + return; } - manager.Log({header, std::move(fields)}); + LogPacketHeader header{}; + std::memcpy(&header, data.data(), sizeof(LogPacketHeader)); + offset += sizeof(LogPacketHeader); + + LogPacketHeaderEntry entry{ + .pid = header.pid, + .tid = header.tid, + .severity = header.severity, + .verbosity = header.verbosity, + }; + + if (True(header.flags & LogPacketFlags::Head)) { + std::vector tmp(data.size() - sizeof(LogPacketHeader)); + std::memcpy(tmp.data(), data.data() + offset, tmp.size()); + entries[entry] = std::move(tmp); + } else { + // Append to existing entry + if (!entries.contains(entry)) { + LOG_ERROR(Service_LM, "Log entry does not exist!"); + return; + } + std::vector tmp(data.size() - sizeof(LogPacketHeader)); + + auto& existing_entry = entries[entry]; + const auto base = existing_entry.size(); + existing_entry.resize(base + (data.size() - sizeof(LogPacketHeader))); + std::memcpy(existing_entry.data() + base, data.data() + offset, + (data.size() - sizeof(LogPacketHeader))); + } + + if (True(header.flags & LogPacketFlags::Tail)) { + auto it = entries.find(entry); + if (it == entries.end()) { + LOG_ERROR(Service_LM, "Log entry does not exist!"); + return; + } + ParseLog(it->first, it->second); + entries.erase(it); + } } void SetDestination(Kernel::HLERequestContext& ctx) { IPC::RequestParser rp{ctx}; - const auto destination = rp.PopEnum(); + const auto log_destination = rp.PopEnum(); - LOG_DEBUG(Service_LM, "called, destination={:08X}", destination); - - manager.SetDestination(destination); + LOG_DEBUG(Service_LM, "called, destination={}", DestinationToString(log_destination)); + destination = log_destination; IPC::ResponseBuilder rb{ctx, 2}; rb.Push(RESULT_SUCCESS); } - Manager& manager; - Core::Memory::Memory& memory; + u32 ReadLeb128(const std::vector& data, std::size_t& offset) { + u32 result{}; + u32 shift{}; + do { + result |= (data[offset] & 0x7f) << shift; + shift += 7; + offset++; + if (offset >= data.size()) { + break; + } + } while ((data[offset] & 0x80) != 0); + return result; + } + + std::optional ReadString(const std::vector& data, std::size_t& offset, + std::size_t length) { + if (length == 0) { + return std::nullopt; + } + std::string output(length, '\0'); + std::memcpy(output.data(), data.data() + offset, length); + offset += length; + return output; + } + + u32_le ReadAsU32(const std::vector& data, std::size_t& offset, std::size_t length) { + ASSERT(length == sizeof(u32)); + u32_le output{}; + std::memcpy(&output, data.data() + offset, sizeof(u32)); + offset += length; + return output; + } + + u64_le ReadAsU64(const std::vector& data, std::size_t& offset, std::size_t length) { + ASSERT(length == sizeof(u64)); + u64_le output{}; + std::memcpy(&output, data.data() + offset, sizeof(u64)); + offset += length; + return output; + } + + void ParseLog(const LogPacketHeaderEntry entry, const std::vector& log_data) { + // Possible entries + std::optional text_log; + std::optional line_number; + std::optional file_name; + std::optional function_name; + std::optional module_name; + std::optional thread_name; + std::optional log_pack_drop_count; + std::optional user_system_clock; + std::optional process_name; + + std::size_t offset{}; + while (offset < log_data.size()) { + const auto key = static_cast(ReadLeb128(log_data, offset)); + const auto chunk_size = ReadLeb128(log_data, offset); + + switch (key) { + case LogDataChunkKey::LogSessionBegin: + case LogDataChunkKey::LogSessionEnd: + break; + case LogDataChunkKey::TextLog: + text_log = ReadString(log_data, offset, chunk_size); + break; + case LogDataChunkKey::LineNumber: + line_number = ReadAsU32(log_data, offset, chunk_size); + break; + case LogDataChunkKey::FileName: + file_name = ReadString(log_data, offset, chunk_size); + break; + case LogDataChunkKey::FunctionName: + function_name = ReadString(log_data, offset, chunk_size); + break; + case LogDataChunkKey::ModuleName: + module_name = ReadString(log_data, offset, chunk_size); + break; + case LogDataChunkKey::ThreadName: + thread_name = ReadString(log_data, offset, chunk_size); + break; + case LogDataChunkKey::LogPacketDropCount: + log_pack_drop_count = ReadAsU64(log_data, offset, chunk_size); + break; + case LogDataChunkKey::UserSystemClock: + user_system_clock = ReadAsU64(log_data, offset, chunk_size); + break; + case LogDataChunkKey::ProcessName: + process_name = ReadString(log_data, offset, chunk_size); + break; + } + } + + std::string output_log{}; + if (process_name) { + output_log += fmt::format("Process: {}\n", *process_name); + } + if (module_name) { + output_log += fmt::format("Module: {}\n", *module_name); + } + if (file_name) { + output_log += fmt::format("File: {}\n", *file_name); + } + if (function_name) { + output_log += fmt::format("Function: {}\n", *function_name); + } + if (line_number && *line_number != 0) { + output_log += fmt::format("Line: {}\n", *line_number); + } + output_log += fmt::format("ProcessID: {}\n", entry.pid); + output_log += fmt::format("ThreadID: {}\n", entry.tid); + + if (text_log) { + output_log += fmt::format("Log Text: {}\n", *text_log); + } + + switch (entry.severity) { + case LogSeverity::Trace: + LOG_DEBUG(Service_LM, "LogManager DEBUG ({}):\n{}", DestinationToString(destination), + output_log); + break; + case LogSeverity::Info: + LOG_INFO(Service_LM, "LogManager INFO ({}):\n{}", DestinationToString(destination), + output_log); + break; + case LogSeverity::Warning: + LOG_WARNING(Service_LM, "LogManager WARNING ({}):\n{}", + DestinationToString(destination), output_log); + break; + case LogSeverity::Error: + LOG_ERROR(Service_LM, "LogManager ERROR ({}):\n{}", DestinationToString(destination), + output_log); + break; + case LogSeverity::Fatal: + LOG_CRITICAL(Service_LM, "LogManager FATAL ({}):\n{}", DestinationToString(destination), + output_log); + break; + default: + LOG_CRITICAL(Service_LM, "LogManager UNKNOWN ({}):\n{}", + DestinationToString(destination), output_log); + break; + } + } + + std::string DestinationToString(LogDestination destination) { + if (True(destination & LogDestination::All)) { + return "TargetManager | Uart | UartSleep"; + } + std::string output{}; + if (True(destination & LogDestination::TargetManager)) { + output += "| TargetManager"; + } + if (True(destination & LogDestination::Uart)) { + output += "| Uart"; + } + if (True(destination & LogDestination::UartSleep)) { + output += "| UartSleep"; + } + if (output.length() > 0) { + return output.substr(2); + } + return "No Destination"; + } + + enum class LogDataChunkKey : u32 { + LogSessionBegin = 0, + LogSessionEnd = 1, + TextLog = 2, + LineNumber = 3, + FileName = 4, + FunctionName = 5, + ModuleName = 6, + ThreadName = 7, + LogPacketDropCount = 8, + UserSystemClock = 9, + ProcessName = 10, + }; + + struct LogPacketHeader { + u64_le pid{}; + u64_le tid{}; + LogPacketFlags flags{}; + INSERT_PADDING_BYTES(1); + LogSeverity severity{}; + u8 verbosity{}; + u32_le payload_size{}; + }; + static_assert(sizeof(LogPacketHeader) == 0x18, "LogPacketHeader is an invalid size"); + + std::unordered_map> entries{}; + LogDestination destination{LogDestination::All}; }; class LM final : public ServiceFramework { diff --git a/src/core/hle/service/lm/manager.cpp b/src/core/hle/service/lm/manager.cpp deleted file mode 100644 index 3ee2374e7..000000000 --- a/src/core/hle/service/lm/manager.cpp +++ /dev/null @@ -1,134 +0,0 @@ -// 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 array; - const auto check_single_flag = [dest, &array](DestinationFlag check, std::string name) { - if ((static_cast(check) & static_cast(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(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(field)); - } -} - -std::string FormatField(Field type, const std::vector& 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(data.data()), data.size()); - default: - UNIMPLEMENTED_MSG("Unimplemented field type={}", type); - return ""; - } -} - -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(destination), std::move(current_log)); - - LOG_INFO(Service_LM, "Finalized current log session"); -} - -} // namespace Service::LM diff --git a/src/core/hle/service/lm/manager.h b/src/core/hle/service/lm/manager.h deleted file mode 100644 index 544e636ba..000000000 --- a/src/core/hle/service/lm/manager.h +++ /dev/null @@ -1,106 +0,0 @@ -// Copyright 2019 yuzu emulator team -// Licensed under GPLv2 or any later version -// Refer to the license.txt file included. - -#pragma once - -#include -#include -#include -#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>; - -struct LogMessage { - MessageHeader header; - FieldMap fields; -}; - -std::string FormatField(Field type, const std::vector& 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 current_log; - - Core::Reporter& reporter; -}; - -} // namespace Service::LM diff --git a/src/core/reporter.cpp b/src/core/reporter.cpp index 0becdf642..f199c3362 100644 --- a/src/core/reporter.cpp +++ b/src/core/reporter.cpp @@ -20,7 +20,6 @@ #include "core/hle/kernel/memory/page_table.h" #include "core/hle/kernel/process.h" #include "core/hle/result.h" -#include "core/hle/service/lm/manager.h" #include "core/memory.h" #include "core/reporter.h" #include "core/settings.h" @@ -360,55 +359,6 @@ 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 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(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()) diff --git a/src/core/reporter.h b/src/core/reporter.h index 86d760cf0..b2c2d9a2e 100644 --- a/src/core/reporter.h +++ b/src/core/reporter.h @@ -72,9 +72,6 @@ public: void SaveFilesystemAccessReport(Service::FileSystem::LogMode log_mode, std::string log_message) const; - // Used by lm services - void SaveLogReport(u32 destination, std::vector 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;