added startup option `--log.escape` for unescaped logging (#5315)

CHANGELOG

@@ -1,6 +1,26 @@
 devel
 -----
 
+* added startup option `--log.escape`
+
+  This option toggles the escaping of log output. 
+
+  If set to `true` (which is the default value), then the logging will work
+  as before, and the following characters in the log output are escaped:
+
+  * the carriage return character (hex 0d)
+  * the newline character (hex 0a)
+  * the tabstop character (hex 09)
+  * any other characters with an ordinal value less than hex 20
+
+  If the option is set to `false`, no characters are escaped. Characters with
+  an ordinal value less than hex 20 will not be printed in this mode but will
+  be replaced with a space character (hex 20).
+
+  A side effect of turning off the escaping is that it will reduce the CPU 
+  overhead for the logging. However, this will only be noticable when logging
+  is set to a very verbose level (e.g. debug or trace).
+
 * increased the default values for the startup options `--javascript.gc-interval`
   from every 1000 to every 2000 requests, and for `--javascript.gc-frequency` from 
   30 to 60 seconds

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

@@ -110,6 +110,30 @@ 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.
 
 
+### Escaping
+
+`--log.escape value`
+
+This option toggles the escaping of log output. 
+
+If set to `true`, the following characters in the log output are escaped:
+
+* the carriage return character (hex 0d)
+* the newline character (hex 0a)
+* the tabstop character (hex 09)
+* any other characters with an ordinal value less than hex 20
+
+If the option is set to `false`, no characters are escaped. Characters with
+an ordinal value less than hex 20 will not be printed in this mode but will
+be replaced with a space character (hex 20).
+
+A side effect of turning off the escaping is that it will reduce the CPU 
+overhead for the logging. However, this will only be noticable when logging
+is set to a very verbose level (e.g. debug or trace).
+
+The default value for this option is `true`.
+
+
 ### Color logging
 
 `--log.color value`

lib/Logger/LogAppenderFile.cpp

@@ -39,12 +39,40 @@ std::vector<std::tuple<int, std::string, LogAppenderFile*>> LogAppenderFile::_fd
 
 LogAppenderStream::LogAppenderStream(std::string const& filename,
                                      std::string const& filter, int fd)
-    : LogAppender(filter), _bufferSize(0), _fd(fd), _useColors(false) {}
+    : LogAppender(filter), _bufferSize(0), _fd(fd), _useColors(false), _escape(Logger::getUseEscaped()) {}
+  
+size_t LogAppenderStream::determineOutputBufferSize(std::string const& message) const {
+  if (_escape) {
+    return TRI_MaxLengthEscapeControlsCString(message.size());
+  }
+  return message.size() + 2;
+}
+  
+size_t LogAppenderStream::writeIntoOutputBuffer(std::string const& message) {
+  if (_escape) {
+    size_t escapedLength;
+    // this is guaranteed to succeed given that we already have a buffer
+    TRI_EscapeControlsCString(message.data(), message.size(), _buffer.get(), &escapedLength, true);
+    return escapedLength;
+  }
+
+  unsigned char const* p = reinterpret_cast<unsigned char const*>(message.data());
+  unsigned char const* e = p + message.size();
+  char* s = _buffer.get();
+  char* q = s;
+  while (p < e) {
+    unsigned char c = *p++;
+    *q++ = c < 0x20 ? ' ' : c;
+  }
+  *q++ = '\n';
+  *q = '\0';
+  return q - s;
+}
   
 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());
