Escape backslashes when logging.

Log::MessageBuilder was already escaping most unsafe characters when
they were being logged, but plain backslashes were not. Merely updating
the existing escaping path was not sufficient, as recursion would cause
escape codes to be doubly escaped. This patches refactors the API to
ensure incoming text is escaped exactly once.

Bug: v8:8039
Change-Id: Id48aabf29fb6153189ae4a1ad7dfaaf4b41b62ad
Reviewed-on: https://chromium-review.googlesource.com/1169049Reviewed-by: Camillo Bruni <cbruni@chromium.org>
Commit-Queue: Bret Sepulveda <bsep@chromium.org>
Cr-Commit-Position: refs/heads/master@{#55038}

src/log-utils.cc

@@ -9,6 +9,7 @@
 #include "src/objects-inl.h"
 #include "src/string-stream.h"
 #include "src/utils.h"
+#include "src/vector.h"
 #include "src/version.h"
 
 namespace v8 {
@@ -87,22 +88,71 @@ Log::MessageBuilder::MessageBuilder(Log* log)
   DCHECK_NOT_NULL(log_->format_buffer_);
 }
 
+void Log::MessageBuilder::AppendString(String* str,
+                                       base::Optional<int> length_limit) {
+  if (str == nullptr) return;
+
+  DisallowHeapAllocation no_gc;  // Ensure string stays valid.
+  int length = str->length();
+  if (length_limit) length = std::min(length, *length_limit);
+  for (int i = 0; i < length; i++) {
+    uint16_t c = str->Get(i);
+    if (c <= 0xFF) {
+      AppendCharacter(static_cast<char>(c));
+    } else {
+      // Escape non-ascii characters.
+      AppendRawFormatString("\\u%04x", c & 0xFFFF);
+    }
+  }
+}
+
+void Log::MessageBuilder::AppendString(Vector<const char> str) {
+  for (auto i = str.begin(); i < str.end(); i++) AppendCharacter(*i);
+}
+
+void Log::MessageBuilder::AppendString(const char* str) {
+  if (str == nullptr) return;
+  AppendString(str, strlen(str));
+}
+
+void Log::MessageBuilder::AppendString(const char* str, size_t length) {
+  if (str == nullptr) return;
+
+  for (size_t i = 0; i < length; i++) {
+    DCHECK_NE(str[i], '\0');
+    AppendCharacter(str[i]);
+  }
+}
 
-void Log::MessageBuilder::Append(const char* format, ...) {
+void Log::MessageBuilder::AppendFormatString(const char* format, ...) {
   va_list args;
   va_start(args, format);
-  AppendVA(format, args);
+  const int length = FormatStringIntoBuffer(format, args);
   va_end(args);
+  for (int i = 0; i < length; i++) {
+    DCHECK_NE(log_->format_buffer_[i], '\0');
+    AppendCharacter(log_->format_buffer_[i]);
+  }
 }
 
-
-void Log::MessageBuilder::AppendVA(const char* format, va_list args) {
-  Vector<char> buf(log_->format_buffer_, Log::kMessageBufferSize);
-  int length = v8::internal::VSNPrintF(buf, format, args);
-  // {length} is -1 if output was truncated.
-  if (length == -1) length = Log::kMessageBufferSize;
-  DCHECK_LE(length, Log::kMessageBufferSize);
-  AppendStringPart(log_->format_buffer_, length);
+void Log::MessageBuilder::AppendCharacter(char c) {
+  if (c >= 32 && c <= 126) {
+    if (c == ',') {
+      // Escape commas to avoid adding column separators.
+      AppendRawFormatString("\\x2C");
+    } else if (c == '\\') {
+      AppendRawFormatString("\\\\");
+    } else {
+      // Safe, printable ascii character.
+      AppendRawCharacter(c);
+    }
+  } else if (c == '\n') {
+    // Escape newlines to avoid adding row separators.
+    AppendRawFormatString("\\n");
+  } else {
+    // Escape non-printable characters.
+    AppendRawFormatString("\\x%02x", c & 0xFF);
+  }
 }
 
 void Log::MessageBuilder::AppendSymbolName(Symbol* symbol) {
@@ -111,15 +161,17 @@ void Log::MessageBuilder::AppendSymbolName(Symbol* symbol) {
   os << "symbol(";
   if (!symbol->name()->IsUndefined()) {
     os << "\"";
-    AppendDetailed(String::cast(symbol->name()), false);
+    AppendSymbolNameDetails(String::cast(symbol->name()), false);
     os << "\" ";
   }
   os << "hash " << std::hex << symbol->Hash() << std::dec << ")";
 }
 
-void Log::MessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
+void Log::MessageBuilder::AppendSymbolNameDetails(String* str,
+                                                  bool show_impl_info) {
   if (str == nullptr) return;
-  DisallowHeapAllocation no_gc;  // Ensure string stay valid.
+
+  DisallowHeapAllocation no_gc;  // Ensure string stays valid.
   OFStream& os = log_->os_;
   int limit = str->length();
   if (limit > 0x1000) limit = 0x1000;
@@ -129,62 +181,32 @@ void Log::MessageBuilder::AppendDetailed(String* str, bool show_impl_info) {
     if (StringShape(str).IsInternalized()) os << '#';
     os << ':' << str->length() << ':';
   }
-  AppendStringPart(str, limit);
-}
-
-void Log::MessageBuilder::AppendString(String* str) {
-  if (str == nullptr) return;
-  int len = str->length();
-  AppendStringPart(str, len);
-}
-
-void Log::MessageBuilder::AppendString(const char* string) {
-  if (string == nullptr) return;
-  for (const char* p = string; *p != '\0'; p++) {
-    this->AppendCharacter(*p);
-  }
+  AppendString(str, limit);
 }
 
-void Log::MessageBuilder::AppendStringPart(String* str, int len) {
-  DCHECK_LE(len, str->length());
-  DisallowHeapAllocation no_gc;  // Ensure string stay valid.
-  // TODO(cbruni): unify escaping.
-  for (int i = 0; i < len; i++) {
-    uc32 c = str->Get(i);
-    if (c <= 0xFF) {
-      AppendCharacter(static_cast<char>(c));
-    } else {
-      // Escape any non-ascii range characters.
-      Append("\\u%04x", c);
-    }
-  }
+int Log::MessageBuilder::FormatStringIntoBuffer(const char* format,
+                                                va_list args) {
+  Vector<char> buf(log_->format_buffer_, Log::kMessageBufferSize);
+  int length = v8::internal::VSNPrintF(buf, format, args);
+  // |length| is -1 if output was truncated.
+  if (length == -1) length = Log::kMessageBufferSize;
+  DCHECK_LE(length, Log::kMessageBufferSize);
+  DCHECK_GE(length, 0);
+  return length;
 }
 
-void Log::MessageBuilder::AppendStringPart(const char* str, size_t len) {
-  for (size_t i = 0; i < len; i++) {
-    DCHECK_NE(str[i], '\0');
-    this->AppendCharacter(str[i]);
+void Log::MessageBuilder::AppendRawFormatString(const char* format, ...) {
+  va_list args;
+  va_start(args, format);
+  const int length = FormatStringIntoBuffer(format, args);
+  va_end(args);
+  for (int i = 0; i < length; i++) {
+    DCHECK_NE(log_->format_buffer_[i], '\0');
+    AppendRawCharacter(log_->format_buffer_[i]);
   }
 }
 
-void Log::MessageBuilder::AppendCharacter(char c) {
-  OFStream& os = log_->os_;
-  // A log entry (separate by commas) cannot contain commas or line-breaks.
-  if (c >= 32 && c <= 126) {
-    if (c == ',') {
-      // Escape commas (log field separator) directly.
-      os << "\\x2C";
-    } else {
-      // Directly append any printable ascii character.
-      os << c;
-    }
-  } else if (c == '\n') {
-    os << "\\n";
-  } else {
-    // Escape any non-printable characters.
-    Append("\\x%02x", c);
-  }
-}
+void Log::MessageBuilder::AppendRawCharacter(char c) { log_->os_ << c; }
 
 void Log::MessageBuilder::WriteToLogFile() { log_->os_ << std::endl; }
 
@@ -235,7 +257,8 @@ Log::MessageBuilder& Log::MessageBuilder::operator<<<Name*>(Name* name) {
 template <>
 Log::MessageBuilder& Log::MessageBuilder::operator<<<LogSeparator>(
     LogSeparator separator) {
-  log_->os_ << ',';
+  // Skip escaping to create a new column.
+  this->AppendRawCharacter(',');
   return *this;
 }
 

src/log-utils.h

@@ -11,6 +11,7 @@
 
 #include "src/allocation.h"
 #include "src/base/compiler-specific.h"
+#include "src/base/optional.h"
 #include "src/base/platform/mutex.h"
 #include "src/flags.h"
 #include "src/ostreams.h"
@@ -19,6 +20,8 @@ namespace v8 {
 namespace internal {
 
 class Logger;
+template <typename T>
+class Vector;
 
 enum class LogSeparator { kSeparator };
 
@@ -53,8 +56,8 @@ class Log {
   static const char* const kLogToTemporaryFile;
   static const char* const kLogToConsole;
 
-  // Utility class for formatting log messages. It fills the message into the
-  // static buffer in Log.
+  // Utility class for formatting log messages. It escapes the given messages
+  // and then appends them to the static buffer in Log.
   class MessageBuilder BASE_EMBEDDED {
    public:
     // Create a message builder starting from position 0.
@@ -62,26 +65,15 @@ class Log {
     explicit MessageBuilder(Log* log);
     ~MessageBuilder() { }
 
-    // Append string data to the log message.
-    void PRINTF_FORMAT(2, 3) Append(const char* format, ...);
-
-    // Append string data to the log message.
-    void PRINTF_FORMAT(2, 0) AppendVA(const char* format, va_list args);
-
+    void AppendString(String* str,
+                      base::Optional<int> length_limit = base::nullopt);
+    void AppendString(Vector<const char> str);
+    void AppendString(const char* str);
+    void AppendString(const char* str, size_t length);
+    void PRINTF_FORMAT(2, 3) AppendFormatString(const char* format, ...);
+    void AppendCharacter(char c);
     void AppendSymbolName(Symbol* symbol);
 
-    void AppendDetailed(String* str, bool show_impl_info);
-
-    // Append and escape a full string.
-    void AppendString(String* source);
-    void AppendString(const char* string);
-
-    // Append and escpae a portion of a string.
-    void AppendStringPart(String* source, int len);
-    void AppendStringPart(const char* str, size_t len);
-
-    void AppendCharacter(const char character);
-
     // Delegate insertion to the underlying {log_}.
     // All appended strings are escaped to maintain one-line log entries.
     template <typename T>
@@ -94,6 +86,16 @@ class Log {
     void WriteToLogFile();
 
    private:
+    // Prints the format string into |log_->format_buffer_|. Returns the length
+    // of the result, or kMessageBufferSize if it was truncated.
+    int PRINTF_FORMAT(2, 0)
+        FormatStringIntoBuffer(const char* format, va_list args);
+
+    void AppendSymbolNameDetails(String* str, bool show_impl_info);
+
+    void PRINTF_FORMAT(2, 3) AppendRawFormatString(const char* format, ...);
+    void AppendRawCharacter(const char character);
+
     Log* log_;
     base::LockGuard<base::Mutex> lock_guard_;
   };

src/log.cc

@@ -127,21 +127,10 @@ class CodeEventLogger::NameBuffer {
 
   void AppendString(String* str) {
     if (str == nullptr) return;
-    int uc16_length = Min(str->length(), kUtf16BufferSize);
-    String::WriteToFlat(str, utf16_buffer, 0, uc16_length);
-    int previous = unibrow::Utf16::kNoPreviousCharacter;
-    for (int i = 0; i < uc16_length && utf8_pos_ < kUtf8BufferSize; ++i) {
-      uc16 c = utf16_buffer[i];
-      if (c <= unibrow::Utf8::kMaxOneByteChar) {
-        utf8_buffer_[utf8_pos_++] = static_cast<char>(c);
-      } else {
-        int char_length = unibrow::Utf8::Length(c, previous);
-        if (utf8_pos_ + char_length > kUtf8BufferSize) break;
-        unibrow::Utf8::Encode(utf8_buffer_ + utf8_pos_, c, previous);
-        utf8_pos_ += char_length;
-      }
-      previous = c;
-    }
+    int length = 0;
+    std::unique_ptr<char[]> c_str =
+        str->ToCString(DISALLOW_NULLS, ROBUST_STRING_TRAVERSAL, &length);
+    AppendBytes(c_str.get(), length);
   }
 
   void AppendBytes(const char* bytes, int size) {
@@ -188,7 +177,6 @@ class CodeEventLogger::NameBuffer {
 
   int utf8_pos_;
   char utf8_buffer_[kUtf8BufferSize];
-  uc16 utf16_buffer[kUtf16BufferSize];
 };
 
 CodeEventLogger::CodeEventLogger(Isolate* isolate)
@@ -1023,7 +1011,7 @@ void Logger::UncheckedIntPtrTEvent(const char* name, intptr_t value) {
   if (!log_->IsEnabled()) return;
   Log::MessageBuilder msg(log_);
   msg << name << kNext;
-  msg.Append("%" V8PRIdPTR, value);
+  msg.AppendFormatString("%" V8PRIdPTR, value);
   msg.WriteToLogFile();
 }
 
@@ -1283,7 +1271,7 @@ void Logger::CodeCreateEvent(CodeEventListener::LogEventsAndTags tag,
   if (name.is_empty()) {
     msg << "<unknown wasm>";
   } else {
-    msg.AppendStringPart(name.start(), name.length());
+    msg.AppendString(name);
   }
   // We have to add two extra fields that allow the tick processor to group
   // events for the same wasm function, even if it gets compiled again. For
@@ -1499,7 +1487,8 @@ void Logger::ResourceEvent(const char* name, const char* tag) {
   if (base::OS::GetUserTime(&sec, &usec) != -1) {
     msg << sec << kNext << usec << kNext;
   }
-  msg.Append("%.0f", V8::GetCurrentPlatform()->CurrentClockTimeMillis());
+  msg.AppendFormatString("%.0f",
+                         V8::GetCurrentPlatform()->CurrentClockTimeMillis());
   msg.WriteToLogFile();
 }
 
@@ -1545,7 +1534,7 @@ void Logger::FunctionEvent(const char* reason, int script_id, double time_delta,
   AppendFunctionMessage(msg, reason, script_id, time_delta, start_position,
                         end_position, &timer_);
   if (function_name_length > 0) {
-    msg.AppendStringPart(function_name, function_name_length);
+    msg.AppendString(function_name, function_name_length);
   }
   msg.WriteToLogFile();
 }

test/mjsunit/tools/csvparser.js

@@ -84,3 +84,7 @@ assertEquals(
 assertEquals(
     ['code-creation','Function','0x42f0a0','163','""'],
     parser.parseLine('code-creation,Function,0x42f0a0,163,""'));
+
+assertEquals(
+    ['foo C:\\Users\\someuser\\script.js:1:13'],
+    parser.parseLine('foo C:\\\\Users\\\\someuser\\\\script.js:1:13'));

tools/csvparser.js

@@ -49,6 +49,9 @@ class CsvParser {
       if (escapeIdentifier == 'n') {
         result += '\n';
         nextPos = pos;
+      } else if (escapeIdentifier == '\\') {
+        result += '\\';
+        nextPos = pos;
       } else {
         if (escapeIdentifier == 'x') {
           // \x00 ascii range escapes consume 2 chars.