diff --git a/src/client/game.cpp b/src/client/game.cpp index 32c57ec1b..1a125f492 100644 --- a/src/client/game.cpp +++ b/src/client/game.cpp @@ -882,7 +882,7 @@ private: SoundMaker *soundmaker = nullptr; ChatBackend *chat_backend = nullptr; - LogOutputBuffer m_chat_log_buf; + CaptureLogOutput m_chat_log_buf; EventManager *eventmgr = nullptr; QuicktuneShortcutter *quicktune = nullptr; @@ -930,6 +930,7 @@ private: * (as opposed to the this local caching). This can be addressed in * a later release. */ + bool m_cache_disable_escape_sequences; bool m_cache_doubletap_jump; bool m_cache_enable_clouds; bool m_cache_enable_joysticks; @@ -973,6 +974,10 @@ Game::Game() : m_chat_log_buf(g_logger), m_game_ui(new GameUI()) { + g_settings->registerChangedCallback("chat_log_level", + &settingChangedCallback, this); + g_settings->registerChangedCallback("disable_escape_sequences", + &settingChangedCallback, this); g_settings->registerChangedCallback("doubletap_jump", &settingChangedCallback, this); g_settings->registerChangedCallback("enable_clouds", @@ -1041,6 +1046,10 @@ Game::~Game() clearTextureNameCache(); + g_settings->deregisterChangedCallback("chat_log_level", + &settingChangedCallback, this); + g_settings->deregisterChangedCallback("disable_escape_sequences", + &settingChangedCallback, this); g_settings->deregisterChangedCallback("doubletap_jump", &settingChangedCallback, this); g_settings->deregisterChangedCallback("enable_clouds", @@ -1277,7 +1286,6 @@ void Game::shutdown() chat_backend->addMessage(L"", L"# Disconnected."); chat_backend->addMessage(L"", L""); - m_chat_log_buf.clear(); if (client) { client->Stop(); @@ -3208,9 +3216,27 @@ void Game::processClientEvents(CameraOrientation *cam) void Game::updateChat(f32 dtime) { + auto color_for = [](LogLevel level) -> const char* { + switch (level) { + case LL_ERROR : return "\x1b(c@#F00)"; // red + case LL_WARNING: return "\x1b(c@#EE0)"; // yellow + case LL_INFO : return "\x1b(c@#BBB)"; // grey + case LL_VERBOSE: return "\x1b(c@#888)"; // dark grey + case LL_TRACE : return "\x1b(c@#888)"; // dark grey + default : return ""; + } + }; + // Get new messages from error log buffer - while (!m_chat_log_buf.empty()) - chat_backend->addMessage(L"", utf8_to_wide(m_chat_log_buf.get())); + std::vector entries = m_chat_log_buf.take(); + for (const auto& entry : entries) { + std::string line; + if (!m_cache_disable_escape_sequences) { + line.append(color_for(entry.level)); + } + line.append(entry.combined); + chat_backend->addMessage(L"", utf8_to_wide(line)); + } // Get new messages from client std::wstring message; @@ -4433,6 +4459,14 @@ void Game::settingChangedCallback(const std::string &setting_name, void *data) void Game::readSettings() { + LogLevel chat_log_level = Logger::stringToLevel(g_settings->get("chat_log_level")); + if (chat_log_level == LL_MAX) { + warningstream << "Supplied unrecognized chat_log_level; showing none." << std::endl; + chat_log_level = LL_NONE; + } + m_chat_log_buf.setLogLevel(chat_log_level); + + m_cache_disable_escape_sequences = g_settings->getBool("disable_escape_sequences"); m_cache_doubletap_jump = g_settings->getBool("doubletap_jump"); m_cache_enable_clouds = g_settings->getBool("enable_clouds"); m_cache_enable_joysticks = g_settings->getBool("enable_joysticks"); diff --git a/src/log.cpp b/src/log.cpp index 5fac64f5c..ae3d9a9ab 100644 --- a/src/log.cpp +++ b/src/log.cpp @@ -371,42 +371,15 @@ void StreamLogOutput::logRaw(LogLevel lev, std::string_view line) } } -void LogOutputBuffer::updateLogLevel() +void StreamProxy::fix_stream_state(std::ostream &os) { - const std::string &conf_loglev = g_settings->get("chat_log_level"); - LogLevel log_level = Logger::stringToLevel(conf_loglev); - if (log_level == LL_MAX) { - warningstream << "Supplied unrecognized chat_log_level; " - "showing none." << std::endl; - log_level = LL_NONE; - } - - m_logger.removeOutput(this); - m_logger.addOutputMaxLevel(this, log_level); -} - -void LogOutputBuffer::logRaw(LogLevel lev, std::string_view line) -{ - std::string color; - - if (!g_settings->getBool("disable_escape_sequences")) { - switch (lev) { - case LL_ERROR: // red - color = "\x1b(c@#F00)"; - break; - case LL_WARNING: // yellow - color = "\x1b(c@#EE0)"; - break; - case LL_INFO: // grey - color = "\x1b(c@#BBB)"; - break; - case LL_VERBOSE: // dark grey - case LL_TRACE: - color = "\x1b(c@#888)"; - break; - default: break; - } - } - MutexAutoLock lock(m_buffer_mutex); - m_buffer.emplace(color.append(line)); + std::ios::iostate state = os.rdstate(); + // clear error state so the stream works again + os.clear(); + if (state & std::ios::eofbit) + os << "(ostream:eofbit)"; + if (state & std::ios::badbit) + os << "(ostream:badbit)"; + if (state & std::ios::failbit) + os << "(ostream:failbit)"; } diff --git a/src/log.h b/src/log.h index ccd13acf3..0e34b2c83 100644 --- a/src/log.h +++ b/src/log.h @@ -32,21 +32,60 @@ class StreamProxy { public: StreamProxy(std::ostream *os) : m_os(os) { } + static void fix_stream_state(std::ostream &os); + template - StreamProxy& operator<<(T&& arg) { + StreamProxy& operator<<(T&& arg) + { if (m_os) { + if (!m_os->good()) + fix_stream_state(*m_os); *m_os << std::forward(arg); } return *this; } - StreamProxy& operator<<(std::ostream& (*manip)(std::ostream&)) { + StreamProxy& operator<<(std::ostream& (*manip)(std::ostream&)) + { if (m_os) { + if (!m_os->good()) + fix_stream_state(*m_os); *m_os << manip; } return *this; } +private: + template + StreamProxy& emit_with_null_check(T&& arg) + { + // These calls explicitly use the templated version of operator<<, + // so that they won't use the overloads created by ADD_NULL_CHECK. + if (arg == nullptr) + return this->operator<< ("(null)"); + else + return this->operator<< (std::forward(arg)); + } + +public: + // Add specific overrides for operator<< which check for NULL string + // pointers. This is undefined behavior in the C++ spec, so emit "(null)" + // instead. These are method overloads, rather than template specializations. +#define ADD_NULL_CHECK(_type) \ + StreamProxy& operator<<(_type arg) \ + { \ + return emit_with_null_check(std::forward<_type>(arg)); \ + } + + ADD_NULL_CHECK(char*) + ADD_NULL_CHECK(unsigned char*) + ADD_NULL_CHECK(signed char*) + ADD_NULL_CHECK(const char*) + ADD_NULL_CHECK(const unsigned char*) + ADD_NULL_CHECK(const signed char*) + +#undef ADD_NULL_CHECK + private: std::ostream *m_os; }; diff --git a/src/log_internal.h b/src/log_internal.h index c8bc1b310..512a57949 100644 --- a/src/log_internal.h +++ b/src/log_internal.h @@ -123,54 +123,69 @@ private: std::ofstream m_stream; }; -class LogOutputBuffer : public ICombinedLogOutput { -public: - LogOutputBuffer(Logger &logger) : - m_logger(logger) - { - updateLogLevel(); - }; +struct LogEntry { + LogLevel level; + std::string timestamp; + std::string thread_name; + std::string text; + // "timestamp: level[thread_name]: text" + std::string combined; +}; - virtual ~LogOutputBuffer() +class CaptureLogOutput : public ILogOutput { +public: + CaptureLogOutput() = delete; + DISABLE_CLASS_COPY(CaptureLogOutput); + + CaptureLogOutput(Logger &logger) : m_logger(logger) + { + m_logger.addOutput(this); + } + + ~CaptureLogOutput() { m_logger.removeOutput(this); } - void updateLogLevel(); - - void logRaw(LogLevel lev, std::string_view line); - - void clear() + void setLogLevel(LogLevel level) { - MutexAutoLock lock(m_buffer_mutex); - m_buffer = std::queue(); + m_logger.removeOutput(this); + m_logger.addOutputMaxLevel(this, level); } - bool empty() const + void logRaw(LogLevel lev, std::string_view line) override { - MutexAutoLock lock(m_buffer_mutex); - return m_buffer.empty(); + MutexAutoLock lock(m_mutex); + m_entries.emplace_back(LogEntry{lev, "", "", std::string(line), std::string(line)}); } - std::string get() + void log(LogLevel lev, const std::string &combined, + const std::string &time, const std::string &thread_name, + std::string_view payload_text) override { - MutexAutoLock lock(m_buffer_mutex); - if (m_buffer.empty()) - return ""; - std::string s = std::move(m_buffer.front()); - m_buffer.pop(); - return s; + MutexAutoLock lock(m_mutex); + m_entries.emplace_back(LogEntry{lev, time, thread_name, std::string(payload_text), combined}); + } + + // Take the log entries currently stored, clearing the buffer. + std::vector take() + { + std::vector entries; + MutexAutoLock lock(m_mutex); + std::swap(m_entries, entries); + return entries; } private: - // g_logger serializes calls to logRaw() with a mutex, but that - // doesn't prevent get() / clear() from being called on top of it. - // This mutex prevents that. - mutable std::mutex m_buffer_mutex; - std::queue m_buffer; Logger &m_logger; + // g_logger serializes calls to log/logRaw with a mutex, but that + // doesn't prevent take() from being called on top of it. + // This mutex prevents that. + std::mutex m_mutex; + std::vector m_entries; }; + #ifdef __ANDROID__ class AndroidLogOutput : public ICombinedLogOutput { public: diff --git a/src/unittest/CMakeLists.txt b/src/unittest/CMakeLists.txt index 93803c912..f546d150e 100644 --- a/src/unittest/CMakeLists.txt +++ b/src/unittest/CMakeLists.txt @@ -13,6 +13,7 @@ set (UNITTEST_SRCS ${CMAKE_CURRENT_SOURCE_DIR}/test_filesys.cpp ${CMAKE_CURRENT_SOURCE_DIR}/test_inventory.cpp ${CMAKE_CURRENT_SOURCE_DIR}/test_irrptr.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/test_logging.cpp ${CMAKE_CURRENT_SOURCE_DIR}/test_lua.cpp ${CMAKE_CURRENT_SOURCE_DIR}/test_map.cpp ${CMAKE_CURRENT_SOURCE_DIR}/test_mapblock.cpp diff --git a/src/unittest/test_logging.cpp b/src/unittest/test_logging.cpp new file mode 100644 index 000000000..dcfe5ec83 --- /dev/null +++ b/src/unittest/test_logging.cpp @@ -0,0 +1,90 @@ +// SPDX-License-Identifier: LGPL-2.1-or-later + +#include "test.h" +#include "log_internal.h" + +using std::ostream; + +class TestLogging : public TestBase +{ +public: + TestLogging() { TestManager::registerTestModule(this); } + const char *getName() { return "TestLogging"; } + + void runTests(IGameDef *gamedef); + + void testNullChecks(); + void testBitCheck(); +}; + +static TestLogging g_test_instance; + +void TestLogging::runTests(IGameDef *gamedef) +{ + TEST(testNullChecks); + TEST(testBitCheck); +} + +//////////////////////////////////////////////////////////////////////////////// + +void TestLogging::testNullChecks() +{ + CaptureLogOutput capture(g_logger); + + infostream << "Test char*: " << (char*)0 << std::endl; + infostream << "Test signed char*: " << (signed char*)0 << std::endl; + infostream << "Test unsigned char*: " << (unsigned char*)0 << std::endl; + + infostream << "Test const char*: " << (const char*)0 << std::endl; + infostream << "Test const signed char*: " << (const signed char*)0 << std::endl; + infostream << "Test const unsigned char*: " << (const unsigned char*)0 << std::endl; + + + auto logs = capture.take(); + UASSERTEQ(size_t, logs.size(), 6); + UASSERTEQ(std::string, logs[0].text, "Test char*: (null)"); + UASSERTEQ(std::string, logs[1].text, "Test signed char*: (null)"); + UASSERTEQ(std::string, logs[2].text, "Test unsigned char*: (null)"); + UASSERTEQ(std::string, logs[3].text, "Test const char*: (null)"); + UASSERTEQ(std::string, logs[4].text, "Test const signed char*: (null)"); + UASSERTEQ(std::string, logs[5].text, "Test const unsigned char*: (null)"); +} + +namespace { + class ForceEofBit {}; + class ForceFailBit {}; + class ForceBadBit {}; + + ostream& operator<<(ostream& os, ForceEofBit) + { + os.setstate(std::ios::eofbit); + return os; + } + + ostream& operator<<(ostream& os, ForceFailBit) + { + os.setstate(std::ios::failbit); + return os; + } + + ostream& operator<<(ostream& os, ForceBadBit) + { + os.setstate(std::ios::badbit); + return os; + } +} + +void TestLogging::testBitCheck() +{ + CaptureLogOutput capture(g_logger); + + infostream << "EOF is " << ForceEofBit{} << std::endl; + infostream << "Fail is " << ForceFailBit{} << std::endl; + infostream << "Bad is " << ForceBadBit{} << std::endl; + + auto logs = capture.take(); + UASSERTEQ(size_t, logs.size(), 3); + UASSERTEQ(std::string, logs[0].text, "EOF is (ostream:eofbit)"); + UASSERTEQ(std::string, logs[1].text, "Fail is (ostream:failbit)"); + UASSERTEQ(std::string, logs[2].text, "Bad is (ostream:badbit)"); +}