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.
This commit is contained in:
Chloe Marcec 2021-01-20 18:25:15 +11:00
parent 4cd8b2f1f7
commit 83f8c1a25e
8 changed files with 291 additions and 350 deletions

View File

@ -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

View File

@ -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;
}

View File

@ -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;

View File

@ -5,22 +5,71 @@
#include <sstream>
#include <string>
#include <optional>
#include <unordered_map>
#include <boost/container_hash/hash.hpp>
#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<Service::LM::LogPacketHeaderEntry> {
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<ILogger> {
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<Field>(memory.Read8(addr++));
const auto length = memory.Read8(addr++);
if (static_cast<Field>(memory.Read8(addr)) == Field::Skip) {
++addr;
}
SCOPE_EXIT({ addr += length; });
if (field == Field::Skip) {
continue;
}
std::vector<u8> 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<u8> 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<u8> 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<DestinationFlag>();
const auto log_destination = rp.PopEnum<LogDestination>();
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<u8>& 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<std::string> ReadString(const std::vector<u8>& 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<u8>& 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<u8>& 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<u8>& log_data) {
// Possible entries
std::optional<std::string> text_log;
std::optional<u32> line_number;
std::optional<std::string> file_name;
std::optional<std::string> function_name;
std::optional<std::string> module_name;
std::optional<std::string> thread_name;
std::optional<u64> log_pack_drop_count;
std::optional<s64> user_system_clock;
std::optional<std::string> process_name;
std::size_t offset{};
while (offset < log_data.size()) {
const auto key = static_cast<LogDataChunkKey>(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<LogPacketHeaderEntry, std::vector<u8>> entries{};
LogDestination destination{LogDestination::All};
};
class LM final : public ServiceFramework<LM> {

View File

@ -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<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_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<u32>(destination), std::move(current_log));
LOG_INFO(Service_LM, "Finalized current log session");
}
} // namespace Service::LM

View File

@ -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 <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

View File

@ -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<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())

View File

@ -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<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;