/** ****************************************************************************** * Xenia : Xbox 360 Emulator Research Project * ****************************************************************************** * Copyright 2022 Ben Vanik. All rights reserved. * * Released under the BSD license - see LICENSE in the root for more details. * ****************************************************************************** */ #include "xenia/base/logging.h" #include #include #include #include #include #include #include "third_party/disruptorplus/include/disruptorplus/multi_threaded_claim_strategy.hpp" #include "third_party/disruptorplus/include/disruptorplus/ring_buffer.hpp" #include "third_party/disruptorplus/include/disruptorplus/sequence_barrier.hpp" #include "third_party/disruptorplus/include/disruptorplus/spin_wait_strategy.hpp" #include "xenia/base/assert.h" #include "xenia/base/atomic.h" #include "xenia/base/console.h" #include "xenia/base/cvar.h" #include "xenia/base/debugging.h" #include "xenia/base/filesystem.h" #include "xenia/base/literals.h" #include "xenia/base/math.h" #include "xenia/base/memory.h" #include "xenia/base/platform.h" #include "xenia/base/ring_buffer.h" #include "xenia/base/string.h" #include "xenia/base/system.h" #include "xenia/base/threading.h" // TODO(benvanik): generic API? logging_win.cc? #if XE_PLATFORM_ANDROID #include #elif XE_PLATFORM_WIN32 // For MessageBox: #include "xenia/base/platform_win.h" #endif // XE_PLATFORM #include "third_party/fmt/include/fmt/format.h" #if XE_PLATFORM_ANDROID DEFINE_bool(log_to_logcat, true, "Write log output to Android Logcat.", "Logging"); #else DEFINE_path(log_file, "", "Logs are written to the given file", "Logging"); DEFINE_bool(log_to_stdout, true, "Write log output to stdout", "Logging"); DEFINE_bool(log_to_debugprint, false, "Dump the log to DebugPrint.", "Logging"); #endif // XE_PLATFORM_ANDROID DEFINE_bool(flush_log, true, "Flush log file after each log line batch.", "Logging"); DEFINE_int32( log_level, 2, "Maximum level to be logged. (0=error, 1=warning, 2=info, 3=debug)", "Logging"); namespace dp = disruptorplus; using namespace xe::literals; namespace xe { class Logger; Logger* logger_ = nullptr; struct LogLine { size_t buffer_length; uint32_t thread_id; uint16_t _pad_0; // (2b) padding bool terminate; char prefix_char; }; thread_local char thread_log_buffer_[64_KiB]; FileLogSink::~FileLogSink() { if (file_) { fflush(file_); if (owns_file_) { fclose(file_); } } } void FileLogSink::Write(const char* buf, size_t size) { if (file_) { fwrite(buf, 1, size, file_); } } void FileLogSink::Flush() { if (file_) { fflush(file_); } } void DebugPrintLogSink::Write(const char* buf, size_t size) { debugging::DebugPrint("{}", std::string_view(buf, size)); } #if XE_PLATFORM_ANDROID class AndroidLogSink final : public LogSink { public: explicit AndroidLogSink(const std::string_view tag) : tag_(tag) {} void Write(const char* buf, size_t size) override; void Flush() override; private: // May be called with an empty line_buffer_ to write an empty log message (if // the original message contains a blank line as a separator, for instance). void WriteLineBuffer(); const std::string tag_; android_LogPriority current_priority_ = ANDROID_LOG_INFO; bool is_line_continuation_ = false; size_t line_buffer_used_ = 0; // LOGGER_ENTRY_MAX_PAYLOAD is defined as 4076 on older Android versions and // as 4068 on newer ones. An attempt to write more than that amount to the // kernel logger will result in a truncated log entry. 4000 is the commonly // used limit considered safe. // However, "Log message text may be truncated to less than an // implementation-specific limit (1023 bytes)" - android/log.h. char line_buffer_[1023 + 1]; }; void AndroidLogSink::Write(const char* buf, size_t size) { // A null character, if appears, is fine - it will just truncate a single // line, but since every message ends with a newline, and WriteLineBuffer is // done after every line, it won't have lasting effects. // Using memchr and memcpy as they are vectorized in Bionic. while (size) { const void* newline = std::memchr(buf, '\n', size); size_t line_remaining = newline ? size_t(static_cast(newline) - buf) : size; while (line_remaining) { assert_true(line_buffer_used_ < xe::countof(line_buffer_)); size_t append_count = std::min(line_remaining, xe::countof(line_buffer_) - size_t(1) - line_buffer_used_); std::memcpy(line_buffer_ + line_buffer_used_, buf, append_count); buf += append_count; size -= append_count; line_remaining -= append_count; line_buffer_used_ += append_count; if (line_buffer_used_ >= xe::countof(line_buffer_) - size_t(1)) { WriteLineBuffer(); // The next WriteLineBuffer belongs to the same line. is_line_continuation_ = true; } } if (newline) { // If the end of the buffer was reached right before a newline character, // so line_buffer_used_ is 0, and is_line_continuation_ has been set, the // line break has already been done by Android itself - don't write an // empty message. However, if the message intentionally contains blank // lines, write them. if (line_buffer_used_ || !is_line_continuation_) { WriteLineBuffer(); } is_line_continuation_ = false; ++buf; --size; } } } void AndroidLogSink::Flush() { if (line_buffer_used_) { WriteLineBuffer(); } } void AndroidLogSink::WriteLineBuffer() { // If this is a new line, check if it's a new log message, and if it is, // update the priority based on the prefix. if (!is_line_continuation_ && line_buffer_used_ >= 3 && line_buffer_[1] == '>' && line_buffer_[2] == ' ') { switch (line_buffer_[0]) { case 'd': current_priority_ = ANDROID_LOG_DEBUG; break; case 'w': current_priority_ = ANDROID_LOG_WARN; break; case '!': current_priority_ = ANDROID_LOG_ERROR; break; case 'x': current_priority_ = ANDROID_LOG_FATAL; break; default: current_priority_ = ANDROID_LOG_INFO; break; } } // Android skips blank lines, but if writing a blank line was requested // explicitly for formatting, write a non-newline character. if (!line_buffer_used_) { line_buffer_[line_buffer_used_++] = ' '; } // Terminate the text. assert_true(line_buffer_used_ < xe::countof(line_buffer_)); line_buffer_[line_buffer_used_] = '\0'; // Write. __android_log_write(current_priority_, tag_.c_str(), line_buffer_); line_buffer_used_ = 0; } #endif // XE_PLATFORM_ANDROID class Logger { public: explicit Logger(const std::string_view app_name) : wait_strategy_(), claim_strategy_(kBlockCount, wait_strategy_), consumed_(wait_strategy_) { claim_strategy_.add_claim_barrier(consumed_); write_thread_ = xe::threading::Thread::Create({}, [this]() { WriteThread(); }); assert_not_null(write_thread_); write_thread_->set_name("Logging Writer"); } ~Logger() { AppendLine(0, '\0', nullptr, 0, true); // append a terminator xe::threading::Wait(write_thread_.get(), true); } void AddLogSink(std::unique_ptr&& sink) { sinks_.push_back(std::move(sink)); } private: static const size_t kBufferSize = 8_MiB; uint8_t buffer_[kBufferSize]; static const size_t kBlockSize = 256; static const size_t kBlockCount = kBufferSize / kBlockSize; static const size_t kBlockIndexMask = kBlockCount - 1; static const size_t kClaimStrategyFootprint = sizeof(std::atomic[kBlockCount]); static size_t BlockOffset(dp::sequence_t sequence) { return (sequence & kBlockIndexMask) * kBlockSize; } static size_t BlockCount(size_t byte_size) { return (byte_size + (kBlockSize - 1)) / kBlockSize; } dp::spin_wait_strategy wait_strategy_; dp::multi_threaded_claim_strategy claim_strategy_; dp::sequence_barrier consumed_; std::vector> sinks_; std::unique_ptr write_thread_; void Write(const char* buf, size_t size) { for (const auto& sink : sinks_) { sink->Write(buf, size); } } void WriteThread() { RingBuffer rb(buffer_, kBufferSize); size_t idle_loops = 0; dp::sequence_t next_sequence = 0; dp::sequence_t last_sequence = -1; size_t desired_count = 1; while (true) { // We want one block to find out how many blocks we need or we know how // many blocks needed for at least one log line. auto next_range = dp::sequence_range(next_sequence, desired_count); claim_strategy_.wait_until_published(next_range.last(), last_sequence); size_t read_count = 0; auto available_range = next_range; auto available_count = available_range.size(); rb.set_write_offset(BlockOffset(available_range.end())); bool terminate = false; for (size_t i = available_range.first(); i != available_range.end();) { rb.set_read_offset(BlockOffset(i)); LogLine line; rb.Read(&line, sizeof(line)); auto needed_count = BlockCount(sizeof(LogLine) + line.buffer_length); if (read_count + needed_count > available_count) { // More blocks are needed for a complete line. desired_count = needed_count; break; } else { // Enough blocks to read this log line, advance by that many. read_count += needed_count; i += needed_count; if (line.prefix_char) { char prefix[] = { line.prefix_char, '>', ' ', '?', // Thread ID gets placed here (8 chars). '?', '?', '?', '?', '?', '?', '?', ' ', 0, }; fmt::format_to_n(prefix + 3, sizeof(prefix) - 3, "{:08X}", line.thread_id); Write(prefix, sizeof(prefix) - 1); } if (line.buffer_length) { // Get access to the line data - which may be split in the ring // buffer - and write it out in parts. auto line_range = rb.BeginRead(line.buffer_length); Write(reinterpret_cast(line_range.first), line_range.first_length); if (line_range.second_length) { Write(reinterpret_cast(line_range.second), line_range.second_length); } // Always ensure there is a newline. char last_char = line_range.second ? line_range.second[line_range.second_length - 1] : line_range.first[line_range.first_length - 1]; if (last_char != '\n') { const char suffix[1] = {'\n'}; Write(suffix, 1); } rb.EndRead(std::move(line_range)); } else { // Always ensure there is a newline. const char suffix[1] = {'\n'}; Write(suffix, 1); } if (line.terminate) { terminate = true; break; } } } if (terminate) { break; } if (read_count) { // Advance by the number of blocks we read. auto read_range = dp::sequence_range(next_sequence, read_count); next_sequence = read_range.end(); last_sequence = read_range.last(); consumed_.publish(last_sequence); desired_count = 1; if (cvars::flush_log) { for (const auto& sink : sinks_) { sink->Flush(); } } idle_loops = 0; } else { if (idle_loops >= 1000) { // Introduce a waiting period. xe::threading::Sleep(std::chrono::milliseconds(50)); } else { idle_loops++; } } } } public: void AppendLine(uint32_t thread_id, const char prefix_char, const char* buffer_data, size_t buffer_length, bool terminate = false) { size_t count = BlockCount(sizeof(LogLine) + buffer_length); auto range = claim_strategy_.claim(count); assert_true(range.size() == count); RingBuffer rb(buffer_, kBufferSize); rb.set_write_offset(BlockOffset(range.first())); rb.set_read_offset(BlockOffset(range.end())); LogLine line = {}; line.buffer_length = buffer_length; line.thread_id = thread_id; line.prefix_char = prefix_char; line.terminate = terminate; rb.Write(&line, sizeof(LogLine)); if (buffer_length) { rb.Write(buffer_data, buffer_length); } claim_strategy_.publish(range); } }; void InitializeLogging(const std::string_view app_name) { auto mem = memory::AlignedAlloc(0x10); logger_ = new (mem) Logger(app_name); #if XE_PLATFORM_ANDROID // TODO(Triang3l): Enable file logging, but not by default as logs may be // huge. if (cvars::log_to_logcat) { logger_->AddLogSink(std::make_unique(app_name)); } #else FILE* log_file = nullptr; if (cvars::log_file.empty()) { // Default to app name. auto file_name = fmt::format("{}.log", app_name); auto file_path = xe::filesystem::GetExecutableFolder() / file_name; log_file = xe::filesystem::OpenFile(file_path, "wt"); } else { xe::filesystem::CreateParentFolder(cvars::log_file); log_file = xe::filesystem::OpenFile(cvars::log_file, "wt"); } logger_->AddLogSink(std::make_unique(log_file, true)); if (cvars::log_to_stdout) { logger_->AddLogSink(std::make_unique(stdout, false)); } if (cvars::log_to_debugprint) { logger_->AddLogSink(std::make_unique()); } #endif // XE_PLATFORM_ANDROID } void ShutdownLogging() { Logger* logger = logger_; logger_ = nullptr; logger->~Logger(); memory::AlignedFree(logger); } bool logging::internal::ShouldLog(LogLevel log_level) { return logger_ != nullptr && static_cast(log_level) <= cvars::log_level; } std::pair logging::internal::GetThreadBuffer() { return {thread_log_buffer_, sizeof(thread_log_buffer_)}; } void logging::internal::AppendLogLine(LogLevel log_level, const char prefix_char, size_t written) { if (!ShouldLog(log_level) || !written) { return; } logger_->AppendLine(xe::threading::current_thread_id(), prefix_char, thread_log_buffer_, written); } void logging::AppendLogLine(LogLevel log_level, const char prefix_char, const std::string_view str) { if (!internal::ShouldLog(log_level) || !str.size()) { return; } logger_->AppendLine(xe::threading::current_thread_id(), prefix_char, str.data(), str.size()); } void FatalError(const std::string_view str) { logging::AppendLogLine(LogLevel::Error, 'x', str); if (!xe::has_console_attached()) { ShowSimpleMessageBox(SimpleMessageBoxType::Error, str); } ShutdownLogging(); #if XE_PLATFORM_ANDROID // Throw an error that can be reported to the developers via the store. std::abort(); #else std::exit(EXIT_FAILURE); #endif // XE_PLATFORM_ANDROID } } // namespace xe