Fix message truncating logic to respect UTF8 encoding. (#14394)

Summary:

.

Reviewed By: metascroy

Differential Revision: D82681904

Author: shoumikhin

runtime/platform/log.cpp

@@ -59,6 +59,42 @@ static_assert(
     kLevelToPal[size_t(LogLevel::Fatal)] == et_pal_log_level_t::kFatal,
     "");
 
+#if ET_LOG_ENABLED
+/**
+ * Returns the length of the longest valid UTF-8 prefix in a byte buffer.
+ */
+static inline size_t get_valid_utf8_prefix_length(
+    const char* bytes,
+    size_t length) {
+  if (!bytes || length == 0) {
+    return 0;
+  }
+  const auto* data = reinterpret_cast<const unsigned char*>(bytes);
+  auto index = size_t{0};
+  auto last_valid_length = size_t{0};
+  while (index < length) {
+    const auto lead_byte = data[index];
+    const size_t sequence_length = (lead_byte < 0x80) ? 1
+        : ((lead_byte & 0xE0) == 0xC0)                ? 2
+        : ((lead_byte & 0xF0) == 0xE0)                ? 3
+        : ((lead_byte & 0xF8) == 0xF0)                ? 4
+                                                      : 0;
+    if (!sequence_length || index + sequence_length > length) {
+      return last_valid_length;
+    }
+    for (size_t continuation_index = 1; continuation_index < sequence_length;
+         ++continuation_index) {
+      if ((data[index + continuation_index] & 0xC0) != 0x80) {
+        return last_valid_length;
+      }
+    }
+    index += sequence_length;
+    last_valid_length = index;
+  }
+  return last_valid_length;
+}
+#endif // ET_LOG_ENABLED
+
 /**
  * Log a string message.
  *
@@ -84,20 +120,24 @@ void vlogf(
 
   // Maximum length of a log message.
   static constexpr size_t kMaxLogMessageLength = 256;
-  char buf[kMaxLogMessageLength];
-  size_t len = vsnprintf(buf, kMaxLogMessageLength, format, args);
-  if (len >= kMaxLogMessageLength - 1) {
-    buf[kMaxLogMessageLength - 2] = '$';
-    len = kMaxLogMessageLength - 1;
-  }
-  buf[kMaxLogMessageLength - 1] = 0;
+  char buffer[kMaxLogMessageLength];
+
+  const auto write_count =
+      vsnprintf(buffer, kMaxLogMessageLength, format, args);
+  const size_t used_length = (write_count < 0)
+      ? 0
+      : (write_count >= static_cast<int>(kMaxLogMessageLength)
+             ? kMaxLogMessageLength - 1
+             : static_cast<size_t>(write_count));
+  const auto valid_length = get_valid_utf8_prefix_length(buffer, used_length);
+  buffer[valid_length] = '\0';
 
-  et_pal_log_level_t pal_level = (level < LogLevel::NumLevels)
+  const auto pal_level = (level < LogLevel::NumLevels)
       ? kLevelToPal[size_t(level)]
       : et_pal_log_level_t::kUnknown;
 
   pal_emit_log_message(
-      timestamp, pal_level, filename, function, line, buf, len);
+      timestamp, pal_level, filename, function, line, buffer, valid_length);
 
 #endif // ET_LOG_ENABLED
 }

runtime/platform/test/CMakeLists.txt

@@ -33,7 +33,7 @@ et_cxx_test(
 #
 # et_cxx_test(platform_death_test SOURCES executor_pal_death_test.cpp)
 
-et_cxx_test(logging_test SOURCES logging_test.cpp)
+et_cxx_test(logging_test SOURCES logging_test.cpp stub_platform.cpp)
 
 # TODO: Re-enable this test on OSS
 #

runtime/platform/test/logging_test.cpp

@@ -10,24 +10,63 @@
 
 #include <executorch/runtime/platform/log.h>
 #include <executorch/runtime/platform/runtime.h>
+#include <executorch/runtime/platform/test/pal_spy.h>
+#include <executorch/runtime/platform/test/stub_platform.h>
 
 using namespace executorch::runtime;
 
 class LoggingTest : public ::testing::Test {
- public:
-  static void SetUpTestSuite() {
-    // Initialize runtime.
-    runtime_init();
-  }
 };
 
 TEST_F(LoggingTest, LogLevels) {
+  PalSpy spy;
+  InterceptWith iw(spy);
+
   ET_LOG(Debug, "Debug log.");
+  EXPECT_EQ(spy.last_log_message_args.message, "Debug log.");
+
   ET_LOG(Info, "Info log.");
+  EXPECT_EQ(spy.last_log_message_args.message, "Info log.");
+
   ET_LOG(Error, "Error log.");
+  EXPECT_EQ(spy.last_log_message_args.message, "Error log.");
+
   ET_LOG(Fatal, "Fatal log.");
+  EXPECT_EQ(spy.last_log_message_args.message, "Fatal log.");
 }
 
 TEST_F(LoggingTest, LogFormatting) {
+  PalSpy spy;
+  InterceptWith iw(spy);
+
   ET_LOG(Info, "Sample log with integer: %u", 100);
+  EXPECT_EQ(spy.last_log_message_args.message, "Sample log with integer: 100");
+}
+
+TEST_F(LoggingTest, Utf8Truncation) {
+  PalSpy spy;
+  InterceptWith iw(spy);
+
+  {
+    // 253 'A' + first 2 bytes of "€" (0xE2 0x82 0xAC) -> mid-codepoint cut at 255
+    std::string prefix(253, 'A');
+    const char euro[] = "\xE2\x82\xAC"; // 3-byte UTF-8
+    std::string suffix = "_SHOULD_BE_CUT";
+
+    ET_LOG(Info, "%s%s%s", prefix.c_str(), euro, suffix.c_str());
+
+    EXPECT_EQ(spy.last_log_message_args.message, prefix);
+    EXPECT_EQ(spy.last_log_message_args.length, prefix.size());
+  }
+  {
+    // 252 'B' + first 3 bytes of "👍" (0xF0 0x9F 0x91 0x8D) -> mid-codepoint cut
+    std::string prefix(252, 'B');
+    const char thumbs_up[] = "\xF0\x9F\x91\x8D"; // 4-byte UTF-8
+    std::string suffix = "_SHOULD_BE_CUT";
+
+    ET_LOG(Info, "%s%s%s", prefix.c_str(), thumbs_up, suffix.c_str());
+
+    EXPECT_EQ(spy.last_log_message_args.message, prefix);
+    EXPECT_EQ(spy.last_log_message_args.length, prefix.size());
+  }
 }

runtime/platform/test/targets.bzl

@@ -84,6 +84,7 @@ def define_common_targets():
             "logging_test.cpp",
         ],
         deps = [
+            ":stub_platform",
             "//executorch/runtime/platform:platform",
         ],
         compiler_flags = [