Merge pull request #9521 from Icinga/noop-log-msgs

Logger: don't render log messages which will be disposed anyway

lib/base/logger.cpp

@@ -12,6 +12,7 @@
 #ifdef _WIN32
 #include "base/windowseventloglogger.hpp"
 #endif /* _WIN32 */
+#include <algorithm>
 #include <iostream>
 #include <utility>
 
@@ -35,6 +36,8 @@ bool Logger::m_ConsoleLogEnabled = true;
 std::atomic<bool> Logger::m_EarlyLoggingEnabled (true);
 bool Logger::m_TimestampEnabled = true;
 LogSeverity Logger::m_ConsoleLogSeverity = LogInformation;
+std::mutex Logger::m_UpdateMinLogSeverityMutex;
+Atomic<LogSeverity> Logger::m_MinLogSeverity (LogDebug);
 
 INITIALIZE_ONCE([]() {
 	ScriptGlobal::Set("System.LogDebug", LogDebug, true);
@@ -51,8 +54,12 @@ void Logger::Start(bool runtimeCreated)
 {
 	ObjectImpl<Logger>::Start(runtimeCreated);
 
-	std::unique_lock<std::mutex> lock(m_Mutex);
-	m_Loggers.insert(this);
+	{
+		std::unique_lock<std::mutex> lock(m_Mutex);
+		m_Loggers.insert(this);
+	}
+
+	UpdateMinLogSeverity();
 }
 
 void Logger::Stop(bool runtimeRemoved)
@@ -62,6 +69,8 @@ void Logger::Stop(bool runtimeRemoved)
 		m_Loggers.erase(this);
 	}
 
+	UpdateMinLogSeverity();
+
 	ObjectImpl<Logger>::Stop(runtimeRemoved);
 }
 
@@ -139,11 +148,15 @@ LogSeverity Logger::StringToSeverity(const String& severity)
 void Logger::DisableConsoleLog()
 {
 	m_ConsoleLogEnabled = false;
+
+	UpdateMinLogSeverity();
 }
 
 void Logger::EnableConsoleLog()
 {
 	m_ConsoleLogEnabled = true;
+
+	UpdateMinLogSeverity();
 }
 
 bool Logger::IsConsoleLogEnabled()
@@ -163,6 +176,8 @@ LogSeverity Logger::GetConsoleLogSeverity()
 
 void Logger::DisableEarlyLogging() {
 	m_EarlyLoggingEnabled = false;
+
+	UpdateMinLogSeverity();
 }
 
 bool Logger::IsEarlyLoggingEnabled() {
@@ -184,6 +199,13 @@ bool Logger::IsTimestampEnabled()
 	return m_TimestampEnabled;
 }
 
+void Logger::SetSeverity(const String& value, bool suppress_events, const Value& cookie)
+{
+	ObjectImpl<Logger>::SetSeverity(value, suppress_events, cookie);
+
+	UpdateMinLogSeverity();
+}
+
 void Logger::ValidateSeverity(const Lazy<String>& lvalue, const ValidationUtils& utils)
 {
 	ObjectImpl<Logger>::ValidateSeverity(lvalue, utils);
@@ -195,14 +217,42 @@ void Logger::ValidateSeverity(const Lazy<String>& lvalue, const ValidationUtils&
 	}
 }
 
-Log::Log(LogSeverity severity, String facility, const String& message)
-	: m_Severity(severity), m_Facility(std::move(facility))
+void Logger::UpdateMinLogSeverity()
 {
-	m_Buffer << message;
+	std::unique_lock<std::mutex> lock (m_UpdateMinLogSeverityMutex);
+	auto result (LogNothing);
+
+	for (auto& logger : Logger::GetLoggers()) {
+		ObjectLock llock (logger);
+
+		if (logger->IsActive()) {
+			result = std::min(result, logger->GetMinSeverity());
+		}
+	}
+
+	if (Logger::IsConsoleLogEnabled()) {
+		result = std::min(result, Logger::GetConsoleLogSeverity());
+	}
+
+#ifdef _WIN32
+	if (Logger::IsEarlyLoggingEnabled()) {
+		result = std::min(result, LogCritical);
+	}
+#endif /* _WIN32 */
+
+	m_MinLogSeverity.store(result);
+}
+
+Log::Log(LogSeverity severity, String facility, const String& message)
+	: Log(severity, std::move(facility))
+{
+	if (!m_IsNoOp) {
+		m_Buffer << message;
+	}
 }
 
 Log::Log(LogSeverity severity, String facility)
