Ensure that null C strings do not break logging (#15255)

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())
+	std::vector<LogEntry> entries = m_chat_log_buf.take();
-		chat_backend->addMessage(L"", utf8_to_wide(m_chat_log_buf.get()));
+	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");

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");
+	std::ios::iostate state = os.rdstate();
-	LogLevel log_level = Logger::stringToLevel(conf_loglev);
+	// clear error state so the stream works again
-	if (log_level == LL_MAX) {
+	os.clear();
-		warningstream << "Supplied unrecognized chat_log_level; "
+	if (state & std::ios::eofbit)
-			"showing none." << std::endl;
+		os << "(ostream:eofbit)";
-		log_level = LL_NONE;
+	if (state & std::ios::badbit)
-	}
+		os << "(ostream:badbit)";
-
+	if (state & std::ios::failbit)
-	m_logger.removeOutput(this);
+		os << "(ostream:failbit)";
-	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));
 }

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<typename T>
-	StreamProxy& operator<<(T&& arg) {
+	StreamProxy& operator<<(T&& arg)
+	{
 		if (m_os) {
+			if (!m_os->good())
+				fix_stream_state(*m_os);
 			*m_os << std::forward<T>(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<typename T>
+	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<< <const char*> ("(null)");
+		else
+			return this->operator<< <T>(std::forward<T>(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;
 };

src/log_internal.h

@@ -123,54 +123,69 @@ private:
 	std::ofstream m_stream;
 };
 
-class LogOutputBuffer : public ICombinedLogOutput {
+struct LogEntry {
-public:
+	LogLevel level;
-	LogOutputBuffer(Logger &logger) :
+	std::string timestamp;
-		m_logger(logger)
+	std::string thread_name;
-	{
+	std::string text;
-		updateLogLevel();
+	// "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 setLogLevel(LogLevel level)
-
-	void logRaw(LogLevel lev, std::string_view line);
-
-	void clear()
 	{
-		MutexAutoLock lock(m_buffer_mutex);
+		m_logger.removeOutput(this);
-		m_buffer = std::queue<std::string>();
+		m_logger.addOutputMaxLevel(this, level);
 	}
 
-	bool empty() const
+	void logRaw(LogLevel lev, std::string_view line) override
 	{
-		MutexAutoLock lock(m_buffer_mutex);
+		MutexAutoLock lock(m_mutex);
-		return m_buffer.empty();
+		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);
+		MutexAutoLock lock(m_mutex);
-		if (m_buffer.empty())
+		m_entries.emplace_back(LogEntry{lev, time, thread_name, std::string(payload_text), combined});
-			return "";
+	}
-		std::string s = std::move(m_buffer.front());
+
-		m_buffer.pop();
+	// Take the log entries currently stored, clearing the buffer.
-		return s;
+	std::vector<LogEntry> take()
+	{
+		std::vector<LogEntry> 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<std::string> 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<LogEntry> m_entries;
 };
 
+
 #ifdef __ANDROID__
 class AndroidLogOutput : public ICombinedLogOutput {
 public:

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

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)");
+}