From 9b6ab4c601923dd2ed14a23e5c0218a331b5b6a5 Mon Sep 17 00:00:00 2001 From: Michael Meeks Date: Fri, 10 May 2024 11:59:18 +0100 Subject: [PATCH] Logging: add Area parameter and new LOGA_ macros to annotate areas. Add logging.disabled_areas setting to coolwsd.xml with some sensible things to ignore unless they are warnings/errors. Kit code duplication around logging is grim; but not fixed in this commit. Signed-off-by: Michael Meeks Change-Id: I36bebb2b3c8d64a814d7b10c167d582de0baf4e5 --- common/Log.cpp | 38 +++++++++++++++++++++++-- common/Log.hpp | 67 +++++++++++++++++++++++++++++--------------- common/StateEnum.hpp | 1 + coolwsd.xml.in | 1 + kit/ForKit.cpp | 10 +++++-- kit/Kit.cpp | 7 +++++ wsd/COOLWSD.cpp | 5 ++++ wsd/COOLWSD.hpp | 1 + 8 files changed, 103 insertions(+), 27 deletions(-) diff --git a/common/Log.cpp b/common/Log.cpp index 881d4baae..dba96986a 100644 --- a/common/Log.cpp +++ b/common/Log.cpp @@ -50,6 +50,9 @@ constexpr int LOG_FILE_FD = STDERR_FILENO; } // namespace +/// Which log areas should be disabled +bool AreasDisabled[Log::AreaMax] = { false, }; + /// Wrapper to expose protected 'log' and genericise class GenericLogger : public Poco::Logger { @@ -665,14 +668,23 @@ namespace Log &GenericLogger::get(Static.getInited() ? Static.getName() : std::string())); } - bool isEnabled(Level l) + bool isEnabled(Level l, Area a) { if (IsShutdown) return false; Log::Level logLevel = GenericLogger::mapToLevel( static_cast(logger().getLevel())); - return logLevel >= static_cast(l); + + if (logLevel < static_cast(l)) + return false; + + bool disabled = AreasDisabled[static_cast(a)]; + + // Areas shouldn't disable warnings & errors + assert(!disabled || logLevel > static_cast(Level::WRN)); + + return !disabled; } void shutdown() @@ -730,6 +742,28 @@ namespace Log // Update our public flags in the array now ... } + /// Set disabled areas + void setDisabledAreas(const std::string &areaStr) + { + if (areaStr != "") + LOG_INF("Setting disabled log areas to [" << areaStr << "]"); + StringVector areas = StringVector::tokenize(areaStr, ','); + std::vector enabled(Log::AreaMax, true); + for (size_t t = 0; t < areas.size(); ++t) + { + for (size_t i = 0; i < Log::AreaMax; ++i) + { + if (areas.equals(t, nameShort(static_cast(i)))) + { + enabled[i] = false; + break; + } + } + } + for (size_t i = 0; i < Log::AreaMax; ++i) + AreasDisabled[i] = !enabled[i]; + } + void log(Level l, const std::string &text) { Log::logger().doLog(l, text); diff --git a/common/Log.hpp b/common/Log.hpp index fe9f5ad03..fab764b17 100644 --- a/common/Log.hpp +++ b/common/Log.hpp @@ -28,6 +28,7 @@ #endif #include "Util.hpp" +#include "StateEnum.hpp" namespace Log { @@ -44,6 +45,18 @@ namespace Log MAX }; + // Different logging domains + STATE_ENUM(Area, + Generic, + Socket, + WebSocket, + Http, + WebServer, + Storage, + WOPI, + Admin, + Javascript); + /// Initialize the logging system. void initialize(const std::string& name, const std::string& logLevel, @@ -73,7 +86,7 @@ namespace Log } /// is a certain level of logging enabled ? - bool isEnabled(Level l); + bool isEnabled(Level l, Area a = Area::Generic); inline bool traceEnabled() { @@ -86,6 +99,9 @@ namespace Log /// Setting the logging level void setLevel(const std::string &l); + /// Set disabled areas + void setDisabledAreas(const std::string &areas); + /// Getting the logging level Level getLevel(); @@ -171,17 +187,17 @@ static constexpr std::size_t skipPathPrefix(const char (&s)[N], std::size_t n = LOG.flush(); \ } while (false) -#define LOG_MESSAGE_(LVL, X, PREFIX, SUFFIX) \ +#define LOG_MESSAGE_(LVL, A, X, PREFIX, SUFFIX) \ do \ { \ - if (LOG_CONDITIONAL(LVL)) \ + if (LOG_CONDITIONAL(LVL, A)) \ { \ - LOG_BODY_(LVL, X, PREFIX, SUFFIX); \ + LOG_BODY_(LVL, X, PREFIX, SUFFIX); \ } \ } while (false) -#define LOG_BODY_(LVL, X, PREFIX, END) \ +#define LOG_BODY_(LVL, X, PREFIX, END) \ char b_[1024]; \ std::ostringstream oss_( \ Log::prefix(b_, #LVL), \ @@ -202,19 +218,26 @@ static constexpr std::size_t skipPathPrefix(const char (&s)[N], std::size_t n = Log::log(Log::Level::INF, oss_.str()); #if defined __GNUC__ || defined __clang__ -# define LOG_CONDITIONAL(type) \ - __builtin_expect(Log::isEnabled(Log::Level::type), 0) +# define LOG_CONDITIONAL(type, area) \ + __builtin_expect(Log::isEnabled(Log::Level::type, Log::Area::area), 0) #else -# define LOG_CONDITIONAL(type) Log::isEnabled(Log::Level::type) +# define LOG_CONDITIONAL(type) Log::isEnabled(Log::Level::type, Log::Level::area) #endif -#define LOG_TRC(X) LOG_MESSAGE_(TRC, X, logPrefix, LOG_END) -#define LOG_TRC_NOFILE(X) LOG_MESSAGE_(TRC, X, logPrefix, LOG_END_NOFILE) -#define LOG_DBG(X) LOG_MESSAGE_(DBG, X, logPrefix, LOG_END) -#define LOG_INF(X) LOG_MESSAGE_(INF, X, logPrefix, LOG_END) -#define LOG_INF_NOFILE(X) LOG_MESSAGE_(INF, X, logPrefix, LOG_END_NOFILE) -#define LOG_WRN(X) LOG_MESSAGE_(WRN, X, logPrefix, LOG_END) -#define LOG_ERR(X) LOG_MESSAGE_(ERR, X, logPrefix, LOG_END) +#define LOG_TRC(X) LOGA_TRC(Generic, X) +#define LOG_TRC_NOFILE(X) LOGA_TRC_NOFILE(Generic, X) +#define LOG_DBG(X) LOGA_DBG(Generic, X) +#define LOG_INF(X) LOGA_INF(Generic, X) +#define LOG_INF_NOFILE(X) LOGA_INF_NOFILE(Generic, X) +#define LOG_WRN(X) LOG_MESSAGE_(WRN, Generic, X, logPrefix, LOG_END) +#define LOG_ERR(X) LOG_MESSAGE_(ERR, Generic, X, logPrefix, LOG_END) + +#define LOGA_TRC(A,X) LOG_MESSAGE_(TRC, A, X, logPrefix, LOG_END) +#define LOGA_TRC_NOFILE(A,X) LOG_MESSAGE_(TRC, A, X, logPrefix, LOG_END_NOFILE) +#define LOGA_DBG(A,X) LOG_MESSAGE_(DBG, A, X, logPrefix, LOG_END) +#define LOGA_INF(A,X) LOG_MESSAGE_(INF, A, X, logPrefix, LOG_END) +#define LOGA_INF_NOFILE(A,X) LOG_MESSAGE_(INF, A, X, logPrefix, LOG_END_NOFILE) +// WRN and ERR should not be filtered by area /// Log an ERR entry with the given errno appended. #define LOG_SYS_ERRNO(ERRNO, X) \ @@ -233,9 +256,9 @@ static constexpr std::size_t skipPathPrefix(const char (&s)[N], std::size_t n = do \ { \ std::cerr << X << std::endl; \ - if (LOG_CONDITIONAL(FTL)) \ + if (LOG_CONDITIONAL(FTL, Generic)) \ { \ - LOG_BODY_(FTL, X, logPrefix, LOG_END); \ + LOG_BODY_(FTL, X, logPrefix, LOG_END); \ } \ } while (false) @@ -249,11 +272,11 @@ static constexpr std::size_t skipPathPrefix(const char (&s)[N], std::size_t n = } while (false) /// No-prefix versions: -#define LOG_TRC_S(X) LOG_MESSAGE_(TRC, X, (void), LOG_END) -#define LOG_DBG_S(X) LOG_MESSAGE_(DBG, X, (void), LOG_END) -#define LOG_INF_S(X) LOG_MESSAGE_(INF, X, (void), LOG_END) -#define LOG_WRN_S(X) LOG_MESSAGE_(WRN, X, (void), LOG_END) -#define LOG_ERR_S(X) LOG_MESSAGE_(ERR, X, (void), LOG_END) +#define LOG_TRC_S(X) LOG_MESSAGE_(TRC, Generic, X, (void), LOG_END) +#define LOG_DBG_S(X) LOG_MESSAGE_(DBG, Generic, X, (void), LOG_END) +#define LOG_INF_S(X) LOG_MESSAGE_(INF, Generic, X, (void), LOG_END) +#define LOG_WRN_S(X) LOG_MESSAGE_(WRN, Generic, X, (void), LOG_END) +#define LOG_ERR_S(X) LOG_MESSAGE_(ERR, Generic, X, (void), LOG_END) #define LOG_CHECK(X) \ do \ diff --git a/common/StateEnum.hpp b/common/StateEnum.hpp index 2fe93cb63..35b4ced77 100644 --- a/common/StateEnum.hpp +++ b/common/StateEnum.hpp @@ -77,6 +77,7 @@ { \ return name(e); \ } \ + static const size_t NAME##Max = COUNT_ARGS(__VA_ARGS__); \ enum class NAME : char \ { \ __VA_ARGS__ \ diff --git a/coolwsd.xml.in b/coolwsd.xml.in index 6497ba50b..258fbedaa 100644 --- a/coolwsd.xml.in +++ b/coolwsd.xml.in @@ -93,6 +93,7 @@ --> @COOLWSD_LOGLEVEL@ trace + Socket,WebSocket,Admin notice fatal @ENABLE_DEBUG_PROTOCOL@ diff --git a/kit/ForKit.cpp b/kit/ForKit.cpp index 30a6182a0..6e27410a5 100644 --- a/kit/ForKit.cpp +++ b/kit/ForKit.cpp @@ -63,6 +63,7 @@ static std::string UserInterface; static bool DisplayVersion = false; static std::string UnitTestLibrary; static std::string LogLevel; +static std::string LogDisabledAreas; static std::string LogLevelStartup; static std::atomic ForkCounter(0); @@ -82,6 +83,7 @@ void dump_forkit_state() oss << "Forkit: " << ForkCounter << " forks\n" << " LogLevel: " << LogLevel << "\n" + << " LogDisabledAreas: " << LogDisabledAreas << "\n" << " LogLevelStartup: " << LogLevelStartup << "\n" << " unit test: " << UnitTestLibrary << "\n" << " NoCapsForKit: " << NoCapsForKit << "\n" @@ -420,8 +422,9 @@ static int createLibreOfficeKit(const std::string& childRoot, pid = fork(); if (!pid) { - // Child + sleepForDebugger(); + // Child Log::postFork(); // sort out thread local variables to get logging right from @@ -444,8 +447,6 @@ static int createLibreOfficeKit(const std::string& childRoot, UnitKit::get().postFork(); - sleepForDebugger(); - lokit_main(childRoot, jailId, sysTemplate, loTemplate, NoCapsForKit, NoSeccomp, queryVersion, DisplayVersion, spareKitId); } @@ -603,6 +604,7 @@ int forkit_main(int argc, char** argv) const bool logToFile = std::getenv("COOL_LOGFILE"); const char* logFilename = std::getenv("COOL_LOGFILENAME"); const char* logLevel = std::getenv("COOL_LOGLEVEL"); + const char* logDisabledAreas = std::getenv("COOL_LOGDISABLED_AREAS"); const char* logLevelStartup = std::getenv("COOL_LOGLEVEL_STARTUP"); const char* logColor = std::getenv("COOL_LOGCOLOR"); std::map logProperties; @@ -620,6 +622,7 @@ int forkit_main(int argc, char** argv) LOG_INF("Setting log-level to [" << LogLevelStartup << " and delaying " "setting to configured [" << LogLevel << "] until after Forkit initialization."); } + LogDisabledAreas = logDisabledAreas ? logDisabledAreas : ""; std::string childRoot; std::string sysTemplate; @@ -789,6 +792,7 @@ int forkit_main(int argc, char** argv) LOG_INF("Forkit initialization complete: setting log-level to [" << LogLevel << "] as configured."); Log::setLevel(LogLevel); } + Log::setDisabledAreas(LogDisabledAreas); // The SocketPoll ctor which may, depending on COOL_WATCHDOG env variable, // want to override the SIG2 handler so set user signal handlers before diff --git a/kit/Kit.cpp b/kit/Kit.cpp index 36053dea7..6dde24ba6 100644 --- a/kit/Kit.cpp +++ b/kit/Kit.cpp @@ -2926,10 +2926,14 @@ void lokit_main( SigUtil::setUserSignals(); } + // Are we the first ever kit ? if so, we havn't tweaked our logging by + // the time we get here; FIXME: much of this is un-necessary duplication. + // Reinitialize logging when forked. const bool logToFile = std::getenv("COOL_LOGFILE"); const char* logFilename = std::getenv("COOL_LOGFILENAME"); const char* logLevel = std::getenv("COOL_LOGLEVEL"); + const char* logDisabledAreas = std::getenv("COOL_LOGDISABLED_AREAS"); const char* logLevelStartup = std::getenv("COOL_LOGLEVEL_STARTUP"); const bool logColor = config::getBool("logging.color", true) && isatty(fileno(stderr)); std::map logProperties; @@ -2942,6 +2946,7 @@ void lokit_main( const std::string LogLevel = logLevel ? logLevel : "trace"; const std::string LogLevelStartup = logLevelStartup ? logLevelStartup : "trace"; + const bool bTraceStartup = (std::getenv("COOL_TRACE_STARTUP") != nullptr); Log::initialize("kit", bTraceStartup ? LogLevelStartup : logLevel, logColor, logToFile, logProperties); if (bTraceStartup && LogLevel != LogLevelStartup) @@ -2949,6 +2954,7 @@ void lokit_main( LOG_INF("Setting log-level to [" << LogLevelStartup << "] and delaying " "setting to [" << LogLevel << "] until after Kit initialization."); } + const std::string LogDisabledAreas = logDisabledAreas ? logDisabledAreas : ""; const char* pAnonymizationSalt = std::getenv("COOL_ANONYMIZATION_SALT"); if (pAnonymizationSalt) @@ -3351,6 +3357,7 @@ void lokit_main( LOG_INF("Kit initialization complete: setting log-level to [" << LogLevel << "] as configured."); Log::setLevel(LogLevel); } + Log::setDisabledAreas(LogDisabledAreas); #endif #ifndef IOS diff --git a/wsd/COOLWSD.cpp b/wsd/COOLWSD.cpp index 8f0c48b9f..1bc2723bb 100644 --- a/wsd/COOLWSD.cpp +++ b/wsd/COOLWSD.cpp @@ -720,6 +720,7 @@ bool COOLWSD::EnableAccessibility = false; FILE *COOLWSD::TraceEventFile = NULL; std::string COOLWSD::LogLevel = "trace"; std::string COOLWSD::LogLevelStartup = "trace"; +std::string COOLWSD::LogDisabledAreas = "Socket,WebSocket,Admin"; std::string COOLWSD::LogToken; std::string COOLWSD::MostVerboseLogLevelSettableFromClient = "notice"; std::string COOLWSD::LeastVerboseLogLevelSettableFromClient = "fatal"; @@ -2177,10 +2178,12 @@ void COOLWSD::innerInitialize(Application& self) // Set the log-level after complete initialization to force maximum details at startup. LogLevel = getConfigValue(conf, "logging.level", "trace"); + LogDisabledAreas = getConfigValue(conf, "logging.disabled_areas", "Socket,WebSocket,Admin"); MostVerboseLogLevelSettableFromClient = getConfigValue(conf, "logging.most_verbose_level_settable_from_client", "notice"); LeastVerboseLogLevelSettableFromClient = getConfigValue(conf, "logging.least_verbose_level_settable_from_client", "fatal"); setenv("COOL_LOGLEVEL", LogLevel.c_str(), true); + setenv("COOL_LOGDISABLED_AREAS", LogDisabledAreas.c_str(), true); #if !ENABLE_DEBUG const std::string salLog = getConfigValue(conf, "logging.lokit_sal_log", "-INFO-WARN"); @@ -3944,6 +3947,7 @@ public: << "\n ConfigFile: " << COOLWSD::ConfigFile << "\n ConfigDir: " << COOLWSD::ConfigDir << "\n LogLevel: " << COOLWSD::LogLevel + << "\n LogDisabledAreas: " << COOLWSD::LogDisabledAreas << "\n AnonymizeUserData: " << (COOLWSD::AnonymizeUserData ? "yes" : "no") << "\n CheckCoolUser: " << (COOLWSD::CheckCoolUser ? "yes" : "no") << "\n IsProxyPrefixEnabled: " << (COOLWSD::IsProxyPrefixEnabled ? "yes" : "no") @@ -4279,6 +4283,7 @@ int COOLWSD::innerMain() LOG_INF("WSD initialization complete: setting log-level to [" << LogLevel << "] as configured."); Log::setLevel(LogLevel); } + Log::setDisabledAreas(LogDisabledAreas); if (Log::getLevel() >= Log::Level::INF) LOG_ERR("Log level is set very high to '" << LogLevel << "' this will have a " diff --git a/wsd/COOLWSD.hpp b/wsd/COOLWSD.hpp index 3e8951e76..be38ef82e 100644 --- a/wsd/COOLWSD.hpp +++ b/wsd/COOLWSD.hpp @@ -281,6 +281,7 @@ public: static void writeTraceEventRecording(const std::string &recording); static std::string LogLevel; static std::string LogLevelStartup; + static std::string LogDisabledAreas; static std::string LogToken; static std::string MostVerboseLogLevelSettableFromClient; static std::string LeastVerboseLogLevelSettableFromClient;