-	: m_Severity(severity), m_Facility(std::move(facility))
+	: m_Severity(severity), m_Facility(std::move(facility)), m_IsNoOp(severity < Logger::GetMinLogSeverity())
 { }
 
 /**
@@ -210,6 +260,10 @@ Log::Log(LogSeverity severity, String facility)
  */
 Log::~Log()
 {
+	if (m_IsNoOp) {
+		return;
+	}
+
 	LogEntry entry;
 	entry.Timestamp = Utility::GetTime();
 	entry.Severity = m_Severity;
@@ -264,6 +318,9 @@ Log::~Log()
 
 Log& Log::operator<<(const char *val)
 {
-	m_Buffer << val;
+	if (!m_IsNoOp) {
+		m_Buffer << val;
+	}
+
 	return *this;
 }

lib/base/logger.hpp

@@ -3,6 +3,7 @@
 #ifndef LOGGER_H
 #define LOGGER_H
 
+#include "base/atomic.hpp"
 #include "base/i2-base.hpp"
 #include "base/logger-ti.hpp"
 #include <set>
@@ -22,7 +23,10 @@ enum LogSeverity
 	LogNotice,
 	LogInformation,
 	LogWarning,
-	LogCritical
+	LogCritical,
+
+	// Just for internal comparision
+	LogNothing,
 };
 
 /**
@@ -76,6 +80,13 @@ public:
 	static void SetConsoleLogSeverity(LogSeverity logSeverity);
 	static LogSeverity GetConsoleLogSeverity();
 
+	static inline
+	LogSeverity GetMinLogSeverity()
+	{
+		return m_MinLogSeverity.load();
+	}
+
+	void SetSeverity(const String& value, bool suppress_events = false, const Value& cookie = Empty) override;
 	void ValidateSeverity(const Lazy<String>& lvalue, const ValidationUtils& utils) final;
 
 protected:
@@ -83,12 +94,16 @@ protected:
 	void Stop(bool runtimeRemoved) override;
 
 private:
+	static void UpdateMinLogSeverity();
+
 	static std::mutex m_Mutex;
 	static std::set<Logger::Ptr> m_Loggers;
 	static bool m_ConsoleLogEnabled;
 	static std::atomic<bool> m_EarlyLoggingEnabled;
 	static bool m_TimestampEnabled;
 	static LogSeverity m_ConsoleLogSeverity;
+	static std::mutex m_UpdateMinLogSeverityMutex;
+	static Atomic<LogSeverity> m_MinLogSeverity;
 };
 
 class Log
@@ -116,6 +131,7 @@ private:
 	LogSeverity m_Severity;
 	String m_Facility;
 	std::ostringstream m_Buffer;
+	bool m_IsNoOp;
 };
 
 extern template Log& Log::operator<<(const Value&);

lib/base/logger.ti

@@ -9,7 +9,7 @@ namespace icinga
 
 abstract class Logger : ConfigObject
 {
-	[config] String severity {
+	[config, virtual] String severity {
 		default {{{ return "information"; }}}
 	};
 };

lib/icingadb/redisconnection.cpp

@@ -115,7 +115,7 @@ void LogQuery(RedisConnection::Query& query, Log& msg)
  */
 void RedisConnection::FireAndForgetQuery(RedisConnection::Query query, RedisConnection::QueryPriority priority, QueryAffects affects)
 {
-	{
+	if (LogDebug >= Logger::GetMinLogSeverity()) {
 		Log msg (LogDebug, "IcingaDB", "Firing and forgetting query:");
 		LogQuery(query, msg);
 	}
@@ -138,9 +138,11 @@ void RedisConnection::FireAndForgetQuery(RedisConnection::Query query, RedisConn
  */
 void RedisConnection::FireAndForgetQueries(RedisConnection::Queries queries, RedisConnection::QueryPriority priority, QueryAffects affects)
 {
-	for (auto& query : queries) {
-		Log msg (LogDebug, "IcingaDB", "Firing and forgetting query:");
-		LogQuery(query, msg);
+	if (LogDebug >= Logger::GetMinLogSeverity()) {
+		for (auto& query : queries) {
+			Log msg(LogDebug, "IcingaDB", "Firing and forgetting query:");
+			LogQuery(query, msg);
+		}
 	}
 
 	auto item (Shared<Queries>::Make(std::move(queries)));
@@ -163,7 +165,7 @@ void RedisConnection::FireAndForgetQueries(RedisConnection::Queries queries, Red
  */
 RedisConnection::Reply RedisConnection::GetResultOfQuery(RedisConnection::Query query, RedisConnection::QueryPriority priority, QueryAffects affects)
 {
-	{
+	if (LogDebug >= Logger::GetMinLogSeverity()) {
 		Log msg (LogDebug, "IcingaDB", "Executing query:");
 		LogQuery(query, msg);
 	}
@@ -194,9 +196,11 @@ RedisConnection::Reply RedisConnection::GetResultOfQuery(RedisConnection::Query
  */
 RedisConnection::Replies RedisConnection::GetResultsOfQueries(RedisConnection::Queries queries, RedisConnection::QueryPriority priority, QueryAffects affects)
 {
-	for (auto& query : queries) {
-		Log msg (LogDebug, "IcingaDB", "Executing query:");
-		LogQuery(query, msg);
+	if (LogDebug >= Logger::GetMinLogSeverity()) {
+		for (auto& query : queries) {
+			Log msg(LogDebug, "IcingaDB", "Executing query:");
+			LogQuery(query, msg);
+		}
 	}
 
 	std::promise<Replies> promise;