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

Summary:

.

Reviewed By: swolchok, metascroy

Differential Revision: D82681904

Author: shoumikhin

runtime/platform/log.cpp

@@ -59,6 +59,40 @@ static_assert(
     kLevelToPal[size_t(LogLevel::Fatal)] == et_pal_log_level_t::kFatal,
     "");
 
+#if ET_LOG_ENABLED
+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);
+  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 +118,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,8 @@ 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)
+target_compile_definitions(logging_test PRIVATE ET_MIN_LOG_LEVEL=Debug)
 
 # TODO: Re-enable this test on OSS
 #

runtime/platform/test/logging_test.cpp

@@ -10,24 +10,64 @@
 
 #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");
+}
+
+TEST_F(LoggingTest, Utf8Truncation) {
+  PalSpy spy;
+  InterceptWith iw(spy);
+
+  {
+    std::string prefix(253, 'A');
+    const char euro[] = "\xE2\x82\xAC";
+    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());
+  }
+  {
+    std::string prefix(252, 'B');
+    const char thumbs_up[] = "\xF0\x9F\x91\x8D";
+    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());
+  }
+  {
+    std::string prefix(254, 'C');
+    const char e_acute[] = "\xC3\xA9";
+    std::string suffix = "_SHOULD_BE_CUT";
+    ET_LOG(Info, "%s%s%s", prefix.c_str(), e_acute, 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 = [