Add formatting support for VSCode logpoints message

[yinghuitan]

Summary

https://reviews.llvm.org/D127702 adds the initial logpoints support in
lldb-vscode. This patch further improves it by:

1. Adding a newline at the end of each log message
2. Support most of the format specifiers like \t, \n, \x etc..

The implementation is borrowed from FormatEntity::ParseInternal(). Future
patch should merge these two implementations.

[clayborg]

lldb/test/API/tools/lldb-vscode/breakpoint/TestVSCode_logpoints.py

52

Are we now auto appending a newline if there isn't one? If so we need to test this functionality. We should append on if the string doesn't end with "\n" and not if it does?

lldb/tools/lldb-vscode/BreakpointBase.cpp

47–52

Please use StringRef::find(char). Something like:

Please use StringRef::find_first_of(...) instead of iterating per character. Something like:

formatted.clear();
while (!text.empty()) {
  size_t backslash_pos = text.find_first_of('\\');
  if (backslash_pos = StringRef::npos) {
    // No more backslash chars append the rest of the string
    formatted += text.str();
    return error;
  }
  // Append anything before the backslash character.
  if (backslash_pos > 0)
    formatted += text.drop_front(backslash_pos).str();

[yinghuitan]

lldb/test/API/tools/lldb-vscode/breakpoint/TestVSCode_logpoints.py

52

Yes, we are always appending a newline now. I decided not to detect if string ends with "\n" or not but always append so that the behavior can be consistent.

By removing the trailing the trailing newline in testcase here we are already testing the newline behavior right? Otherwise the testcase would fail.

lldb/tools/lldb-vscode/BreakpointBase.cpp

47–52

Ah, definitely.

[yinghuitan]

Address review comments

[clayborg]

lldb/tools/lldb-vscode/BreakpointBase.cpp

29

indentation is off here.

45

indentation is off here

53

Remove assert, this should be already tested in StringRef::find(...)

55

Is this going to append the backslash character as well? Seems like a bug. Above suggested code did this correctly I think with:

// Append anything before the backslash character.
if (backslash_pos > 0)
  formatted += text.drop_front(backslash_pos).str();

Which was always then followed by:

text = text.drop_front(); // Drop the backslash

305

I would still only push one if the output doesn't end with one and add a test for this.

if (!output.empty() && output.back() != '\n')
  output.push_back('\n'); // Ensure log message has line break.

[yinghuitan]

lldb/tools/lldb-vscode/BreakpointBase.cpp

29

Hmm, it is chosen by clang-format. I tried again it is still the same result. I will leave the decision to clang-format.

53

I know but I like to use assertion as a contract documentation here so that it is easier to reason later code. I can remove if you feel strong about it.

55

Thanks!

I wonder why the testcase did not catch it, turns out the testcase has a bug -- it uses escaped string for logmessage which did not trigger the code path at all!!
Fixed the testcase caused this bug to show up.

[yinghuitan]

lldb/tools/lldb-vscode/BreakpointBase.cpp

305

Ok, I can do this. But the existing tests (which has ending newline removed) should be testing this -- they do not have newline in log-message, but we still can correctly split-lines to get message boundary.

[yinghuitan]

Address review comments.

[clayborg]

Just a few nits and this is good to go

lldb/tools/lldb-vscode/BreakpointBase.cpp

29

no, it is fixed now, so all good.

53

I would remove it because it is already part of the StringRef::find() contract and it isn't needed.

56

[yinghuitan]

Address review comments

[clayborg]

What happens when we have a log message error? I see we log to the console, but we should test this. Also, if there is an error, do we fail the breakpoint setting completely or do we just not set the log message? We need a test for these cases.

[yinghuitan]

Add failure case testcase

lldb/test/API/tools/lldb-vscode/breakpoint/TestVSCode_logpoints.py

def test_logmessage_basic(self):
 
         # Swallow old console output
         self.get_console()
 
         # Set two breakpoints:
         # 1. First at the loop line with logMessage
         # 2. Second guard breakpoint at a line after loop
         logMessage_prefix = "This is log message for { -- "
-        # Trailing newline is needed for splitlines()
-        logMessage = logMessage_prefix + "{i + 3}\n"
+        logMessage = logMessage_prefix + "{i + 3}"
         [loop_breakpoint_id, post_loop_breakpoint_id] = self.set_source_breakpoints(
             self.main_path,
             [loop_line, after_loop_line],
             [{'logMessage': logMessage}, {}]
         )
 
         # Continue to trigger the breakpoint with log messages
         self.vscode.request_continue()
def test_logmessage_advanced(self):
 
         # Swallow old console output
         self.get_console()
 
         # Set two breakpoints:
         # 1. First at the loop line with logMessage
         # 2. Second guard breakpoint at a line after loop
         logMessage_prefix = "This is log message for { -- "
-        # Trailing newline is needed for splitlines()
-        logMessage = logMessage_prefix + "{int y = 0; if (i % 3 == 0) { y = i + 3;} else {y = i * 3;} y}\n"
+        logMessage = logMessage_prefix + "{int y = 0; if (i % 3 == 0) { y = i + 3;} else {y = i * 3;} y}"
         [loop_breakpoint_id, post_loop_breakpoint_id] = self.set_source_breakpoints(
             self.main_path,
             [loop_line, after_loop_line],
             [{'logMessage': logMessage}, {}]
         )
 
         # Continue to trigger the breakpoint with log messages
         self.vscode.request_continue()
def test_logmessage_advanced(self):
         # Verify logMessage count
         loop_count = 10
         self.assertEqual(len(logMessage_output), loop_count)
 
         # Verify log message match
         for idx, logMessage_line in enumerate(logMessage_output):
             result = idx + 3 if idx % 3 == 0 else idx * 3
             self.assertEqual(logMessage_line, logMessage_prefix + str(result))
+
+    @skipIfWindows
+    @skipIfRemote
+    def test_logmessage_format(self):
+        '''
+            Tests breakpoint logmessage functionality with format.
+        '''
+        before_loop_line = line_number('main.cpp', '// before loop')
+        loop_line = line_number('main.cpp', '// break loop')
+        after_loop_line = line_number('main.cpp', '// after loop')
+
+        program = self.getBuildArtifact("a.out")
+        self.build_and_launch(program)
+
+        # Set a breakpoint at a line before loop
+        before_loop_breakpoint_ids = self.set_source_breakpoints(
+            self.main_path,
+            [before_loop_line])
+        self.assertEquals(len(before_loop_breakpoint_ids), 1, "expect one breakpoint")
+
+        self.vscode.request_continue()
+
+        # Verify we hit the breakpoint before loop line
+        self.verify_breakpoint_hit(before_loop_breakpoint_ids)
+
+        # Swallow old console output
+        self.get_console()
+
+        # Set two breakpoints:
+        # 1. First at the loop line with logMessage
+        # 2. Second guard breakpoint at a line after loop
+        logMessage_prefix = "This is log message for -- "
+        logMessage_with_format = "part1\tpart2\bpart3\x64part4"
+        logMessage_with_format_raw = r"part1\tpart2\bpart3\x64part4"
+        logMessage = logMessage_prefix + logMessage_with_format_raw + "{i - 1}"
+        [loop_breakpoint_id, post_loop_breakpoint_id] = self.set_source_breakpoints(
+            self.main_path,
+            [loop_line, after_loop_line],
+            [{'logMessage': logMessage}, {}]
+        )
+
+        # Continue to trigger the breakpoint with log messages
+        self.vscode.request_continue()
+
+        # Verify we hit the breakpoint after loop line
+        self.verify_breakpoint_hit([post_loop_breakpoint_id])
+
+        output = self.get_console()
+        lines = output.splitlines()
+        logMessage_output = []
+        for line in lines:
+            if line.startswith(logMessage_prefix):
+                logMessage_output.append(line)
+
+        # Verify logMessage count
+        loop_count = 10
+        self.assertEqual(len(logMessage_output), loop_count)
+
+        # Verify log message match
+        for idx, logMessage_line in enumerate(logMessage_output):
+            result = idx - 1
+            self.assertEqual(logMessage_line, logMessage_prefix + logMessage_with_format + str(result))
+
+
+    @skipIfWindows
+    @skipIfRemote
+    def test_logmessage_format_failure(self):
+        '''
+            Tests breakpoint logmessage format with parsing failure.
+        '''
+        before_loop_line = line_number('main.cpp', '// before loop')
+        loop_line = line_number('main.cpp', '// break loop')
+        after_loop_line = line_number('main.cpp', '// after loop')
+
+        program = self.getBuildArtifact("a.out")
+        self.build_and_launch(program)
+
+        # Set a breakpoint at a line before loop
+        before_loop_breakpoint_ids = self.set_source_breakpoints(
+            self.main_path,
+            [before_loop_line])
+        self.assertEquals(len(before_loop_breakpoint_ids), 1, "expect one breakpoint")
+
+        self.vscode.request_continue()
+
+        # Verify we hit the breakpoint before loop line
+        self.verify_breakpoint_hit(before_loop_breakpoint_ids)
+
+        # Swallow old console output
+        self.get_console()
+
+        # Set two breakpoints:
+        # 1. First at the loop line with logMessage
+        # 2. Second guard breakpoint at a line after loop
+        logMessage_prefix = "This is log message for -- "
+        # log message missing hex number.
+        logMessage_with_format_raw = r"part1\x"
+        logMessage = logMessage_prefix + logMessage_with_format_raw
+        [loop_breakpoint_id, post_loop_breakpoint_id] = self.set_source_breakpoints(
+            self.main_path,
+            [loop_line, after_loop_line],
+            [{'logMessage': logMessage}, {}]
+        )
+
+        # Continue to trigger the breakpoint with log messages
+        self.vscode.request_continue()
+
+        # Verify we hit logpoint breakpoint if it's format has error.
+        self.verify_breakpoint_hit([loop_breakpoint_id])
+
+        output = self.get_console()
+        lines = output.splitlines()
+
+        failure_prefix = "Log message has error:"
+        logMessage_output = []
+        logMessage_failure_output = []
+        for line in lines:
+            if line.startswith(logMessage_prefix):
+                logMessage_output.append(line)
+            elif line.startswith(failure_prefix):
+                logMessage_failure_output.append(line)
+
+        # Verify logMessage failure message
+        self.assertEqual(len(logMessage_failure_output), 1)
+        self.assertEqual(
+            logMessage_failure_output[0].strip(),
+            failure_prefix + " missing hex number following '\\x'")

lldb/tools/lldb-vscode/BreakpointBase.h

 
 namespace lldb_vscode {
 
 struct BreakpointBase {
   // logMessage part can be either a raw text or an expression.
   struct LogMessagePart {
     LogMessagePart(llvm::StringRef text, bool is_expr)
         : text(text), is_expr(is_expr) {}
-    llvm::StringRef text;
+    std::string text;
     bool is_expr;
   };
   // An optional expression for conditional breakpoints.
   std::string condition;
   // An optional expression that controls how many hits of the breakpoint are
   // ignored. The backend is expected to interpret the expression as needed
   std::string hitCondition;
   // If this attribute exists and is non-empty, the backend must not 'break'
   // (stop) but log the message instead. Expressions within {} are
   // interpolated.
   std::string logMessage;
   std::vector<LogMessagePart> logMessageParts;
   // The LLDB breakpoint associated wit this source breakpoint
   lldb::SBBreakpoint bp;
 
   BreakpointBase() = default;
   BreakpointBase(const llvm::json::Object &obj);
 
   void SetCondition();
   void SetHitCondition();
   void SetLogMessage();
   void UpdateBreakpoint(const BreakpointBase &request_bp);
+
+  // Format \param text and return formatted text in \param formatted.
+  // \return any formatting failures.
+  lldb::SBError FormatLogText(llvm::StringRef text, std::string &formatted);
+  lldb::SBError AppendLogMessagePart(llvm::StringRef part, bool is_expr);
+  void NotifyLogMessageError(llvm::StringRef error);
+
   static const char *GetBreakpointLabel();
   static bool BreakpointHitCallback(void *baton, lldb::SBProcess &process,
                                     lldb::SBThread &thread,
                                     lldb::SBBreakpointLocation &location);
 };
 
 } // namespace lldb_vscode
 
 #endif

lldb/tools/lldb-vscode/BreakpointBase.cpp

 void BreakpointBase::SetCondition() { bp.SetCondition(condition.c_str()); }
 
 void BreakpointBase::SetHitCondition() {
   uint64_t hitCount = 0;
   if (llvm::to_integer(hitCondition, hitCount))
     bp.SetIgnoreCount(hitCount - 1);
 }
 
+lldb::SBError BreakpointBase::AppendLogMessagePart(llvm::StringRef part,
+                                                   bool is_expr) {
+  if (is_expr) {
+    logMessageParts.emplace_back(part, is_expr);
+  } else {
+    std::string formatted;
+    lldb::SBError error = FormatLogText(part, formatted);
+    if (error.Fail())
+      return error;
+    logMessageParts.emplace_back(formatted, is_expr);
+  }
+  return lldb::SBError();
+}
+
+// TODO: consolidate this code with the implementation in
+// FormatEntity::ParseInternal().
+lldb::SBError BreakpointBase::FormatLogText(llvm::StringRef text,
+                                            std::string &formatted) {
+  lldb::SBError error;
+  while (!text.empty()) {
+    size_t backslash_pos = text.find_first_of('\\');
+    if (backslash_pos == std::string::npos) {
+      formatted += text.str();
+      return error;
+    }
+
+    formatted += text.substr(0, backslash_pos).str();
+    // Skip the characters before and including '\'.
+    text = text.drop_front(backslash_pos + 1);
+
+    if (text.empty()) {
+      error.SetErrorString(
+          "'\\' character was not followed by another character");
+      return error;
+    }
+
+    const char desens_char = text[0];
+    text = text.drop_front(); // Skip the desensitized char character
+    switch (desens_char) {
+    case 'a':
+      formatted.push_back('\a');
+      break;
+    case 'b':
+      formatted.push_back('\b');
+      break;
+    case 'f':
+      formatted.push_back('\f');
+      break;
+    case 'n':
+      formatted.push_back('\n');
+      break;
+    case 'r':
+      formatted.push_back('\r');
+      break;
+    case 't':
+      formatted.push_back('\t');
+      break;
+    case 'v':
+      formatted.push_back('\v');
+      break;
+    case '\'':
+      formatted.push_back('\'');
+      break;
+    case '\\':
+      formatted.push_back('\\');
+      break;
+    case '0':
+      // 1 to 3 octal chars
+      {
+        if (text.empty()) {
+          error.SetErrorString("missing octal number following '\\0'");
+          return error;
+        }
+
+        // Make a string that can hold onto the initial zero char, up to 3
+        // octal digits, and a terminating NULL.
+        char oct_str[5] = {0, 0, 0, 0, 0};
+
+        size_t i;
+        for (i = 0;
+             i < text.size() && i < 4 && (text[i] >= '0' && text[i] <= '7');
+             ++i) {
+          oct_str[i] = text[i];
+        }
+
+        text = text.drop_front(i);
+        unsigned long octal_value = ::strtoul(oct_str, nullptr, 8);
+        if (octal_value <= UINT8_MAX) {
+          formatted.push_back((char)octal_value);
+        } else {
+          error.SetErrorString("octal number is larger than a single byte");
+          return error;
+        }
+      }
+      break;
+
+    case 'x': {
+      if (text.empty()) {
+        error.SetErrorString("missing hex number following '\\x'");
+        return error;
+      }
+      // hex number in the text
+      if (isxdigit(text[0])) {
+        // Make a string that can hold onto two hex chars plus a
+        // NULL terminator
+        char hex_str[3] = {0, 0, 0};
+        hex_str[0] = text[0];
+
+        text = text.drop_front();
+
+        if (!text.empty() && isxdigit(text[0])) {
+          hex_str[1] = text[0];
+          text = text.drop_front();
+        }
+
+        unsigned long hex_value = strtoul(hex_str, nullptr, 16);
+        if (hex_value <= UINT8_MAX) {
+          formatted.push_back((char)hex_value);
+        } else {
+          error.SetErrorString("hex number is larger than a single byte");
+          return error;
+        }
+      } else {
+        formatted.push_back(desens_char);
+      }
+      break;
+    }
+
+    default:
+      // Just desensitize any other character by just printing what came
+      // after the '\'
+      formatted.push_back(desens_char);
+      break;
+    }
+  }
+  return error;
+}
+
 // logMessage will be divided into array of LogMessagePart as two kinds:
 // 1. raw print text message, and
 // 2. interpolated expression for evaluation which is inside matching curly
 //    braces.
 //
 // The function tries to parse logMessage into a list of LogMessageParts
 // for easy later access in BreakpointHitCallback.
 void BreakpointBase::SetLogMessage() {
   logMessageParts.clear();
 
   // Contains unmatched open curly braces indices.
   std::vector<int> unmatched_curly_braces;
 
   // Contains all matched curly braces in logMessage.
   // Loop invariant: matched_curly_braces_ranges are sorted by start index in
   // ascending order without any overlap between them.
   std::vector<std::pair<int, int>> matched_curly_braces_ranges;
 
+  lldb::SBError error;
   // Part1 - parse matched_curly_braces_ranges.
   // locating all curly braced expression ranges in logMessage.
   // The algorithm takes care of nested and imbalanced curly braces.
   for (size_t i = 0; i < logMessage.size(); ++i) {
     if (logMessage[i] == '{') {
       unmatched_curly_braces.push_back(i);
     } else if (logMessage[i] == '}') {
       if (unmatched_curly_braces.empty())
void BreakpointBase::SetLogMessage() {
   // The code below uses matched_curly_braces_ranges to divide logMessage
   // into raw text parts and expression parts.
   int last_raw_text_start = 0;
   for (const std::pair<int, int> &curly_braces_range :
        matched_curly_braces_ranges) {
     // Raw text before open curly brace.
     assert(curly_braces_range.first >= last_raw_text_start);
     size_t raw_text_len = curly_braces_range.first - last_raw_text_start;
-    if (raw_text_len > 0)
-      logMessageParts.emplace_back(
+    if (raw_text_len > 0) {
+      error = AppendLogMessagePart(
           llvm::StringRef(logMessage.c_str() + last_raw_text_start,
                           raw_text_len),
           /*is_expr=*/false);
+      if (error.Fail()) {
+        NotifyLogMessageError(error.GetCString());
+        return;
+      }
+    }
 
     // Expression between curly braces.
     assert(curly_braces_range.second > curly_braces_range.first);
     size_t expr_len = curly_braces_range.second - curly_braces_range.first - 1;
-    logMessageParts.emplace_back(
+    error = AppendLogMessagePart(
         llvm::StringRef(logMessage.c_str() + curly_braces_range.first + 1,
                         expr_len),
         /*is_expr=*/true);
+    if (error.Fail()) {
+      NotifyLogMessageError(error.GetCString());
+      return;
+    }
+
     last_raw_text_start = curly_braces_range.second + 1;
   }
   // Trailing raw text after close curly brace.
   assert(last_raw_text_start >= 0);
-  if (logMessage.size() > (size_t)last_raw_text_start)
-    logMessageParts.emplace_back(
+  if (logMessage.size() > (size_t)last_raw_text_start) {
+    error = AppendLogMessagePart(
         llvm::StringRef(logMessage.c_str() + last_raw_text_start,
                         logMessage.size() - last_raw_text_start),
         /*is_expr=*/false);
+    if (error.Fail()) {
+      NotifyLogMessageError(error.GetCString());
+      return;
+    }
+  }
+
   bp.SetCallback(BreakpointBase::BreakpointHitCallback, this);
 }
 
+void BreakpointBase::NotifyLogMessageError(llvm::StringRef error) {
+  std::string message = "Log message has error: ";
+  message += error;
+  g_vsc.SendOutput(OutputType::Console, message);
+}
+
 /*static*/
 bool BreakpointBase::BreakpointHitCallback(
     void *baton, lldb::SBProcess &process, lldb::SBThread &thread,
     lldb::SBBreakpointLocation &location) {
   if (!baton)
     return true;
 
   BreakpointBase *bp = (BreakpointBase *)baton;
   lldb::SBFrame frame = thread.GetSelectedFrame();
 
   std::string output;
   for (const BreakpointBase::LogMessagePart &messagePart :
        bp->logMessageParts) {
     if (messagePart.is_expr) {
       // Try local frame variables first before fall back to expression
       // evaluation
-      std::string expr_str = messagePart.text.str();
+      const std::string &expr_str = messagePart.text;
       const char *expr = expr_str.c_str();
       lldb::SBValue value =
           frame.GetValueForVariablePath(expr, lldb::eDynamicDontRunTarget);
       if (value.GetError().Fail())
         value = frame.EvaluateExpression(expr);
       const char *expr_val = value.GetValue();
       if (expr_val)
         output += expr_val;
     } else {
-      output += messagePart.text.str();
+      output += messagePart.text;
     }
   }
+  if (!output.empty() && output.back() != '\n')
+    output.push_back('\n'); // Ensure log message has line break.
   g_vsc.SendOutput(OutputType::Console, output.c_str());
 
   // Do not stop.
   return false;
 }
 
 void BreakpointBase::UpdateBreakpoint(const BreakpointBase &request_bp) {
   if (condition != request_bp.condition) {