Private/mmeeks/logfixup

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<Poco::Message::Priority>(logger().getLevel()));
- return logLevel >= static_cast<int>(l);
+
+ if (logLevel < static_cast<int>(l))
+ return false;
+
+ bool disabled = AreasDisabled[static_cast<size_t>(a)];
+
+ // Areas shouldn't disable warnings & errors
+ assert(!disabled || logLevel > static_cast<int>(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<bool> 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<Log::Area>(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);

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<sizeof(b_) - 1>(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 \

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__ \

common/Unit.cpp

@@ -231,6 +231,11 @@
  return false;
  }
 
+ // For now enable full logging
+ // FIXME: remove this when time sensitive WOPI
+ // tests are fixed.
+ Log::setDisabledAreas("");
+
  initTestSuiteOptions();
 
  // Filter tests.

coolwsd.xml.in

@@ -93,6 +93,7 @@
  -->
  <level type="string" desc="Can be 0-8 (with the lowest numbers being the least verbose), or none (turns off logging), fatal, critical, error, warning, notice, information, debug, trace" default="@COOLWSD_LOGLEVEL@">@COOLWSD_LOGLEVEL@</level>
  <level_startup type="string" desc="As for level - but for the initial startup phase which is most problematic, logging reverts to level configured above when startup is complete" default="trace">trace</level_startup>
+ <disabled_areas type="string" desc="High verbosity logging ie. info to trace are disable-able, comma separated: Generic, Socket, WebSocket, Http, WebServer, Storage, WOPI, Admin, Javascript" default="Socket,WebSocket,Admin">Socket,WebSocket,Admin</disabled_areas>
  <most_verbose_level_settable_from_client type="string" desc="A loggingleveloverride message from the client can not set a more verbose log level than this" default="notice">notice</most_verbose_level_settable_from_client>
  <least_verbose_level_settable_from_client type="string" desc="A loggingleveloverride message from a client can not set a less verbose log level than this" default="fatal">fatal</least_verbose_level_settable_from_client>
  <protocol type="bool" desc="Enable minimal client-site JS protocol logging from the start">@ENABLE_DEBUG_PROTOCOL@</protocol>

cypress_test/Makefile.am

@@ -203,7 +203,7 @@ define start_coolwsd_instance
  --o:ssl.ca_file_path="$(abs_top_srcdir)/etc/ca-chain.cert.pem" \
  --o:admin_console.username=admin --o:admin_console.password=admin \
  --o:logging.file[@enable]=true --o:logging.level=trace \
- --o:welcome.enable=false \
+ --o:logging.disabled_areas="" --o:welcome.enable=false \
  --o:user_interface.mode=$(USER_INTERFACE) \
  --o:accessibility.enable=$(A11Y_ENABLE) \
  --o:security.enable_macros_execution=true \

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<unsigned> 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"
@@ -281,9 +283,6 @@ static void cleanupChildren()
  int status = 0;
  int segFaultCount = 0;
 
- LOG_TRC("cleanupChildren with " << childJails.size()
- << (childJails.size() == 1 ? " child" : " children"));
-
  // Reap quickly without doing slow cleanup so WSD can spawn more rapidly.
  while ((exitedChildPid = waitpid(-1, &status, WUNTRACED | WNOHANG)) > 0)
  {
@@ -319,7 +318,7 @@ static void cleanupChildren()
  }
  }
 
- if (Log::traceEnabled())
+ if (Log::traceEnabled() && cleanupJailPaths.size() > 0)
  {
  std::ostringstream oss;
  for (const auto& pair : childJails)
@@ -420,8 +419,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 +444,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 +601,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<std::string, std::string> logProperties;
@@ -620,6 +619,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 +789,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

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<std::string, std::string> logProperties;
@@ -2942,13 +2946,15 @@ 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)
  {
  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