From d0d264d5b6a7ebf3c7c85daf55209c85e379a9b3 Mon Sep 17 00:00:00 2001 From: Philipp Schrader Date: Wed, 20 Dec 2023 11:11:35 -0800 Subject: [PATCH] Fix undefined behaviour in `aos/time/time.cc` We're currently seeing the following undefined behaviour in the code that converts `realtime_clock::time_point` values into human-readable strings. The issue is that the computation overflows what we can represent in 64 bits when stringifying `realtime_clock::min_time`. $ bazel test --config=ubsan @aos//aos/events/logging:logfile_utils_test --test_filter=PartsMessageReaderDeathTest.TooFarOutOfOrder --test_output=streamed --test_env=UBSAN_SYMBOLIZER_PATH="$(readlink -f external/llvm_k8/bin/llvm-symbolizer)" ... [ RUN ] PartsMessageReaderDeathTest.TooFarOutOfOrder external/aos/aos/events/logging/logfile_utils_test.cc:169: Failure Death test: { reader.ReadMessage(); } Result: died but not with expected error. Expected: contains regular expression "-0.000000001sec vs. 0.000000000sec" Actual msg: [ DEATH ] external/llvm_k8/include/c++/v1/__chrono/duration.h:102:59: runtime error: signed integer overflow: -9223372037 * 1000000000 cannot be represented in type '_Ct' (aka 'long long') ... [ DEATH ] #4 0x7f6788f54d9a in aos::operator<<(std::__1::basic_ostream>&, std::__1::chrono::time_point>> const&) external/aos/aos/time/time.cc:189:55 [ DEATH ] #5 0x7f67938da571 in aos::logger::operator<<(std::__1::basic_ostream>&, aos::logger::LogParts const&) external/aos/aos/events/logging/logfile_sorting.cc:2163:50 [ DEATH ] #6 0x7f6793aeec53 in aos::logger::PartsMessageReader::ReadMessage() external/aos/aos/events/logging/logfile_utils.cc:1679:32 [ DEATH ] #7 0x55ed45105cb0 in aos::logger::testing::PartsMessageReaderDeathTest_TooFarOutOfOrder_Test::TestBody() external/aos/aos/events/logging/logfile_utils_test.cc:169:3 ... [ DEATH ] [ DEATH ] SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior external/llvm_k8/include/c++/v1/__chrono/duration.h:102:59 in [ DEATH ] [ FAILED ] PartsMessageReaderDeathTest.TooFarOutOfOrder (200 ms) [----------] 1 test from PartsMessageReaderDeathTest (200 ms total) This patch fixes the issue by detecting potential overflow and return a mostly non-human-readable string version of the time stamp. Change-Id: I4bff6272ac6f4d48c646face2c13fbc7dd3bb0ed Signed-off-by: James Kuszmaul --- aos/time/time.cc | 10 ++++++++++ aos/time/time_test.cc | 5 +++-- 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/aos/time/time.cc b/aos/time/time.cc index 6a25aa98dd..db713790e9 100644 --- a/aos/time/time.cc +++ b/aos/time/time.cc @@ -170,6 +170,16 @@ std::ostream &operator<<(std::ostream &stream, : std::chrono::duration_cast( now.time_since_epoch()); + // We can run into some corner cases where the seconds value is large enough + // to cause the conversion to nanoseconds to overflow. That is undefined + // behaviour so we prevent it with this check here. + if (int64_t result; + __builtin_mul_overflow(seconds.count(), 1'000'000'000, &result)) { + stream << "(unrepresentable realtime " << now.time_since_epoch().count() + << ")"; + return stream; + } + std::time_t seconds_t = seconds.count(); stream << std::put_time(localtime_r(&seconds_t, &tm), "%Y-%m-%d_%H-%M-%S.") << std::setfill('0') << std::setw(9) diff --git a/aos/time/time_test.cc b/aos/time/time_test.cc index 63a145b0a6..e8b7153b4c 100644 --- a/aos/time/time_test.cc +++ b/aos/time/time_test.cc @@ -208,8 +208,9 @@ TEST(TimeTest, OperatorStreamRealtimeNegative) { std::stringstream s; s << t; - EXPECT_EQ(s.str(), "1677-09-21_00-12-43.145224192"); - EXPECT_EQ(realtime_clock::FromString(s.str()).value(), t); + // min_time happens to be unrepresentable because of rounding and signed + // integer overflow. + EXPECT_EQ(s.str(), "(unrepresentable realtime -9223372036854775808)"); } {