added `--log.color` option to toggle colorful logging to terminal (#3356)

CHANGELOG

@@ -1,6 +1,10 @@
 devel
 -----
 
+* added config option `--log.color` to toggle colorful logging to terminal
+
+* added config option `--log.thread-name` to additionally log thread names 
+
 * usernames must not start with `:role:`, added new options:
     --server.authentication-timeout
     --ldap.roles-attribute-name

Documentation/Books/Manual/Administration/Configuration/Logging.md

@@ -109,7 +109,16 @@ will be printed in UTC / Zulu time. The date and time format used in logs
 is always `YYYY-MM-DD HH:MM:SS`, regardless of this setting. If UTC time
 is used, a `Z` will be appended to indicate Zulu time.
 
-### Line number
+
+### Color logging
+
+`--log.color value`
+
+Logging to terminal output is by default colored. Colorful logging can be 
+turned off by setting the value to false.
+
+
+### Source file and Line number
 
 Log line number: `--log.line-number`
 
@@ -124,9 +133,9 @@ Log prefix: `--log.prefix prefix`
 
 This option is used specify an prefix to logged text.
 
-### Thread
+### Threads
 
-Log thread identifier: `--log.thread`
+Log thread identifier: `--log.thread true`
 
 Whenever log output is generated, the process ID is written as part of the
 log information. Setting this option appends the thread id of the calling
@@ -144,9 +153,12 @@ when no thread is logged and
 
 when this command line option is set.
 
+To also log thread names, it is possible to set the `--log.thread-name`
+option. By default `--log.thread-name` is set to `false`.
+
 ### Role
 
-Log role: `--log.role`
+Log role: `--log.role true`
 
 When set to `true`, this option will make the ArangoDB logger print a single 
 character with the server's role into each logged message. The roles are: 

lib/Basics/Thread.cpp

@@ -45,6 +45,7 @@ using namespace arangodb::basics;
 ////////////////////////////////////////////////////////////////////////////////
 
 static thread_local uint64_t LOCAL_THREAD_NUMBER = 0;
+static thread_local char const* LOCAL_THREAD_NAME = nullptr;
 
 #if !defined(ARANGODB_HAVE_GETTID) && !defined(_WIN32)
 
@@ -78,6 +79,8 @@ void Thread::startThread(void* arg) {
   TRI_ASSERT(ptr != nullptr);
 
   ptr->_threadNumber = LOCAL_THREAD_NUMBER;
+  
+  LOCAL_THREAD_NAME = ptr->name().c_str();
 
   if (0 <= ptr->_affinity) {
     TRI_SetProcessorAffinity(&ptr->_thread, ptr->_affinity);
@@ -129,6 +132,13 @@ TRI_pid_t Thread::currentProcessId() {
 ////////////////////////////////////////////////////////////////////////////////
 
 uint64_t Thread::currentThreadNumber() { return LOCAL_THREAD_NUMBER; }
+  
+////////////////////////////////////////////////////////////////////////////////
+/// @brief returns the name of the current thread, if set
+/// note that this function may return a nullptr
+////////////////////////////////////////////////////////////////////////////////
+
+char const* Thread::currentThreadName() { return LOCAL_THREAD_NAME; }
 
 ////////////////////////////////////////////////////////////////////////////////
 /// @brief returns the thread id
@@ -212,6 +222,8 @@ Thread::~Thread() {
         << ". shutting down hard";
     FATAL_ERROR_ABORT();
   }
+  
+  LOCAL_THREAD_NAME = nullptr;
 }
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -431,6 +443,7 @@ void Thread::runMe() {
 
 void Thread::cleanupMe() {
   if (_deleteOnExit) {
+    LOCAL_THREAD_NAME = nullptr;
     delete this;
   }
 }

lib/Basics/Thread.h

@@ -93,6 +93,13 @@ class Thread {
   //////////////////////////////////////////////////////////////////////////////
 
   static uint64_t currentThreadNumber();
+  
+  //////////////////////////////////////////////////////////////////////////////
+  /// @brief returns the name of the current thread, if set
+  /// note that this function may return a nullptr
+  //////////////////////////////////////////////////////////////////////////////
+  
+  static char const* currentThreadName();
 
   //////////////////////////////////////////////////////////////////////////////
   /// @brief returns the thread id

lib/Logger/LogAppender.h

@@ -53,14 +53,14 @@ class LogAppender {
   virtual ~LogAppender() {}
 
  public:
-  virtual bool logMessage(LogLevel, std::string const& message,
+  virtual void logMessage(LogLevel, std::string const& message,
                           size_t offset) = 0;
 
   virtual std::string details() = 0;
 
  public:
-  bool logMessage(LogLevel level, std::string const& message) {
-    return logMessage(level, message, 0);
+  void logMessage(LogLevel level, std::string const& message) {
+    logMessage(level, message, 0);
   }
 
   bool checkContent(std::string const& message) {

lib/Logger/LogAppenderFile.cpp

@@ -39,9 +39,9 @@ std::vector<std::pair<int, std::string>> LogAppenderFile::_fds = {};
 
 LogAppenderStream::LogAppenderStream(std::string const& filename,
                                      std::string const& filter, int fd)
-    : LogAppender(filter), _bufferSize(0), _fd(fd), _isTty(false) {}
+    : LogAppender(filter), _bufferSize(0), _fd(fd), _useColors(false) {}
   
-bool LogAppenderStream::logMessage(LogLevel level, std::string const& message,
+void LogAppenderStream::logMessage(LogLevel level, std::string const& message,
                                    size_t offset) {
   // check max. required output length
   size_t const neededBufferSize = TRI_MaxLengthEscapeControlsCString(message.size());
@@ -60,7 +60,7 @@ bool LogAppenderStream::logMessage(LogLevel level, std::string const& message,
       _bufferSize = neededBufferSize * 2;
     } catch (...) {
       // if allocation fails, simply give up
-      return false;
+      return;
     }
   }
   
@@ -78,8 +78,6 @@ bool LogAppenderStream::logMessage(LogLevel level, std::string const& message,
     _buffer.reset();
     _bufferSize = 0;
   }
-
-  return _isTty;
 }
 
 LogAppenderFile::LogAppenderFile(std::string const& filename, std::string const& filter)
@@ -116,20 +114,20 @@ LogAppenderFile::LogAppenderFile(std::string const& filename, std::string const&
     }
   }
   
-  _isTty = (isatty(_fd) == 1);
+  _useColors = ((isatty(_fd) == 1) && Logger::getUseColor());
 }
 
 void LogAppenderFile::writeLogMessage(LogLevel level, char const* buffer, size_t len) {
   bool giveUp = false;
-  int fd = _fd;
 
   while (len > 0) {
-    ssize_t n = TRI_WRITE(fd, buffer, static_cast<TRI_write_t>(len));
+    ssize_t n = TRI_WRITE(_fd, buffer, static_cast<TRI_write_t>(len));
 
     if (n < 0) {
       fprintf(stderr, "cannot log data: %s\n", TRI_LAST_ERROR_STR);
-      return;  // give up, but do not try to log failure
-    } else if (n == 0) {
+      return;  // give up, but do not try to log the failure via the Logger
+    } 
+    if (n == 0) {
       if (!giveUp) {
         giveUp = true;
         continue;
@@ -141,8 +139,10 @@ void LogAppenderFile::writeLogMessage(LogLevel level, char const* buffer, size_t
   }
 
   if (level == LogLevel::FATAL) {
-    FILE* f = TRI_FDOPEN(fd, "w+");
+    FILE* f = TRI_FDOPEN(_fd, "a");
     if (f != nullptr) {
+      // valid file pointer...
+      // now flush the file one last time before we shut down
       fflush(f);
     }
   }
@@ -204,6 +204,7 @@ void LogAppenderFile::closeAll() {
     it.first = -1;
 
     if (fd > STDERR_FILENO) {
+      fsync(fd);
       TRI_TRACKED_CLOSE_FILE(fd);
     }
   }
@@ -211,7 +212,7 @@ void LogAppenderFile::closeAll() {
   
 LogAppenderStdStream::LogAppenderStdStream(std::string const& filename, std::string const& filter, int fd)
     : LogAppenderStream(filename, filter, fd) {
-  _isTty = (isatty(_fd) == 1);
+  _useColors = ((isatty(_fd) == 1) && Logger::getUseColor());
 }
 
 LogAppenderStdStream::~LogAppenderStdStream() {
@@ -221,15 +222,15 @@ LogAppenderStdStream::~LogAppenderStdStream() {
 }
   
 void LogAppenderStdStream::writeLogMessage(LogLevel level, char const* buffer, size_t len) {
-  writeLogMessage(_fd, _isTty, level, buffer, len, false);
+  writeLogMessage(_fd, _useColors, level, buffer, len, false);
 }
 
-void LogAppenderStdStream::writeLogMessage(int fd, bool isTty, LogLevel level, char const* buffer, size_t len, bool appendNewline) {
+void LogAppenderStdStream::writeLogMessage(int fd, bool useColors, LogLevel level, char const* buffer, size_t len, bool appendNewline) {
   // out stream
   FILE* fp = (fd == STDOUT_FILENO ? stdout : stderr);
   char const* nl = (appendNewline ? "\n" : "");
 
-  if (isTty) {
+  if (useColors) {
     // joyful color output
     if (level == LogLevel::FATAL || level == LogLevel::ERR) {
       fprintf(fp, "%s%s%s%s", ShellColorsFeature::SHELL_COLOR_RED, buffer, ShellColorsFeature::SHELL_COLOR_RESET, nl);
@@ -243,8 +244,12 @@ void LogAppenderStdStream::writeLogMessage(int fd, bool isTty, LogLevel level, c
     fprintf(fp, "%s%s", buffer, nl);
   }
 
-  if (level == LogLevel::FATAL || level == LogLevel::ERR || level == LogLevel::WARN) {
+  if (level == LogLevel::FATAL || level == LogLevel::ERR || 
+      level == LogLevel::WARN || level == LogLevel::INFO) {
     // flush the output so it becomes visible immediately
+    // at least for log levels that are used seldomly
+    // it would probably be overkill to flush everytime we
+    // encounter a log message for level DEBUG or TRACE
     fflush(fp);
   }
 }

lib/Logger/LogAppenderFile.h

@@ -32,7 +32,7 @@ class LogAppenderStream : public LogAppender {
   LogAppenderStream(std::string const& filename, std::string const& filter, int fd);
   ~LogAppenderStream() {}
 
-  bool logMessage(LogLevel, std::string const& message,
+  void logMessage(LogLevel, std::string const& message,
                   size_t offset) override final;
 
   virtual std::string details() override = 0;
@@ -56,8 +56,8 @@ class LogAppenderStream : public LogAppender {
   /// @brief file descriptor 
   int _fd;
   
-  /// @brief whether or not the outfile is a tty 
-  bool _isTty;
+  /// @brief whether or not we should use colors
+  bool _useColors;
 };
 
 class LogAppenderFile : public LogAppenderStream {
@@ -85,7 +85,7 @@ class LogAppenderStdStream : public LogAppenderStream {
 
   std::string details() override final { return std::string(); }
   
-  static void writeLogMessage(int fd, bool isTty, LogLevel, char const* p, size_t length, bool appendNewline);
+  static void writeLogMessage(int fd, bool useColors, LogLevel, char const* p, size_t length, bool appendNewline);
 
  private:
   void writeLogMessage(LogLevel, char const*, size_t) override final;

lib/Logger/LogAppenderSyslog.cpp

@@ -81,7 +81,7 @@ LogAppenderSyslog::LogAppenderSyslog(std::string const& facility,
   _opened = true;
 }
 
-bool LogAppenderSyslog::logMessage(LogLevel level, std::string const& message,
+void LogAppenderSyslog::logMessage(LogLevel level, std::string const& message,
                                    size_t offset) {
   int priority = LOG_ERR;
 
@@ -110,9 +110,6 @@ bool LogAppenderSyslog::logMessage(LogLevel level, std::string const& message,
   if (_opened) {
     ::syslog(priority, "%s", message.c_str() + offset);
   }
-
-  // not logging to TTY
-  return false;
 }
 
 std::string LogAppenderSyslog::details() {

lib/Logger/LogAppenderSyslog.h

@@ -37,7 +37,7 @@ class LogAppenderSyslog : public LogAppender {
   LogAppenderSyslog(std::string const& facility, std::string const& name,
                     std::string const& filter);
 
-  bool logMessage(LogLevel, std::string const& message,
+  void logMessage(LogLevel, std::string const& message,
                   size_t offset) override final;
 
   std::string details() override final;

lib/Logger/Logger.cpp

@@ -56,7 +56,9 @@ std::atomic<LogLevel> Logger::_level(LogLevel::INFO);
 bool Logger::_showLineNumber(false);
 bool Logger::_shortenFilenames(true);
 bool Logger::_showThreadIdentifier(false);
+bool Logger::_showThreadName(false);
 bool Logger::_threaded(false);
+bool Logger::_useColor(true);
 bool Logger::_useLocalTime(false);
 bool Logger::_keepLogRotate(false);
 bool Logger::_useMicrotime(false);
@@ -181,6 +183,27 @@ void Logger::setShowThreadIdentifier(bool show) {
   _showThreadIdentifier = show;
 }
 
+// NOTE: this function should not be called if the logging is active.
+void Logger::setShowThreadName(bool show) {
+  if (_active) {
+    THROW_ARANGO_EXCEPTION_MESSAGE(TRI_ERROR_INTERNAL,
+                                   "cannot change show thread name if logging is active");
+  }
+
+  _showThreadName = show;
+}
+
+// NOTE: this function should not be called if the logging is active.
+void Logger::setUseColor(bool value) {
+  if (_active) {
+    THROW_ARANGO_EXCEPTION_MESSAGE(TRI_ERROR_INTERNAL,
+                                   "cannot change color if logging is active");
+  }
+
+  _useColor = value;
+}
+
+
 // NOTE: this function should not be called if the logging is active.
 void Logger::setUseLocalTime(bool show) {
   if (_active) {
@@ -291,17 +314,23 @@ void Logger::log(char const* function, char const* file, long int line,
   }
 
   // append the process / thread identifier
-  TRI_pid_t processId = Thread::currentProcessId();
+  out << '[' << Thread::currentProcessId();
 
   if (_showThreadIdentifier) {
-    uint64_t threadNumber = Thread::currentThreadNumber();
-    snprintf(buf, sizeof(buf), "[%llu-%llu] ",
-             (unsigned long long)processId, (unsigned long long)threadNumber);
-  } else {
-    snprintf(buf, sizeof(buf), "[%llu] ",
-             (unsigned long long)processId);
+    out << '-' << Thread::currentThreadNumber();
   }
-  out << buf;
+
+  // log thread name
+  if (_showThreadName) {
+    char const* threadName =  Thread::currentThreadName();
+    if (threadName == nullptr) {
+      threadName = "main";
+    }
+   
+    out << '-' << threadName;
+  }
+
+  out << "] ";
   
   if (_showRole && _role != '\0') {
     out << _role << ' ';

lib/Logger/Logger.h

@@ -211,6 +211,9 @@ class Logger {
   static bool getShowRole() {return _showRole;};
   static void setShortenFilenames(bool);
   static void setShowThreadIdentifier(bool);
+  static void setShowThreadName(bool);
+  static void setUseColor(bool);
+  static bool getUseColor() {return _useColor;};
   static void setUseLocalTime(bool);
   static bool getUseLocalTime() {return _useLocalTime;};
   static void setUseMicrotime(bool);
@@ -248,8 +251,10 @@ class Logger {
   static bool _showLineNumber;
   static bool _shortenFilenames;
   static bool _showThreadIdentifier;
+  static bool _showThreadName;
   static bool _showRole;
   static bool _threaded;
+  static bool _useColor;
   static bool _useLocalTime;
   static bool _keepLogRotate;
   static bool _useMicrotime;

lib/Logger/LoggerFeature.cpp

@@ -71,6 +71,9 @@ void LoggerFeature::collectOptions(std::shared_ptr<ProgramOptions> options) {
                            new VectorParameter<StringParameter>(&_levels));
 
   options->addSection("log", "Configure the logging");
+  
+  options->addOption("--log.color", "use colors for TTY logging",
+                     new BooleanParameter(&_useColor));
 
   options->addOption("--log.output,-o", "log destination(s)",
                      new VectorParameter<StringParameter>(&_output));
@@ -108,7 +111,11 @@ void LoggerFeature::collectOptions(std::shared_ptr<ProgramOptions> options) {
 
   options->addHiddenOption("--log.thread",
                            "show thread identifier in log message",
-                           new BooleanParameter(&_thread));
+                           new BooleanParameter(&_threadId));
+  
+  options->addHiddenOption("--log.thread-name",
+                           "show thread name in log message",
+                           new BooleanParameter(&_threadName));
 
   options->addHiddenOption("--log.performance",
                            "shortcut for '--log.level performance=trace'",
@@ -163,11 +170,13 @@ void LoggerFeature::prepare() {
 
   Logger::setLogLevel(_levels);
   Logger::setShowRole(_showRole);
+  Logger::setUseColor(_useColor);
   Logger::setUseLocalTime(_useLocalTime);
   Logger::setUseMicrotime(_useMicrotime);
   Logger::setShowLineNumber(_lineNumber);
   Logger::setShortenFilenames(_shortenFilenames);
-  Logger::setShowThreadIdentifier(_thread);
+  Logger::setShowThreadIdentifier(_threadId);
+  Logger::setShowThreadName(_threadName);
   Logger::setOutputPrefix(_prefix);
   Logger::setKeepLogrotate(_keepLogRotate);
 

lib/Logger/LoggerFeature.h

@@ -47,12 +47,14 @@ class LoggerFeature final : public application_features::ApplicationFeature {
  private:
   std::vector<std::string> _output;
   std::vector<std::string> _levels;
-  bool _useLocalTime = false;
   std::string _prefix;
   std::string _file;
+  bool _useLocalTime = false;
+  bool _useColor = true;
   bool _lineNumber = false;
   bool _shortenFilenames = true;
-  bool _thread = false;
+  bool _threadId = false;
+  bool _threadName = false;
   bool _performance = false;
   bool _keepLogRotate = false;
   bool _foregroundTty = false;