diff --git a/CHANGELOG b/CHANGELOG index 816fa43aea..fcda592c2b 100644 --- a/CHANGELOG +++ b/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 diff --git a/Documentation/Books/Manual/Administration/Configuration/Logging.md b/Documentation/Books/Manual/Administration/Configuration/Logging.md index bf9f68e0f6..e0939d9dec 100644 --- a/Documentation/Books/Manual/Administration/Configuration/Logging.md +++ b/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: diff --git a/lib/Basics/Thread.cpp b/lib/Basics/Thread.cpp index 2afd1208e3..78a472c483 100644 --- a/lib/Basics/Thread.cpp +++ b/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; } } diff --git a/lib/Basics/Thread.h b/lib/Basics/Thread.h index 3b637a6748..1b60698234 100644 --- a/lib/Basics/Thread.h +++ b/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 diff --git a/lib/Logger/LogAppender.h b/lib/Logger/LogAppender.h index cdede59eb9..fc5e5ae06d 100644 --- a/lib/Logger/LogAppender.h +++ b/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) { diff --git a/lib/Logger/LogAppenderFile.cpp b/lib/Logger/LogAppenderFile.cpp index e96551947b..519328bd45 100644 --- a/lib/Logger/LogAppenderFile.cpp +++ b/lib/Logger/LogAppenderFile.cpp @@ -39,9 +39,9 @@ std::vector> 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(len)); + ssize_t n = TRI_WRITE(_fd, buffer, static_cast(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); } } diff --git a/lib/Logger/LogAppenderFile.h b/lib/Logger/LogAppenderFile.h index d0fbed7ad1..d579f1a86d 100644 --- a/lib/Logger/LogAppenderFile.h +++ b/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; diff --git a/lib/Logger/LogAppenderSyslog.cpp b/lib/Logger/LogAppenderSyslog.cpp index adc6eac461..c7158d958a 100644 --- a/lib/Logger/LogAppenderSyslog.cpp +++ b/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() { diff --git a/lib/Logger/LogAppenderSyslog.h b/lib/Logger/LogAppenderSyslog.h index 2b45d4eece..6bbbc540ff 100644 --- a/lib/Logger/LogAppenderSyslog.h +++ b/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; diff --git a/lib/Logger/Logger.cpp b/lib/Logger/Logger.cpp index 9b420ece6b..b2988fff01 100644 --- a/lib/Logger/Logger.cpp +++ b/lib/Logger/Logger.cpp @@ -56,7 +56,9 @@ std::atomic 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 << ' '; diff --git a/lib/Logger/Logger.h b/lib/Logger/Logger.h index 871fcaa164..ef382afc45 100644 --- a/lib/Logger/Logger.h +++ b/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; diff --git a/lib/Logger/LoggerFeature.cpp b/lib/Logger/LoggerFeature.cpp index 8ebc6a8855..41facd0416 100644 --- a/lib/Logger/LoggerFeature.cpp +++ b/lib/Logger/LoggerFeature.cpp @@ -71,6 +71,9 @@ void LoggerFeature::collectOptions(std::shared_ptr options) { new VectorParameter(&_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(&_output)); @@ -108,7 +111,11 @@ void LoggerFeature::collectOptions(std::shared_ptr 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); diff --git a/lib/Logger/LoggerFeature.h b/lib/Logger/LoggerFeature.h index a3f91a09b1..eb5eb19483 100644 --- a/lib/Logger/LoggerFeature.h +++ b/lib/Logger/LoggerFeature.h @@ -47,12 +47,14 @@ class LoggerFeature final : public application_features::ApplicationFeature { private: std::vector _output; std::vector _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;