From 34c89d855ad7a92da7ae38ad2922899e26d20109 Mon Sep 17 00:00:00 2001
From: Alexander Shabalin <alexander.shabalin@jetbrains.com>
Date: Thu, 23 Sep 2021 13:05:40 +0300
Subject: [PATCH] [K/N] Improve logging with multithreading

---
 .../runtime/src/main/cpp/Logging.cpp          | 12 +++++----
 .../runtime/src/main/cpp/LoggingTest.cpp      | 25 ++++++++++++-------
 2 files changed, 23 insertions(+), 14 deletions(-)

diff --git a/kotlin-native/runtime/src/main/cpp/Logging.cpp b/kotlin-native/runtime/src/main/cpp/Logging.cpp
index fe35c954dad..69e3dc87068 100644
--- a/kotlin-native/runtime/src/main/cpp/Logging.cpp
+++ b/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);
-    buffer = FormatTags(buffer, tags);
-    buffer = FormatToSpan(buffer, " ");
-    buffer = VFormatToSpan(buffer, format, args);
+    auto subbuffer = buffer.subspan(0, buffer.size() - 1);
+    subbuffer = FormatLevel(subbuffer, level);
+    subbuffer = FormatTags(subbuffer, tags);
+    subbuffer = FormatToSpan(subbuffer, " ");
+    subbuffer = VFormatToSpan(subbuffer, format, args);
+    buffer = buffer.subspan(subbuffer.data() - buffer.data());
+    buffer = FormatToSpan(buffer, "\n");
     return buffer;
 }
 
diff --git a/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp b/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp
index 14e124a56c4..57286adf508 100644
--- a/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp
+++ b/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);
 }