[K/N] Improve logging with multithreading

kotlin-native/runtime/src/main/cpp/Logging.cpp

@@ -114,7 +114,6 @@ class StderrLogger : public logging::internal::Logger {
 public:
     void Log(logging::Level level, std_support::span<const char* const> tags, std::string_view message) const noexcept override {
         konan::consoleErrorUtf8(message.data(), message.size());
-        konan::consoleErrorf("\n");
     }
 };
 
@@ -157,10 +156,13 @@ std_support::span<char> logging::internal::FormatLogEntry(
         std_support::span<const char* const> tags,
         const char* format,
         std::va_list args) noexcept {
-    buffer = FormatLevel(buffer, level);
+    auto subbuffer = buffer.subspan(0, buffer.size() - 1);
-    buffer = FormatTags(buffer, tags);
+    subbuffer = FormatLevel(subbuffer, level);
-    buffer = FormatToSpan(buffer, " ");
+    subbuffer = FormatTags(subbuffer, tags);
-    buffer = VFormatToSpan(buffer, format, args);
+    subbuffer = FormatToSpan(subbuffer, " ");
+    subbuffer = VFormatToSpan(subbuffer, format, args);
+    buffer = buffer.subspan(subbuffer.data() - buffer.data());
+    buffer = FormatToSpan(buffer, "\n");
     return buffer;
 }
 

kotlin-native/runtime/src/main/cpp/LoggingTest.cpp

@@ -55,49 +55,56 @@ public:
 TEST(LoggingTest, FormatLogEntry_Debug_OneTag) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kDebug, {"t1"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Debug_TwoTags) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kDebug, {"t1", "t2"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1,t2] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1,t2] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Info_OneTag) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kInfo, {"t1"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Info_TwoTags) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kInfo, {"t1", "t2"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1,t2] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1,t2] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Warning_OneTag) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kWarning, {"t1"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Warning_TwoTags) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kWarning, {"t1", "t2"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1,t2] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1,t2] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Error_OneTag) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kError, {"t1"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1] Log #42\n"));
 }
 
 TEST(LoggingTest, FormatLogEntry_Error_TwoTags) {
     std::array<char, 1024> buffer;
     FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, "Log #%d", 42);
-    EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2] Log #42"));
+    EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2] Log #42\n"));
+}
+
+TEST(LoggingTest, FormatLogEntry_Overflow) {
+    std::array<char, 20> buffer;
+    FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, "Log #%d", 42);
+    // Only 18 characters are used for the log string contents, another 2 are \n and \0.
+    EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2] Log\n"));
 }
 
 TEST(LoggingDeathTest, StderrLogger) {
@@ -215,6 +222,6 @@ TEST_F(LoggingLogTest, Log_Success) {
     constexpr auto level = logging::Level::kInfo;
     const std::initializer_list<const char*> tags = {"t1", "t2"};
     EXPECT_CALL(logFilter(), Enabled(level, TagsAre(tags))).WillOnce(testing::Return(true));
-    EXPECT_CALL(logger(), Log(level, TagsAre(tags), "[INFO][t1,t2] Message 42"));
+    EXPECT_CALL(logger(), Log(level, TagsAre(tags), "[INFO][t1,t2] Message 42\n"));
     Log(level, tags, "Message %d", 42);
 }