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

Author: shoumikhin

runtime/platform/log.cpp

@@ -59,6 +59,38 @@ static_assert(
     kLevelToPal[size_t(LogLevel::Fatal)] == et_pal_log_level_t::kFatal,
     "");
 
+#if ET_LOG_ENABLED
+static 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);
+  size_t i = length;
+  while (i > 0 && (data[i - 1] & 0xC0) == 0x80) {
+    --i;
+  }
+  if (i == 0) {
+    return 0;
+  }
+  const size_t lead_pos = i - 1;
+  const unsigned char lead = data[lead_pos];
+  size_t need = 0;
+
+  if (lead < 0x80) {
+    need = 1;
+  } else if ((lead & 0xE0) == 0xC0) {
+    need = 2;
+  } else if ((lead & 0xF0) == 0xE0) {
+    need = 3;
+  } else if ((lead & 0xF8) == 0xF0) {
+    need = 4;
+  } else {
+    return lead_pos;
+  }
+  return length - lead_pos == need ? length : lead_pos;
+}
+#endif // ET_LOG_ENABLED
+
 /**
  * Log a string message.
  *
@@ -84,20 +116,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,13 @@ et_cxx_test(
 #
 # et_cxx_test(platform_death_test SOURCES executor_pal_death_test.cpp)
 
-et_cxx_test(logging_test SOURCES logging_test.cpp)
+# No weak function symbols Windows/MSVC, thus PAL intercept is not supported.
+if(NOT WIN32)
+  et_cxx_test(logging_test SOURCES logging_test.cpp stub_platform.cpp)
+  set_source_files_properties(
+    logging_test.cpp PROPERTIES COMPILE_DEFINITIONS "ET_MIN_LOG_LEVEL=Debug"
+  )
+endif()
 
 # TODO: Re-enable this test on OSS
 #

runtime/platform/test/logging_test.cpp

@@ -10,24 +10,79 @@
 
 #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();
-  }
-};
+class LoggingTest : public ::testing::Test {};
 
 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");
+}
+
+static std::string get_prefix(std::size_t length, bool use_multibyte) {
+  if (!use_multibyte) {
+    return std::string(length, 'A');
+  }
+  std::ostringstream result;
+  result << std::string(length % 4, 'A');
+  std::size_t remaining = length - (length % 4);
+  while (remaining > 0) {
+    result << "\xF0\x9F\x91\x8D";
+    remaining -= 4;
+  }
+  return result.str();
+}
+
+TEST_F(LoggingTest, Utf8Truncation) {
+  PalSpy spy;
+  InterceptWith iw(spy);
+
+  const char euro[] = "\xE2\x82\xAC";
+  const char thumbs_up[] = "\xF0\x9F\x91\x8D";
+  const char e_acute[] = "\xC3\xA9";
+  const char capital_a_tilde[] = "\xC3\x83";
+
+  struct TruncCase {
+    size_t prefix_length;
+    const char* codepoint;
+  };
+  const TruncCase cases[] = {
+      {253, euro},
+      {252, thumbs_up},
+      {254, e_acute},
+      {254, capital_a_tilde},
+  };
+  for (bool use_multibyte_prefix : {false, true}) {
+    for (const auto& c : cases) {
+      const std::string prefix =
+          get_prefix(c.prefix_length, use_multibyte_prefix);
+      const std::string suffix = "_SHOULD_BE_CUT";
+      ET_LOG(Info, "%s%s%s", prefix.c_str(), c.codepoint, 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 = [