From 83f8c1a25ef9a65eac0d000e41373bc212c5ba1c Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Wed, 20 Jan 2021 18:25:15 +1100 Subject: 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/hle/service/lm/lm.cpp | 317 ++++++++++++++++++++++++++++++++---- src/core/hle/service/lm/manager.cpp | 134 --------------- src/core/hle/service/lm/manager.h | 106 ------------ 3 files changed, 286 insertions(+), 271 deletions(-) delete mode 100644 src/core/hle/service/lm/manager.cpp delete mode 100644 src/core/hle/service/lm/manager.h (limited to 'src/core/hle') 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 (data.size() < sizeof(LogPacketHeader)) { + LOG_ERROR(Service_LM, "Data size is too small for header! size={}", data.size()); + return; + } - if (static_cast(memory.Read8(addr)) == Field::Skip) { - ++addr; - } + LogPacketHeader header{}; + std::memcpy(&header, data.data(), sizeof(LogPacketHeader)); + offset += sizeof(LogPacketHeader); - SCOPE_EXIT({ addr += length; }); + LogPacketHeaderEntry entry{ + .pid = header.pid, + .tid = header.tid, + .severity = header.severity, + .verbosity = header.verbosity, + }; - if (field == Field::Skip) { - continue; + 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)); - std::vector data(length); - memory.ReadBlock(addr, data.data(), length); - fields.emplace(field, std::move(data)); + 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))); } - manager.Log({header, std::move(fields)}); + 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(); - - LOG_DEBUG(Service_LM, "called, destination={:08X}", destination); + const auto log_destination = rp.PopEnum(); - 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 -- cgit v1.2.3 From dca2e2c8f1d72802c4804db16f9aedb3bf41328d Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Wed, 20 Jan 2021 18:35:58 +1100 Subject: Mark LogPacketHeaderEntry hash as noexcept --- src/core/hle/service/lm/lm.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/core/hle') diff --git a/src/core/hle/service/lm/lm.cpp b/src/core/hle/service/lm/lm.cpp index f4f6533ad..93e1fde01 100644 --- a/src/core/hle/service/lm/lm.cpp +++ b/src/core/hle/service/lm/lm.cpp @@ -39,7 +39,7 @@ struct LogPacketHeaderEntry { namespace std { template <> struct hash { - std::size_t operator()(const Service::LM::LogPacketHeaderEntry& k) const { + std::size_t operator()(const Service::LM::LogPacketHeaderEntry& k) const noexcept { std::size_t seed{}; boost::hash_combine(seed, k.pid); boost::hash_combine(seed, k.tid); -- cgit v1.2.3 From dc18a1261cb841502cbd8f41e9bc820a9d9a15b6 Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Wed, 20 Jan 2021 18:42:39 +1100 Subject: Mark DestinationToString as static --- src/core/hle/service/lm/lm.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/core/hle') diff --git a/src/core/hle/service/lm/lm.cpp b/src/core/hle/service/lm/lm.cpp index 93e1fde01..4e0b4ea09 100644 --- a/src/core/hle/service/lm/lm.cpp +++ b/src/core/hle/service/lm/lm.cpp @@ -286,7 +286,7 @@ private: } } - std::string DestinationToString(LogDestination destination) { + static std::string DestinationToString(LogDestination destination) { if (True(destination & LogDestination::All)) { return "TargetManager | Uart | UartSleep"; } -- cgit v1.2.3 From df4210032060ac271bb6c909d489ff094e16b7b9 Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Sat, 23 Jan 2021 18:24:57 +1100 Subject: Clamp string reads to buffer size --- src/core/hle/service/lm/lm.cpp | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) (limited to 'src/core/hle') diff --git a/src/core/hle/service/lm/lm.cpp b/src/core/hle/service/lm/lm.cpp index 4e0b4ea09..90e9e691a 100644 --- a/src/core/hle/service/lm/lm.cpp +++ b/src/core/hle/service/lm/lm.cpp @@ -162,9 +162,11 @@ private: if (length == 0) { return std::nullopt; } - std::string output(length, '\0'); - std::memcpy(output.data(), data.data() + offset, length); - offset += length; + const auto length_to_read = std::min(length, data.size() - offset); + + std::string output(length_to_read, '\0'); + std::memcpy(output.data(), data.data() + offset, length_to_read); + offset += length_to_read; return output; } -- cgit v1.2.3 From 2afc1060ef63c64cd1f541b37c219b340c84f722 Mon Sep 17 00:00:00 2001 From: Chloe Marcec Date: Mon, 25 Jan 2021 02:47:40 +1100 Subject: Print Process ID and Thread ID as hex --- src/core/hle/service/lm/lm.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'src/core/hle') diff --git a/src/core/hle/service/lm/lm.cpp b/src/core/hle/service/lm/lm.cpp index 90e9e691a..2a6d43d2a 100644 --- a/src/core/hle/service/lm/lm.cpp +++ b/src/core/hle/service/lm/lm.cpp @@ -253,8 +253,8 @@ private: 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); + output_log += fmt::format("ProcessID: {:X}\n", entry.pid); + output_log += fmt::format("ThreadID: {:X}\n", entry.tid); if (text_log) { output_log += fmt::format("Log Text: {}\n", *text_log); -- cgit v1.2.3