diff --git a/SilKit/IntegrationTests/CMakeLists.txt b/SilKit/IntegrationTests/CMakeLists.txt index 062939788..f53267d65 100644 --- a/SilKit/IntegrationTests/CMakeLists.txt +++ b/SilKit/IntegrationTests/CMakeLists.txt @@ -66,6 +66,10 @@ add_silkit_test_to_executable(SilKitIntegrationTests SOURCES ITest_LabelsMatching.cpp ) +add_silkit_test_to_executable(SilKitIntegrationTests + SOURCES ITest_Logging.cpp +) + add_silkit_test_to_executable(SilKitInternalIntegrationTests SOURCES ITest_Internals_TargetedMessaging.cpp ) diff --git a/SilKit/IntegrationTests/ITest_Logging.cpp b/SilKit/IntegrationTests/ITest_Logging.cpp new file mode 100644 index 000000000..b3f9cd909 --- /dev/null +++ b/SilKit/IntegrationTests/ITest_Logging.cpp @@ -0,0 +1,161 @@ +// SPDX-FileCopyrightText: 2026 Vector Informatik GmbH +// +// SPDX-License-Identifier: MIT + +#include +#include +#include +#include +#include +#include + +#include "silkit/SilKit.hpp" +#include "silkit/services/flexray/string_utils.hpp" +#include "silkit/services/logging/ILogger.hpp" +#include "silkit/vendor/CreateSilKitRegistry.hpp" + +#include "gmock/gmock.h" +#include "gtest/gtest.h" + + +namespace { + +namespace fs = std::filesystem; + +using namespace std::chrono_literals; +using namespace SilKit::Services::Logging; + +const std::string participantName{"LoggingParticipant"}; +const std::string simpleLogName{"ITest_Logging_Simple"}; +const std::string jsonLogName{"ITest_Logging_Json"}; + +// The demos render bus events into their log messages, and the SIL Kit stream operators use braces: +// "Received Flexray::FlexraySymbolTransmitEvent{pattern=Wus, channel=A @ 12.796ms}". Such a message must +// reach the sinks verbatim. If it is handed on as a fmt format string instead, '{pattern=' is parsed as a +// replacement field and fmt::format throws - which used to surface as a SilKitError inside the user's +// event handler. +auto MakeBracedMessage() -> std::string +{ + SilKit::Services::Flexray::FlexraySymbolTransmitEvent symbol{}; + symbol.timestamp = 12796us; + symbol.channel = SilKit::Services::Flexray::FlexrayChannel::A; + symbol.pattern = SilKit::Services::Flexray::FlexraySymbolPattern::Wus; + + std::stringstream ss; + ss << "Received " << symbol; + return ss.str(); +} + +auto MakeParticipantConfiguration() -> const std::string +{ + std::string config = R"( +Logging: + FlushLevel: Trace + Sinks: + - Type: File + Level: Trace + Format: Simple + LogName: ITest_Logging_Simple + - Type: File + Level: Trace + Format: Json + LogName: ITest_Logging_Json + )"; + return config; +} + +class ITest_Logging : public testing::Test +{ +protected: + void SetUp() override + { + RemoveLogFiles(); + } + + void TearDown() override + { + RemoveLogFiles(); + } + + // The sinks append a participant name and a timestamp to the configured log name, so the files can only + // be identified by their prefix. + static auto FindLogFiles(const std::string& logName) -> std::vector + { + const auto prefix = logName + "_"; + + std::vector logFiles; + for (const auto& entry : fs::directory_iterator{fs::current_path()}) + { + if (entry.is_regular_file() && entry.path().filename().string().compare(0, prefix.size(), prefix) == 0) + { + logFiles.push_back(entry.path()); + } + } + return logFiles; + } + + static void RemoveLogFiles() + { + for (const auto& logName : {simpleLogName, jsonLogName}) + { + for (const auto& logFile : FindLogFiles(logName)) + { + std::error_code ec; + fs::remove(logFile, ec); + } + } + } + + static auto ReadLogFile(const std::string& logName) -> std::string + { + const auto logFiles = FindLogFiles(logName); + EXPECT_EQ(logFiles.size(), 1u) << "Expected exactly one log file for '" << logName << "'"; + if (logFiles.size() != 1u) + { + return {}; + } + + std::ifstream stream{logFiles.front()}; + EXPECT_TRUE(stream.good()) << "Cannot open " << logFiles.front().string(); + + std::stringstream contents; + contents << stream.rdbuf(); + return contents.str(); + } +}; + +TEST_F(ITest_Logging, log_message_with_braces_is_not_parsed_as_format_string) +{ + const auto bracedMessage = MakeBracedMessage(); + ASSERT_THAT(bracedMessage, testing::HasSubstr("{pattern=Wus, channel=A @ 12.796ms}")); + + // An unbalanced brace is the degenerate case: fmt cannot even recover by treating the field as named. + const std::string unbalancedMessage{"A lone opening brace { and a lone closing brace }"}; + + { + auto registryConfig = SilKit::Config::ParticipantConfigurationFromString(""); + auto registry = SilKit::Vendor::Vector::CreateSilKitRegistry(registryConfig); + const auto registryUri = registry->StartListening("silkit://127.0.0.1:0"); + + auto participantConfig = SilKit::Config::ParticipantConfigurationFromString(MakeParticipantConfiguration()); + auto participant = SilKit::CreateParticipant(participantConfig, participantName, registryUri); + + auto* logger = participant->GetLogger(); + ASSERT_NE(logger, nullptr); + + EXPECT_NO_THROW(logger->Info(bracedMessage)); + EXPECT_NO_THROW(logger->Log(Level::Warn, bracedMessage)); + EXPECT_NO_THROW(logger->Error(unbalancedMessage)); + } + // The participant is gone, so the file sinks are flushed and closed. + + const auto simpleLog = ReadLogFile(simpleLogName); + EXPECT_THAT(simpleLog, testing::HasSubstr(bracedMessage)); + EXPECT_THAT(simpleLog, testing::HasSubstr(unbalancedMessage)); + + const auto jsonLog = ReadLogFile(jsonLogName); + EXPECT_THAT(jsonLog, testing::HasSubstr(bracedMessage)); + EXPECT_THAT(jsonLog, testing::HasSubstr(unbalancedMessage)); +} + +} // namespace diff --git a/SilKit/source/services/logging/LoggerMessage.hpp b/SilKit/source/services/logging/LoggerMessage.hpp index c3b62b72b..9236a488d 100644 --- a/SilKit/source/services/logging/LoggerMessage.hpp +++ b/SilKit/source/services/logging/LoggerMessage.hpp @@ -73,6 +73,15 @@ class LoggerMessage return *this; } + LoggerMessage& SetMessage(std::string msg) + { + if (_logger->GetLogLevel() <= _level) + { + _msg = std::move(msg); + } + return *this; + } + auto SetTopic(Topic topic) -> LoggerMessage& { _topic = topic; diff --git a/docs/changelog/versions/latest.md b/docs/changelog/versions/latest.md index c344f4f3e..db68c2c85 100644 --- a/docs/changelog/versions/latest.md +++ b/docs/changelog/versions/latest.md @@ -1,4 +1,4 @@ -# [5.0.7] - 2026-07-29 +# [5.0.7] - 2026-07-31 ## Added @@ -15,6 +15,7 @@ simulation step sizes, aligning each simulation step to the minimal step among all synchronized participants. Tri-state: `true` requests it for the whole simulation, `false` opts out, and leaving it unset follows the network. Off by default. +- `logging`: Fixes a bug where some log messages (e.g., user-level log messages) were passed to fmt and caused exceptions when placeholder characters were present. These log messages are no longer passed to fmt. ## Changed