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.
This commit is contained in:
Scott McKay 2019-08-14 07:53:45 +10:00 committed by GitHub
parent a50a63aa9e
commit b5de1324ef
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
2 changed files with 46 additions and 6 deletions

View file

@ -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();

View file

@ -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