diff --git a/runtime/platform/log.cpp b/runtime/platform/log.cpp index b338ee10a71..a09987271e7 100644 --- a/runtime/platform/log.cpp +++ b/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(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(kMaxLogMessageLength) + ? kMaxLogMessageLength - 1 + : static_cast(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 } diff --git a/runtime/platform/test/CMakeLists.txt b/runtime/platform/test/CMakeLists.txt index 901fd0499cd..fee7566da3d 100644 --- a/runtime/platform/test/CMakeLists.txt +++ b/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 # diff --git a/runtime/platform/test/logging_test.cpp b/runtime/platform/test/logging_test.cpp index d44cd2d5e71..3ddc506c062 100644 --- a/runtime/platform/test/logging_test.cpp +++ b/runtime/platform/test/logging_test.cpp @@ -10,24 +10,79 @@ #include #include +#include +#include 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()); + } + } } diff --git a/runtime/platform/test/targets.bzl b/runtime/platform/test/targets.bzl index 6a46eb29f4b..a5d77ef5a4e 100644 --- a/runtime/platform/test/targets.bzl +++ b/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 = [