+  size_t const neededBufferSize = determineOutputBufferSize(message);
   
   // check if we can re-use our already existing buffer
   if (neededBufferSize > _bufferSize) {
@@ -66,12 +94,10 @@ void LogAppenderStream::logMessage(LogLevel level, std::string const& message,
   
   TRI_ASSERT(_buffer != nullptr);
   
-  size_t escapedLength;
-  // this is guaranteed to succeed given that we already have a buffer
-  TRI_EscapeControlsCString(message.c_str(), message.size(), _buffer.get(), &escapedLength, true);
-  TRI_ASSERT(escapedLength <= neededBufferSize);
+  size_t length = writeIntoOutputBuffer(message);
+  TRI_ASSERT(length <= neededBufferSize);
 
-  this->writeLogMessage(level, _buffer.get(), escapedLength);
+  this->writeLogMessage(level, _buffer.get(), length);
 
   if (_bufferSize > maxBufferSize) {
     // free the buffer so the Logger is not hogging so much memory

lib/Logger/LogAppenderFile.h

@@ -42,6 +42,12 @@ class LogAppenderStream : public LogAppender {
  protected:
   void updateFd(int fd) { _fd = fd; }
 
+  // determine the required length of the output buffer for the log message
+  size_t determineOutputBufferSize(std::string const& message) const;
+  
+  // write the log message into the already allocated output buffer
+  size_t writeIntoOutputBuffer(std::string const& message);
+
   virtual void writeLogMessage(LogLevel, char const*, size_t) = 0;
 
   /// @brief maximum size for reusable log buffer
@@ -62,6 +68,9 @@ class LogAppenderStream : public LogAppender {
   
   /// @brief whether or not we should use colors
   bool _useColors;
+
+  /// @brief whether or not to escape special chars in log output
+  bool const _escape;
 };
 
 class LogAppenderFile : public LogAppenderStream {

lib/Logger/Logger.cpp

@@ -61,6 +61,7 @@ bool Logger::_showThreadIdentifier(false);
 bool Logger::_showThreadName(false);
 bool Logger::_threaded(false);
 bool Logger::_useColor(true);
+bool Logger::_useEscaped(true);
 bool Logger::_useLocalTime(false);
 bool Logger::_keepLogRotate(false);
 bool Logger::_useMicrotime(false);
@@ -208,6 +209,15 @@ void Logger::setUseColor(bool value) {
   _useColor = value;
 }
 
+// NOTE: this function should not be called if the logging is active.
+void Logger::setUseEscaped(bool value) {
+  if (_active) {
+    THROW_ARANGO_EXCEPTION_MESSAGE(TRI_ERROR_INTERNAL,
+                                   "cannot change escaping if logging is active");
+  }
+
+  _useEscaped = value;
+}
 
 // NOTE: this function should not be called if the logging is active.
 void Logger::setUseLocalTime(bool show) {
@@ -270,7 +280,7 @@ std::string const& Logger::translateLogLevel(LogLevel level) {
   return UNKNOWN;
 }
 
-void Logger::log(char const* function, char const* file, long int line,
+void Logger::log(char const* function, char const* file, int line,
                  LogLevel level, size_t topicId,
                  std::string const& message) {
 #ifdef _WIN32

lib/Logger/Logger.h

@@ -224,6 +224,8 @@ class Logger {
   static void setShowThreadName(bool);
   static void setUseColor(bool);
   static bool getUseColor() {return _useColor;};
+  static void setUseEscaped(bool);
+  static bool getUseEscaped() {return _useEscaped;};
   static void setUseLocalTime(bool);
   static bool getUseLocalTime() {return _useLocalTime;};
   static void setUseMicrotime(bool);
@@ -232,7 +234,7 @@ class Logger {
 
   static std::string const& translateLogLevel(LogLevel);
 
-  static void log(char const* function, char const* file, long int line,
+  static void log(char const* function, char const* file, int line,
                   LogLevel level, size_t topicId, std::string const& message);
 
   static bool isEnabled(LogLevel level) {
@@ -265,6 +267,7 @@ class Logger {
   static bool _showRole;
   static bool _threaded;
   static bool _useColor;
+  static bool _useEscaped;
   static bool _useLocalTime;
   static bool _keepLogRotate;
   static bool _useMicrotime;

lib/Logger/LoggerFeature.cpp

@@ -73,6 +73,9 @@ void LoggerFeature::collectOptions(std::shared_ptr<ProgramOptions> options) {
   
   options->addOption("--log.color", "use colors for TTY logging",
                      new BooleanParameter(&_useColor));
+  
+  options->addOption("--log.escape", "escape characters when logging",
+                     new BooleanParameter(&_useEscaped));
 
   options->addOption("--log.output,-o", "log destination(s)",
                      new VectorParameter<StringParameter>(&_output));
@@ -172,6 +175,7 @@ void LoggerFeature::prepare() {
   Logger::setUseColor(_useColor);
   Logger::setUseLocalTime(_useLocalTime);
   Logger::setUseMicrotime(_useMicrotime);
+  Logger::setUseEscaped(_useEscaped);
   Logger::setShowLineNumber(_lineNumber);
   Logger::setShortenFilenames(_shortenFilenames);
   Logger::setShowThreadIdentifier(_threadId);

lib/Logger/LoggerFeature.h

@@ -51,6 +51,7 @@ class LoggerFeature final : public application_features::ApplicationFeature {
   std::string _file;
   bool _useLocalTime = false;
   bool _useColor = true;
+  bool _useEscaped = true;
   bool _lineNumber = false;
   bool _shortenFilenames = true;
   bool _threadId = false;