From b5de1324ef881a54aee7e358ccf10701292e4574 Mon Sep 17 00:00:00 2001
From: Scott McKay <scmckay@microsoft.com>
Date: Wed, 14 Aug 2019 07:53:45 +1000
Subject: [PATCH] Fix log message truncation on Windows when printf formatting
 is used.` (#1599)

* Fix log message truncation and add unit test. On Windows vnsprintf_s returns -1 when truncating so we need to differentiate that from a real error.
---
 onnxruntime/core/common/logging/capture.cc    | 14 ++++++-
 .../test/common/logging/logging_test.cc       | 38 +++++++++++++++++--
 2 files changed, 46 insertions(+), 6 deletions(-)

diff --git a/onnxruntime/core/common/logging/capture.cc b/onnxruntime/core/common/logging/capture.cc
index 016ddb9fc0..6223d2ca70 100644
--- a/onnxruntime/core/common/logging/capture.cc
+++ b/onnxruntime/core/common/logging/capture.cc
@@ -27,16 +27,26 @@ void Capture::ProcessPrintf(msvc_printf_check const char* format, va_list args)
   char message_buffer[kMaxMessageSize];
   const auto message = gsl::make_span(message_buffer);
 
+  bool error = false;
+  bool truncated = false;
+
 #if (defined(WIN32) || defined(_WIN32) || defined(__WIN32__) && !defined(__GNUC__))
+  errno = 0;
   const int nbrcharacters = vsnprintf_s(message.data(), message.size(), _TRUNCATE, format, args);
+  if (nbrcharacters < 0) {
+    error = errno != 0;
+    truncated = !error;
+  }
 #else
   const int nbrcharacters = vsnprintf(message.data(), message.size(), format, args);
+  error = nbrcharacters < 0;
+  truncated = nbrcharacters > message.size();
 #endif
 
-  if (nbrcharacters <= 0) {
+  if (error) {
     stream_ << "\n\tERROR LOG MSG NOTIFICATION: Failure to successfully parse the message";
     stream_ << '"' << format << '"' << std::endl;
-  } else if (nbrcharacters > message.size()) {
+  } else if (truncated) {
     stream_ << message.data() << kTruncatedWarningText;
   } else {
     stream_ << message.data();
diff --git a/onnxruntime/test/common/logging/logging_test.cc b/onnxruntime/test/common/logging/logging_test.cc
index 828e230482..11ca7fb4ca 100644
--- a/onnxruntime/test/common/logging/logging_test.cc
+++ b/onnxruntime/test/common/logging/logging_test.cc
@@ -11,10 +11,6 @@
 
 #include "test/common/logging/helpers.h"
 
-using namespace onnxruntime;
-using namespace ::onnxruntime::logging;
-using InstanceType = LoggingManager::InstanceType;
-
 // if we pull in the whole 'testing' namespace we get warnings from date.h as both use '_' in places.
 // to avoid that we explicitly pull in the pieces we are using
 using testing::Eq;
@@ -23,6 +19,12 @@ using testing::Ge;
 using testing::HasSubstr;
 using testing::Property;
 
+namespace onnxruntime {
+using namespace logging;
+using InstanceType = LoggingManager::InstanceType;
+
+namespace test {
+
 static std::string default_logger_id{"TestFixtureDefaultLogger"};
 
 // class to provide single default instance of LoggingManager for use with macros involving 'DEFAULT'
@@ -232,3 +234,31 @@ TEST_F(LoggingTestsFixture, TestVLog) {
   VLOGS(*logger, 0) << "Should be ignored.";  // ignored as disabled
 #endif
 }
+
+class CTestSink : public OStreamSink {
+ public:
+  CTestSink(std::ostringstream& stream) : OStreamSink(stream, /*flush*/ true) {
+  }
+};
+
+TEST_F(LoggingTestsFixture, TestTruncation) {
+  const std::string logger_id{"TestTruncation"};
+  const Severity min_log_level = Severity::kVERBOSE;
+  const bool filter_user_data = false;
+
+  std::ostringstream out;
+  auto* sink_ptr = new CTestSink{out};
+
+  LoggingManager manager{std::unique_ptr<ISink>(sink_ptr), min_log_level, filter_user_data,
+                         InstanceType::Temporal};
+
+  auto logger = manager.CreateLogger(logger_id);
+
+  // attempt to print string longer than hard-coded 2K buffer limit
+  LOGF(*logger, ERROR, "%s", std::string(4096, 'a').c_str());
+
+  EXPECT_THAT(out.str(), HasSubstr("[...truncated...]"));
+}
+
+}  // namespace test
+}  // namespace onnxruntime