diff --git a/SilKit/source/core/internal/LoggingDatatypesInternal.hpp b/SilKit/source/core/internal/LoggingDatatypesInternal.hpp index d64c5ffc4..aa9f03e0d 100644 --- a/SilKit/source/core/internal/LoggingDatatypesInternal.hpp +++ b/SilKit/source/core/internal/LoggingDatatypesInternal.hpp @@ -25,7 +25,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include #include #include -#include +#include #include "silkit/services/logging/LoggingDatatypes.hpp" #include "silkit/services/logging/string_utils.hpp" @@ -54,7 +54,7 @@ struct LogMsg log_clock::time_point time; SourceLoc source; std::string payload; - std::unordered_map keyValues; + std::vector> keyValues; }; inline bool operator==(const SourceLoc& lhs, const SourceLoc& rhs); @@ -67,8 +67,8 @@ inline std::string to_string(const LogMsg& msg); inline std::ostream& operator<<(std::ostream& out, const LogMsg& msg); -inline std::string to_string(const std::unordered_map& kv); -inline std::ostream& operator<<(std::ostream& out, const std::unordered_map& kv); +inline std::string to_string(const std::vector>& kv); +inline std::ostream& operator<<(std::ostream& out, const std::vector>& kv); // ================================================================================ // Inline Implementations @@ -98,7 +98,8 @@ std::ostream& operator<<(std::ostream& out, const SourceLoc& sourceLoc) << "line=" << sourceLoc.line << ", funcname={\"" << sourceLoc.funcname << "\"}"; } -inline std::string to_string(const std::unordered_map& kv) + +inline std::string to_string(const std::vector>& kv) { std::stringstream outStream; outStream << kv; @@ -106,7 +107,7 @@ inline std::string to_string(const std::unordered_map& } -inline std::ostream& operator<<(std::ostream& out, const std::unordered_map& kv) +inline std::ostream& operator<<(std::ostream& out, const std::vector>& kv) { std::string result; result.reserve(kv.size() * 2); @@ -115,7 +116,7 @@ inline std::ostream& operator<<(std::ostream& out, const std::unordered_map::const_iterator it = kv.begin(); + std::vector>::const_iterator it = kv.begin(); result.append("{"); while (it != kv.end()) { diff --git a/SilKit/source/core/internal/MessageBuffer.hpp b/SilKit/source/core/internal/MessageBuffer.hpp index a1691abc3..0c3765db3 100644 --- a/SilKit/source/core/internal/MessageBuffer.hpp +++ b/SilKit/source/core/internal/MessageBuffer.hpp @@ -229,6 +229,12 @@ class MessageBuffer template inline MessageBuffer& operator>>(std::array& array); // -------------------------------------------------------------------------------- + // std::pair + template + inline MessageBuffer& operator<<(const std::pair& pair); + template + inline MessageBuffer& operator>>(std::pair& pair); + // -------------------------------------------------------------------------------- // std::chrono::duration and system_clock::time_point template inline MessageBuffer& operator<<(std::chrono::duration duration); @@ -632,6 +638,21 @@ inline MessageBuffer& MessageBuffer::operator>>(std::unordered_map +inline MessageBuffer& MessageBuffer::operator<<(const std::pair& pair) +{ + *this << pair.first << pair.second; + return *this; +} + +template +inline MessageBuffer& MessageBuffer::operator>>(std::pair& pair) +{ + *this >> pair.first >> pair.second; + return *this; +} + + // -------------------------------------------------------------------------------- // Uuid diff --git a/SilKit/source/core/internal/ServiceDescriptor.hpp b/SilKit/source/core/internal/ServiceDescriptor.hpp index 22d375747..e20795e81 100644 --- a/SilKit/source/core/internal/ServiceDescriptor.hpp +++ b/SilKit/source/core/internal/ServiceDescriptor.hpp @@ -24,6 +24,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include #include +#include "StructuredLoggingKeys.hpp" #include "ServiceConfigKeys.hpp" #include "Configuration.hpp" #include "EndpointAddress.hpp" @@ -70,6 +71,8 @@ class ServiceDescriptor inline bool operator==(const ServiceDescriptor& rhs) const; inline bool operator!=(const ServiceDescriptor& rhs) const; inline std::string to_string() const; + inline std::vector> to_keyValues() const; + inline Core::EndpointAddress to_endpointAddress() const; public: @@ -304,6 +307,47 @@ std::string ServiceDescriptor::to_string() const return ss.str(); } + + std::vector> ServiceDescriptor::to_keyValues() const +{ + namespace Keys = SilKit::Services::Logging::Keys; + + std::vector> kv; + std::string controllerTypeName; + std::stringstream ss; + + kv.push_back({Keys::participantName, GetParticipantName()}); + + switch (GetServiceType()) + { + case ServiceType::Link: + kv.push_back({Keys::networkType, Config::to_string(GetNetworkType())}); + kv.push_back({Keys::networkName, GetNetworkName()}); + break; + case ServiceType::Controller: + case ServiceType::SimulatedController: + if (!GetSupplementalDataItem(SilKit::Core::Discovery::controllerType, controllerTypeName)) + { + throw LogicError( + "ServiceDescriptor::to_keyValues() failed: No controller type defined in supplemental data."); + } + kv.push_back({Keys::controllerTypeName, controllerTypeName}); + kv.push_back({Keys::networkName, GetNetworkName()}); + kv.push_back({Keys::serviceName, GetServiceName()}); + break; + case ServiceType::InternalController: + kv.push_back({Keys::serviceName, GetServiceName()}); + break; + case ServiceType::Undefined: + kv.push_back({Keys::networkName, GetNetworkName()}); + kv.push_back({Keys::serviceName, GetServiceName()}); + break; + } + + kv.push_back({Keys::serviceType, SilKit::Core::to_string(GetServiceType())}); + return kv; +} + EndpointAddress ServiceDescriptor::to_endpointAddress() const { return {GetParticipantId(), GetServiceId()}; diff --git a/SilKit/source/core/mock/nullconnection/NullConnectionParticipant.cpp b/SilKit/source/core/mock/nullconnection/NullConnectionParticipant.cpp index ff0e5a802..06632d53f 100644 --- a/SilKit/source/core/mock/nullconnection/NullConnectionParticipant.cpp +++ b/SilKit/source/core/mock/nullconnection/NullConnectionParticipant.cpp @@ -40,6 +40,7 @@ struct NullConnection } void SetLogger(Services::Logging::ILogger* /*logger*/) {} + void SetLoggerInternal(Services::Logging::ILoggerInternal* /*logger*/) {} void SetTimeSyncService(Orchestration::TimeSyncService* /*timeSyncService*/) {} void JoinSimulation(std::string /*registryUri*/) {} diff --git a/SilKit/source/core/participant/Participant_impl.hpp b/SilKit/source/core/participant/Participant_impl.hpp index b4062808b..444335fc8 100644 --- a/SilKit/source/core/participant/Participant_impl.hpp +++ b/SilKit/source/core/participant/Participant_impl.hpp @@ -41,7 +41,8 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include "SystemMonitor.hpp" #include "LogMsgSender.hpp" #include "LogMsgReceiver.hpp" -#include "Logger.hpp" +#include "ILoggerInternal.hpp" +#include "StructuredLoggingKeys.hpp" #include "TimeProvider.hpp" #include "TimeSyncService.hpp" #include "ServiceDiscovery.hpp" @@ -112,13 +113,16 @@ Participant::Participant(Config::ParticipantConfiguration par // NB: do not create the _logger in the initializer list. If participantName is empty, // this will cause a fairly unintuitive exception in spdlog. _logger = std::make_unique(GetParticipantName(), _participantConfig.logging); - dynamic_cast(*_metricsProcessor).SetLogger(*_logger); dynamic_cast(*_metricsManager).SetLogger(*_logger); - _connection.SetLogger(_logger.get()); + _connection.SetLoggerInternal(_logger.get()); - Logging::Info(_logger.get(), "Creating participant '{}' at '{}', SIL Kit version: {}", GetParticipantName(), - _participantConfig.middleware.registryUri, Version::StringImpl()); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Info}; + lm.SetMessage("Creating participant"); + lm.SetKeyValue(Logging::Keys::participantName, GetParticipantName()); + lm.SetKeyValue(Logging::Keys::registryUri, _participantConfig.middleware.registryUri); + lm.SetKeyValue(Logging::Keys::silKitVersion, Version::StringImpl()); + lm.Dispatch(); } @@ -317,9 +321,13 @@ auto Participant::CreateCanController(const std::string& cano controller->RegisterServiceDiscovery(); - Logging::Trace(GetLogger(), "Created CAN controller '{}' for network '{}' with service name '{}'", - controllerConfig.name, controllerConfig.network.value(), - controller->GetServiceDescriptor().to_string()); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::network, controllerConfig.network.value()); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.Dispatch(); if (_replayScheduler) { @@ -352,9 +360,13 @@ auto Participant::CreateEthernetController( controller->RegisterServiceDiscovery(); - Logging::Trace(GetLogger(), "Created Ethernet controller '{}' for network '{}' with service name '{}'", - controllerConfig.name, controllerConfig.network.value(), - controller->GetServiceDescriptor().to_string()); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::network, controllerConfig.network.value()); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.Dispatch(); if (_replayScheduler) { @@ -387,9 +399,13 @@ auto Participant::CreateFlexrayController( controller->RegisterServiceDiscovery(); - Logging::Trace(GetLogger(), "Created FlexRay controller '{}' for network '{}' with service name '{}'", - controllerConfig.name, controllerConfig.network.value(), - controller->GetServiceDescriptor().to_string()); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::network, controllerConfig.network.value()); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.Dispatch(); auto* traceSource = dynamic_cast(controller); if (traceSource) @@ -416,9 +432,13 @@ auto Participant::CreateLinController(const std::string& cano controller->RegisterServiceDiscovery(); - Logging::Trace(GetLogger(), "Created LIN controller '{}' for network '{}' with service name '{}'", - controllerConfig.name, controllerConfig.network.value(), - controller->GetServiceDescriptor().to_string()); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::network, controllerConfig.network.value()); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.Dispatch(); if (_replayScheduler) { @@ -472,46 +492,6 @@ auto Participant::CreateDataSubscriberInternal( return controller; } -static inline auto FormatLabelsForLogging(const std::vector& labels) -> std::string -{ - std::ostringstream os; - - if (labels.empty()) - { - os << "(no labels)"; - } - - bool first = true; - - for (const auto& label : labels) - { - if (first) - { - first = false; - } - else - { - os << ", "; - } - - switch (label.kind) - { - case MatchingLabel::Kind::Optional: - os << "Optional"; - break; - case MatchingLabel::Kind::Mandatory: - os << "Mandatory"; - break; - default: - os << "MatchingLabel::Kind(" << static_cast>(label.kind) << ")"; - break; - } - - os << " '" << label.key << "': '" << label.value << "'"; - } - - return os.str(); -} template auto Participant::CreateDataPublisher(const std::string& canonicalName, @@ -558,12 +538,17 @@ auto Participant::CreateDataPublisher(const std::string& cano if (GetLogger()->GetLogLevel() <= Logging::Level::Trace) { - Logging::Trace( - GetLogger(), - "Created DataPublisher '{}' with topic '{}' and media type '{}' for network '{}' with service name " - "'{}' and labels: {}", - controllerConfig.name, controllerConfig.topic.value(), dataSpec.MediaType(), network, - controller->GetServiceDescriptor().to_string(), FormatLabelsForLogging(configuredDataNodeSpec.Labels())); + + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::pubSubTopic, configuredDataNodeSpec.Topic()); + lm.SetKeyValue(Logging::Keys::mediaType, configuredDataNodeSpec.MediaType()); + lm.SetKeyValue(Logging::Keys::network, network); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.SetKeyValue(configuredDataNodeSpec.Labels()); + lm.Dispatch(); } auto* traceSource = dynamic_cast(controller); @@ -623,12 +608,16 @@ auto Participant::CreateDataSubscriber( if (GetLogger()->GetLogLevel() <= Logging::Level::Trace) { - Logging::Trace( - GetLogger(), - "Created DataSubscriber '{}' with topic '{}' and media type '{}' for network '{}' with service name " - "'{}' and labels: {}", - controllerConfig.name, controllerConfig.topic.value(), dataSpec.MediaType(), network, - controller->GetServiceDescriptor().to_string(), FormatLabelsForLogging(configuredDataNodeSpec.Labels())); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::pubSubTopic, configuredDataNodeSpec.Topic()); + lm.SetKeyValue(Logging::Keys::mediaType, configuredDataNodeSpec.MediaType()); + lm.SetKeyValue(Logging::Keys::network, network); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.SetKeyValue(configuredDataNodeSpec.Labels()); + lm.Dispatch(); } auto* traceSource = dynamic_cast(controller); @@ -697,8 +686,8 @@ auto Participant::CreateRpcClient( // RpcClient gets discovered by RpcServer which creates RpcServerInternal on a matching connection Core::SupplementalData supplementalData; supplementalData[SilKit::Core::Discovery::controllerType] = SilKit::Core::Discovery::controllerTypeRpcClient; - supplementalData[SilKit::Core::Discovery::supplKeyRpcClientFunctionName] = controllerConfig.functionName.value(); - supplementalData[SilKit::Core::Discovery::supplKeyRpcClientMediaType] = dataSpec.MediaType(); + supplementalData[SilKit::Core::Discovery::supplKeyRpcClientFunctionName] = configuredRpcSpec.FunctionName(); + supplementalData[SilKit::Core::Discovery::supplKeyRpcClientMediaType] = configuredRpcSpec.MediaType(); supplementalData[SilKit::Core::Discovery::supplKeyRpcClientLabels] = SilKit::Config::Serialize(configuredRpcSpec.Labels()); supplementalData[SilKit::Core::Discovery::supplKeyRpcClientUUID] = network; @@ -712,12 +701,16 @@ auto Participant::CreateRpcClient( if (GetLogger()->GetLogLevel() <= Logging::Level::Trace) { - Logging::Trace( - GetLogger(), - "Created RPC Client '{}' with function name '{}' and media type '{}' for network '{}' with service name " - "'{}' and labels: {}", - controllerConfig.name, controllerConfig.functionName.value(), dataSpec.MediaType(), network, - controller->GetServiceDescriptor().to_string(), FormatLabelsForLogging(dataSpec.Labels())); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::controllerFuncName, configuredRpcSpec.FunctionName()); + lm.SetKeyValue(Logging::Keys::mediaType, configuredRpcSpec.MediaType()); + lm.SetKeyValue(Logging::Keys::network, network); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.SetKeyValue(configuredRpcSpec.Labels()); + lm.Dispatch(); } return controller; @@ -751,8 +744,8 @@ auto Participant::CreateRpcServer( Core::SupplementalData supplementalData; supplementalData[SilKit::Core::Discovery::controllerType] = SilKit::Core::Discovery::controllerTypeRpcServer; // Needed for RpcServer discovery in tests - supplementalData[SilKit::Core::Discovery::supplKeyRpcServerFunctionName] = controllerConfig.functionName.value(); - supplementalData[SilKit::Core::Discovery::supplKeyRpcServerMediaType] = dataSpec.MediaType(); + supplementalData[SilKit::Core::Discovery::supplKeyRpcServerFunctionName] = configuredRpcSpec.FunctionName(); + supplementalData[SilKit::Core::Discovery::supplKeyRpcServerMediaType] = configuredRpcSpec.MediaType(); supplementalData[SilKit::Core::Discovery::supplKeyRpcServerLabels] = SilKit::Config::Serialize(configuredRpcSpec.Labels()); @@ -764,12 +757,16 @@ auto Participant::CreateRpcServer( if (GetLogger()->GetLogLevel() <= Logging::Level::Trace) { - Logging::Trace( - GetLogger(), - "Created RPC Server '{}' with function name '{}' and media type '{}' for network '{}' with service name " - "'{}' and labels: {}", - controllerConfig.name, controllerConfig.functionName.value(), dataSpec.MediaType(), network, - controller->GetServiceDescriptor().to_string(), FormatLabelsForLogging(dataSpec.Labels())); + Logging::LoggerMessage lm{_logger.get(), Logging::Level::Trace}; + lm.SetMessage("Created controller"); + lm.SetKeyValue(Logging::Keys::controllerType, supplementalData[SilKit::Core::Discovery::controllerType]); + lm.SetKeyValue(Logging::Keys::controllerName, controllerConfig.name); + lm.SetKeyValue(Logging::Keys::controllerFuncName, configuredRpcSpec.FunctionName()); + lm.SetKeyValue(Logging::Keys::mediaType, configuredRpcSpec.MediaType()); + lm.SetKeyValue(Logging::Keys::network, network); + lm.SetKeyValue(Logging::Keys::serviceName, controller->GetServiceDescriptor().to_string()); + lm.SetKeyValue(configuredRpcSpec.Labels()); + lm.Dispatch(); } return controller; @@ -1333,7 +1330,7 @@ template template void Participant::SendMsgImpl(const IServiceEndpoint* from, SilKitMessageT&& msg) { - TraceTx(GetLogger(), from, msg); + TraceTx(GetLoggerInternal(), from, msg); _connection.SendMsg(from, std::forward(msg)); } @@ -1637,7 +1634,7 @@ template void Participant::SendMsgImpl(const IServiceEndpoint* from, const std::string& targetParticipantName, SilKitMessageT&& msg) { - TraceTx(GetLogger(), from, msg); + TraceTx(GetLoggerInternal(), from, msg); _connection.SendMsg(from, targetParticipantName, std::forward(msg)); } diff --git a/SilKit/source/core/vasio/SilKitLink.hpp b/SilKit/source/core/vasio/SilKitLink.hpp index dff061238..d041ce44c 100644 --- a/SilKit/source/core/vasio/SilKitLink.hpp +++ b/SilKit/source/core/vasio/SilKitLink.hpp @@ -42,9 +42,10 @@ class SilKitLink public: // ---------------------------------------- // Constructors and Destructor - SilKitLink(std::string name, Services::Logging::ILogger* logger, + SilKitLink(std::string name, Services::Logging::ILoggerInternal* logger, Services::Orchestration::ITimeProvider* timeProvider); + public: // ---------------------------------------- // Public methods @@ -85,7 +86,7 @@ class SilKitLink // ---------------------------------------- // private members std::string _name; - Services::Logging::ILogger* _logger; + Services::Logging::ILoggerInternal* _logger; Services::Orchestration::ITimeProvider* _timeProvider; std::vector _localReceivers; @@ -96,8 +97,9 @@ class SilKitLink // Inline Implementations // ================================================================================ template -SilKitLink::SilKitLink(std::string name, Services::Logging::ILogger* logger, +SilKitLink::SilKitLink(std::string name, Services::Logging::ILoggerInternal* logger, Services::Orchestration::ITimeProvider* timeProvider) + : _name{std::move(name)} , _logger{logger} , _timeProvider{timeProvider} diff --git a/SilKit/source/core/vasio/Test_VAsioConnection.cpp b/SilKit/source/core/vasio/Test_VAsioConnection.cpp index 3d886eb50..8c4b8708e 100644 --- a/SilKit/source/core/vasio/Test_VAsioConnection.cpp +++ b/SilKit/source/core/vasio/Test_VAsioConnection.cpp @@ -178,7 +178,7 @@ class Test_VAsioConnection : public testing::Test Test_VAsioConnection() : _connection(nullptr, &_dummyMetricsManager, {}, "Test_VAsioConnection", 1, &_timeProvider) { - _connection.SetLogger(&_dummyLogger); + _connection.SetLoggerInternal(&_dummyLogger); } Tests::MockLogger _dummyLogger; diff --git a/SilKit/source/core/vasio/VAsioConnection.cpp b/SilKit/source/core/vasio/VAsioConnection.cpp index 7e9767fa9..fba7f4763 100644 --- a/SilKit/source/core/vasio/VAsioConnection.cpp +++ b/SilKit/source/core/vasio/VAsioConnection.cpp @@ -300,7 +300,7 @@ VAsioConnection::~VAsioConnection() } } -void VAsioConnection::SetLogger(Services::Logging::ILogger* logger) +void VAsioConnection::SetLoggerInternal(Services::Logging::ILoggerInternal* logger) { _logger = logger; @@ -308,7 +308,7 @@ void VAsioConnection::SetLogger(Services::Logging::ILogger* logger) _connectKnownParticipants.SetLogger(*_logger); } -auto VAsioConnection::GetLogger() -> SilKit::Services::Logging::ILogger* +auto VAsioConnection::GetLoggerInternal() -> SilKit::Services::Logging::ILoggerInternal* { return _logger; } diff --git a/SilKit/source/core/vasio/VAsioConnection.hpp b/SilKit/source/core/vasio/VAsioConnection.hpp index 85d6acd93..cbf5d14e4 100644 --- a/SilKit/source/core/vasio/VAsioConnection.hpp +++ b/SilKit/source/core/vasio/VAsioConnection.hpp @@ -105,8 +105,8 @@ class VAsioConnection public: // ---------------------------------------- // Public methods - void SetLogger(Services::Logging::ILogger* logger); - auto GetLogger() -> SilKit::Services::Logging::ILogger*; + void SetLoggerInternal(Services::Logging::ILoggerInternal* logger); + auto GetLoggerInternal() -> SilKit::Services::Logging::ILoggerInternal*; void JoinSimulation(std::string registryUri); @@ -487,7 +487,7 @@ class VAsioConnection SilKit::Config::ParticipantConfiguration _config; std::string _participantName; ParticipantId _participantId{0}; - Services::Logging::ILogger* _logger{nullptr}; + Services::Logging::ILoggerInternal* _logger{nullptr}; Services::Orchestration::ITimeProvider* _timeProvider{nullptr}; std::string _simulationName; diff --git a/SilKit/source/core/vasio/VAsioReceiver.hpp b/SilKit/source/core/vasio/VAsioReceiver.hpp index 7e46a7c8e..1d2d31174 100644 --- a/SilKit/source/core/vasio/VAsioReceiver.hpp +++ b/SilKit/source/core/vasio/VAsioReceiver.hpp @@ -28,6 +28,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include "MessageTracing.hpp" #include "IServiceEndpoint.hpp" #include "SerializedMessage.hpp" +#include "ILoggerInternal.hpp" namespace SilKit { namespace Core { @@ -74,7 +75,8 @@ class VAsioReceiver // ---------------------------------------- // Constructors and Destructor VAsioReceiver(VAsioMsgSubscriber subscriberInfo, std::shared_ptr> link, - Services::Logging::ILogger* logger); + Services::Logging::ILoggerInternal* logger); + public: // ---------------------------------------- @@ -95,7 +97,7 @@ class VAsioReceiver // private members VAsioMsgSubscriber _subscriptionInfo; std::shared_ptr> _link; - Services::Logging::ILogger* _logger; + Services::Logging::ILoggerInternal* _logger; ServiceDescriptor _serviceDescriptor; }; @@ -104,7 +106,7 @@ class VAsioReceiver // ================================================================================ template VAsioReceiver::VAsioReceiver(VAsioMsgSubscriber subscriberInfo, std::shared_ptr> link, - Services::Logging::ILogger* logger) + Services::Logging::ILoggerInternal* logger) : _subscriptionInfo{std::move(subscriberInfo)} , _link{link} , _logger{logger} diff --git a/SilKit/source/core/vasio/VAsioRegistry.cpp b/SilKit/source/core/vasio/VAsioRegistry.cpp index 3d25c6bdc..6466d1c6a 100644 --- a/SilKit/source/core/vasio/VAsioRegistry.cpp +++ b/SilKit/source/core/vasio/VAsioRegistry.cpp @@ -66,12 +66,12 @@ VAsioRegistry::VAsioRegistry(std::shared_ptrOnLoggerCreated(_logger.get()); + _registryEventListener->OnLoggerInternalCreated(_logger.get()); } dynamic_cast(*_metricsProcessor).SetLogger(*_logger); dynamic_cast(*_metricsManager).SetLogger(*_logger); - _connection.SetLogger(_logger.get()); + _connection.SetLoggerInternal(_logger.get()); _connection.RegisterMessageReceiver([this](IVAsioPeer* from, const ParticipantAnnouncement& announcement) { this->OnParticipantAnnouncement(from, announcement); diff --git a/SilKit/source/core/vasio/VAsioRegistry.hpp b/SilKit/source/core/vasio/VAsioRegistry.hpp index 2dece0f13..1c6d71421 100644 --- a/SilKit/source/core/vasio/VAsioRegistry.hpp +++ b/SilKit/source/core/vasio/VAsioRegistry.hpp @@ -48,7 +48,7 @@ struct IRegistryEventListener { virtual ~IRegistryEventListener() = default; - virtual void OnLoggerCreated(SilKit::Services::Logging::ILogger* logger) = 0; + virtual void OnLoggerInternalCreated(SilKit::Services::Logging::ILoggerInternal* logger) = 0; virtual void OnRegistryUri(const std::string& registryUri) = 0; virtual void OnParticipantConnected(const std::string& simulationName, const std::string& participantName) = 0; virtual void OnParticipantDisconnected(const std::string& simulationName, const std::string& participantName) = 0; @@ -124,7 +124,7 @@ class VAsioRegistry private: // ---------------------------------------- // private members - std::unique_ptr _logger; + std::unique_ptr _logger; IRegistryEventListener* _registryEventListener{nullptr}; std::unordered_map> _connectedParticipants; std::function _onAllParticipantsConnected; diff --git a/SilKit/source/dashboard/DashboardInstance.cpp b/SilKit/source/dashboard/DashboardInstance.cpp index bac4f8296..7430a4ae5 100644 --- a/SilKit/source/dashboard/DashboardInstance.cpp +++ b/SilKit/source/dashboard/DashboardInstance.cpp @@ -435,11 +435,7 @@ void DashboardInstance::RemoveSimulationData(const std::string &simulationName) _simulationEventHandlers.erase(simulationName); } - -// SilKit::Core::IRegistryEventListener - - -void DashboardInstance::OnLoggerCreated(SilKit::Services::Logging::ILogger *logger) +void DashboardInstance::OnLoggerInternalCreated(SilKit::Services::Logging::ILoggerInternal *logger) { SILKIT_ASSERT(_logger == nullptr); _logger = logger; diff --git a/SilKit/source/dashboard/DashboardInstance.hpp b/SilKit/source/dashboard/DashboardInstance.hpp index 61a9d5c8a..593b1f7b8 100644 --- a/SilKit/source/dashboard/DashboardInstance.hpp +++ b/SilKit/source/dashboard/DashboardInstance.hpp @@ -7,7 +7,8 @@ #include "IDashboardInstance.hpp" #include "VAsioRegistry.hpp" -#include "silkit/services/logging/ILogger.hpp" +#include "ILoggerInternal.hpp" + #include "silkit/config/IParticipantConfiguration.hpp" #include "CachingSilKitEventHandler.hpp" @@ -59,7 +60,7 @@ class DashboardInstance final void RunBulkUpdateEventQueueWorkerThread(); private: // SilKit::Core::IRegistryEventListener - void OnLoggerCreated(SilKit::Services::Logging::ILogger* logger) override; + void OnLoggerInternalCreated(SilKit::Services::Logging::ILoggerInternal* logger) override; void OnRegistryUri(const std::string& registryUri) override; void OnParticipantConnected(std::string const& simulationName, std::string const& participantName) override; void OnParticipantDisconnected(std::string const& simulationName, std::string const& participantName) override; @@ -73,7 +74,7 @@ class DashboardInstance final private: /// Assigned in OnLoggerCreated - SilKit::Services::Logging::ILogger* _logger{nullptr}; + SilKit::Services::Logging::ILoggerInternal* _logger{nullptr}; /// Assigned in OnRegistryUri std::unique_ptr _registryUri; diff --git a/SilKit/source/services/logging/CMakeLists.txt b/SilKit/source/services/logging/CMakeLists.txt index 2dfd8f2b7..76c07add0 100644 --- a/SilKit/source/services/logging/CMakeLists.txt +++ b/SilKit/source/services/logging/CMakeLists.txt @@ -72,6 +72,7 @@ add_library(O_SilKit_Services_Logging OBJECT LoggingSerdes.hpp LoggingSerdes.cpp + StructuredLoggingKeys.hpp ) target_link_libraries(O_SilKit_Services_Logging diff --git a/SilKit/source/services/logging/ILoggerInternal.hpp b/SilKit/source/services/logging/ILoggerInternal.hpp index bc0da6ffe..c897a1fd6 100644 --- a/SilKit/source/services/logging/ILoggerInternal.hpp +++ b/SilKit/source/services/logging/ILoggerInternal.hpp @@ -25,12 +25,13 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include "silkit/services/logging/ILogger.hpp" +#include "StructuredLoggingKeys.hpp" #include "SilKitFmtFormatters.hpp" #include "fmt/format.h" -#include #include + namespace SilKit { namespace Services { namespace Logging { @@ -45,9 +46,10 @@ struct ILoggerInternal : ILogger }; +// forwards template void Log(ILogger* logger, Level level, const char* fmt, const Args&... args); - +inline auto FormatLabelsForLogging(const std::vector& labels) -> std::string; class LoggerMessage { @@ -72,21 +74,61 @@ class LoggerMessage { } + template - void SetMessage(fmt::format_string fmt, Args&&... args) + void FormatMessage(fmt::format_string fmt, Args&&... args) { - _msg = fmt::format(fmt, std::forward(args)...); + if (_logger->GetLogLevel() <= _level) + { + _msg = fmt::format(fmt, std::forward(args)...); + } } void SetMessage(std::string newMsg) { - _msg = std::move(newMsg); + if (_logger->GetLogLevel() <= _level) + { + _msg = std::move(newMsg); + } } + + template + void FormatKeyValue(Key&& key, fmt::format_string fmt, Args&&... args) + { + if (_logger->GetLogLevel() <= _level) + { + auto&& formattedValue = fmt::format(fmt, std::forward(args)...); + _keyValues.emplace_back(std::forward(key), formattedValue); + } + } + + + void SetKeyValue(const std::vector& labels) + { + if (_logger->GetLogLevel() <= _level) + { + SetKeyValue(Keys::label, FormatLabelsForLogging(labels)); + } + } + + void SetKeyValue(const Core::ServiceDescriptor& descriptor) + { + if (_logger->GetLogLevel() <= _level) + { + for (const auto& pair : descriptor.to_keyValues()) + { + SetKeyValue(pair.first, pair.second); + } + } + } template void SetKeyValue(Key&& key, Value&& value) { - _keyValues[std::forward(key)] = std::forward(value); + if (_logger->GetLogLevel() <= _level) + { + _keyValues.emplace_back(std::forward(key), std::forward(value)); + } } auto GetLevel() const -> Level @@ -94,26 +136,16 @@ class LoggerMessage return _level; } - auto GetKeyValues() const -> const std::unordered_map& + auto GetKeyValues() const -> const std::vector>& { return _keyValues; } - bool HasKeyValues() const - { - return !_keyValues.empty(); - } - auto GetMsgString() const -> const std::string& { return _msg; } - auto GetLogger() const -> ILoggerInternal* - { - return _logger; - } - void Dispatch() { if (_logger->GetLogLevel() <= _level) @@ -126,7 +158,7 @@ class LoggerMessage ILoggerInternal* _logger; Level _level; std::string _msg; - std::unordered_map _keyValues; + std::vector> _keyValues; }; @@ -210,6 +242,49 @@ void Critical(ILogger* logger, const char* fmt, const Args&... args) { Log(logger, Level::Critical, fmt, args...); } + + +inline auto FormatLabelsForLogging(const std::vector& labels) -> std::string +{ + std::ostringstream os; + + if (labels.empty()) + { + os << "(no labels)"; + } + + bool first = true; + + for (const auto& label : labels) + { + if (first) + { + first = false; + } + else + { + os << ", "; + } + + switch (label.kind) + { + case MatchingLabel::Kind::Optional: + os << "Optional"; + break; + case MatchingLabel::Kind::Mandatory: + os << "Mandatory"; + break; + default: + os << "MatchingLabel::Kind(" << static_cast>(label.kind) + << ")"; + break; + } + + os << " '" << label.key << "': '" << label.value << "'"; + } + + return os.str(); +} } // namespace Logging } // namespace Services } // namespace SilKit diff --git a/SilKit/source/services/logging/Logger.cpp b/SilKit/source/services/logging/Logger.cpp index ae03835d3..c59d0ba4f 100644 --- a/SilKit/source/services/logging/Logger.cpp +++ b/SilKit/source/services/logging/Logger.cpp @@ -22,7 +22,6 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include #include #include -#include #include #include "Logger.hpp" @@ -53,13 +52,13 @@ class LoggerMessage; struct SimpleLogMessage { const std::string& msg; - const std::unordered_map& kv; + const std::vector>& kv; }; struct JsonLogMessage { const std::string& msg; - const std::unordered_map& kv; + const std::vector>& kv; }; struct JsonString @@ -90,12 +89,12 @@ class epoch_formatter_flag : public spdlog::custom_flag_formatter }; -std::string KeyValuesToSimpleString(const std::unordered_map& input) +std::string KeyValuesToSimpleString(const std::vector>& input) { std::string result; result.reserve(input.size() * 2); - std::unordered_map::const_iterator it = input.begin(); + std::vector>::const_iterator it = input.begin(); while (it != input.end()) { @@ -103,18 +102,18 @@ std::string KeyValuesToSimpleString(const std::unordered_mapfirst) + ": " + SilKit::Util::EscapeString(it->second)); + result.append(it->first + ": " + it->second); ++it; } return result; } -std::string KeyValuesToJsonString(const std::unordered_map& input) +std::string KeyValuesToJsonString(const std::vector>& input) { std::string result; result.reserve(input.size() * 2); - std::unordered_map::const_iterator it = input.begin(); + std::vector>::const_iterator it = input.begin(); result.append("{"); while (it != input.end()) { @@ -132,6 +131,7 @@ std::string KeyValuesToJsonString(const std::unordered_map struct fmt::formatter { diff --git a/SilKit/source/services/logging/MessageTracing.hpp b/SilKit/source/services/logging/MessageTracing.hpp index ca1f33547..cd63da7ec 100644 --- a/SilKit/source/services/logging/MessageTracing.hpp +++ b/SilKit/source/services/logging/MessageTracing.hpp @@ -24,26 +24,75 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include "ILoggerInternal.hpp" #include "IServiceEndpoint.hpp" #include "ServiceDescriptor.hpp" +#include "traits/SilKitMsgTraits.hpp" + namespace SilKit { namespace Services { + +template +std::chrono::nanoseconds GetTimestamp(MsgT& msg, + std::enable_if_t::value, bool> = true) +{ + return msg.timestamp; +} + +template +std::chrono::nanoseconds GetTimestamp(MsgT& /*msg*/, + std::enable_if_t::value, bool> = false) +{ + return std::chrono::nanoseconds::duration::min(); +} + + + + template -void TraceRx(Logging::ILogger* logger, const Core::IServiceEndpoint* addr, const SilKitMessageT& msg, +void TraceRx(Logging::ILoggerInternal* logger, const Core::IServiceEndpoint* addr, const SilKitMessageT& msg, const Core::ServiceDescriptor& from) { - Logging::Trace(logger, "Recv on {} from {}: {}", addr->GetServiceDescriptor(), from.GetParticipantName(), msg); + if (logger->GetLogLevel() == Logging::Level::Trace) + { + Logging::LoggerMessage lm{logger, Logging::Level::Trace}; + lm.SetMessage("Recv message"); + lm.SetKeyValue(addr->GetServiceDescriptor()); + lm.SetKeyValue(Logging::Keys::from, from.GetParticipantName()); + lm.FormatKeyValue(Logging::Keys::msg, "{}", msg); + + auto virtualTimeStamp = GetTimestamp(msg); + if (virtualTimeStamp != std::chrono::nanoseconds::duration::min()) + { + lm.FormatKeyValue(Logging::Keys::virtualTimeNS, "{}", virtualTimeStamp.count()); + } + lm.Dispatch(); + } } template -void TraceTx(Logging::ILogger* logger, const Core::IServiceEndpoint* addr, const SilKitMessageT& msg) +void TraceTx(Logging::ILoggerInternal* logger, const Core::IServiceEndpoint* addr, const SilKitMessageT& msg) { - Logging::Trace(logger, "Send from {}: {}", addr->GetServiceDescriptor(), msg); + if (logger->GetLogLevel() == Logging::Level::Trace) + { + Logging::LoggerMessage lm{logger, Logging::Level::Trace}; + lm.SetMessage("Send message"); + lm.SetKeyValue(addr->GetServiceDescriptor()); + lm.FormatKeyValue(Logging::Keys::msg, "{}", msg); + + auto virtualTimeStamp = GetTimestamp(msg); + if (virtualTimeStamp != std::chrono::nanoseconds::duration::min()) + { + lm.FormatKeyValue(Logging::Keys::virtualTimeNS, "{}", virtualTimeStamp.count()); + } + lm.Dispatch(); + } } // Don't trace LogMessages - this could cause cycles! -inline void TraceRx(Logging::ILogger* /*logger*/, Core::IServiceEndpoint* /*addr*/, const Logging::LogMsg& /*msg*/) {} -inline void TraceTx(Logging::ILogger* /*logger*/, Core::IServiceEndpoint* /*addr*/, const Logging::LogMsg& /*msg*/) {} +inline void TraceRx(Logging::ILoggerInternal* /*logger*/, Core::IServiceEndpoint* /*addr*/, const Logging::LogMsg& /*msg*/) {} +inline void TraceTx(Logging::ILoggerInternal* /*logger*/, Core::IServiceEndpoint* /*addr*/, const Logging::LogMsg& /*msg*/) {} +inline void TraceRx(Logging::ILoggerInternal* /*logger*/, Core::IServiceEndpoint* /*addr*/, Logging::LogMsg&& /*msg*/) {} +inline void TraceTx(Logging::ILoggerInternal* /*logger*/, Core::IServiceEndpoint* /*addr*/, Logging::LogMsg&& /*msg*/) {} } // namespace Services } // namespace SilKit diff --git a/SilKit/source/services/logging/StructuredLoggingKeys.hpp b/SilKit/source/services/logging/StructuredLoggingKeys.hpp new file mode 100644 index 000000000..c17f295e5 --- /dev/null +++ b/SilKit/source/services/logging/StructuredLoggingKeys.hpp @@ -0,0 +1,67 @@ +/* Copyright (c) 2022 Vector Informatik GmbH + +Permission is hereby granted, free of charge, to any person obtaining +a copy of this software and associated documentation files (the +"Software"), to deal in the Software without restriction, including +without limitation the rights to use, copy, modify, merge, publish, +distribute, sublicense, and/or sell copies of the Software, and to +permit persons to whom the Software is furnished to do so, subject to +the following conditions: + +The above copyright notice and this permission notice shall be +included in all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, +EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF +MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND +NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE +LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION +OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION +WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ + +#pragma once + +#include +#include + +namespace SilKit { +namespace Services { +namespace Logging { +namespace Keys { + +const std::string virtualTimeNS{"VirtualTimeNS"}; +const std::string msg{"Msg"}; +const std::string from{"From"}; + +const std::string waitingTime{"WaitingTime"}; +const std::string executionTime{"ExecutionTime"}; + +const std::string participantName{"ParticipantName"}; +const std::string registryUri{"RegistryUri"}; +const std::string silKitVersion{"SilKitVersion"}; + +const std::string newParticipantState{"NewParticipantState"}; +const std::string oldParticipantState{"OldParticipantState"}; +const std::string enterTime{"EnterTime"}; +const std::string enterReason{"EnterReason"}; + +const std::string serviceType{"ServiceType"}; +const std::string serviceName{"ServiceName"}; +const std::string networkType{"NetworkType"}; +const std::string networkName{"NetworkName"}; +const std::string controllerTypeName{"ControllerTypeName"}; + + +const std::string controllerName{"ControllerName"}; +const std::string controllerType{"ControllerType"}; +const std::string pubSubTopic{"PubSubTopic"}; +const std::string controllerFuncName{"ControllerFuncName"}; +const std::string mediaType{"MediaType"}; +const std::string network{"Network"}; +const std::string label{"Label"}; + + +} // namespace Keys +} // namespace Logging +} // namespace Services +} // namespace SilKit diff --git a/SilKit/source/services/logging/Test_Logger.cpp b/SilKit/source/services/logging/Test_Logger.cpp index 62e334fc8..3bfb3b525 100644 --- a/SilKit/source/services/logging/Test_Logger.cpp +++ b/SilKit/source/services/logging/Test_Logger.cpp @@ -22,7 +22,6 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include #include #include -#include #include "gtest/gtest.h" #include "gmock/gmock.h" @@ -72,8 +71,9 @@ auto ALogMsgWith(std::string loggerName, Level level, std::string payload) -> Ma ); } + auto ALogMsgWith(std::string loggerName, Level level, std::string payload, - std::unordered_map keyValues) -> Matcher + std::vector> keyValues) -> Matcher { return AllOf(Field(&LogMsg::loggerName, loggerName), Field(&LogMsg::level, level), Field(&LogMsg::payload, payload), Field(&LogMsg::keyValues, keyValues)); @@ -135,8 +135,7 @@ TEST(Test_Logger, send_log_message_from_logger) EXPECT_CALL(mockParticipant, SendMsg_LogMsg(testing::_, ALogMsgWith(loggerName, Level::Info, payload))).Times(1); - EXPECT_CALL(mockParticipant, SendMsg_LogMsg(testing::_, ALogMsgWith(loggerName, Level::Critical, payload))) - .Times(1); + EXPECT_CALL(mockParticipant, SendMsg_LogMsg(testing::_, ALogMsgWith(loggerName, Level::Critical, payload))).Times(1); logger.Info(payload); logger.Critical(payload); @@ -172,7 +171,6 @@ TEST(Test_Logger, LogOnceFlag_check_setter) EXPECT_EQ(once.WasCalled(), true); } - TEST(Test_Logger, send_loggermessage_from_logger) { std::string loggerName{"ParticipantAndLogger"}; @@ -196,7 +194,7 @@ TEST(Test_Logger, send_loggermessage_from_logger) std::string payload{"Test log message"}; std::string key{"TestKey"}; std::string value{"TestValue"}; - std::unordered_map keyValue{{key, value}}; + std::vector> keyValue{{key, value}}; EXPECT_CALL(mockParticipant, SendMsg_LogMsg(&logMsgSender, ALogMsgWith(loggerName, Level::Debug, payload, keyValue))) diff --git a/SilKit/source/services/orchestration/SystemMonitor.cpp b/SilKit/source/services/orchestration/SystemMonitor.cpp index 431c977ff..1dab9f878 100644 --- a/SilKit/source/services/orchestration/SystemMonitor.cpp +++ b/SilKit/source/services/orchestration/SystemMonitor.cpp @@ -37,7 +37,7 @@ namespace Services { namespace Orchestration { SystemMonitor::SystemMonitor(Core::IParticipantInternal* participant) - : _logger{participant->GetLogger()} + : _logger{participant->GetLoggerInternal()} , _participant{participant} { _systemStateTracker.SetLogger(_logger); diff --git a/SilKit/source/services/orchestration/SystemMonitor.hpp b/SilKit/source/services/orchestration/SystemMonitor.hpp index ac0802fe7..44f53c460 100644 --- a/SilKit/source/services/orchestration/SystemMonitor.hpp +++ b/SilKit/source/services/orchestration/SystemMonitor.hpp @@ -112,7 +112,7 @@ class SystemMonitor // ---------------------------------------- // private members Core::ServiceDescriptor _serviceDescriptor{}; - Services::Logging::ILogger* _logger{nullptr}; + Services::Logging::ILoggerInternal* _logger{nullptr}; Core::IParticipantInternal* _participant{nullptr}; VSilKit::SystemStateTracker _systemStateTracker; diff --git a/SilKit/source/services/orchestration/SystemStateTracker.cpp b/SilKit/source/services/orchestration/SystemStateTracker.cpp index d50497a31..f1b8bb4d8 100644 --- a/SilKit/source/services/orchestration/SystemStateTracker.cpp +++ b/SilKit/source/services/orchestration/SystemStateTracker.cpp @@ -92,7 +92,7 @@ auto FormatTimePoint(std::chrono::system_clock::time_point timePoint) -> std::st namespace VSilKit { -void SystemStateTracker::SetLogger(SilKit::Services::Logging::ILogger* logger) +void SystemStateTracker::SetLogger(SilKit::Services::Logging::ILoggerInternal* logger) { _logger = logger; } @@ -139,35 +139,40 @@ auto SystemStateTracker::UpdateParticipantStatus(const ParticipantStatus& newPar const auto oldParticipantState{participantStatus.state}; const auto newParticipantState{newParticipantStatus.state}; - - Log::Debug(_logger, "Updating participant status for {} from {} to {}", participantName, oldParticipantState, - newParticipantState); + { + Log::LoggerMessage lm{_logger, Log::Level::Debug}; + lm.SetMessage("Updating participant status"); + lm.SetKeyValue(Log::Keys::participantName, participantName); + lm.FormatKeyValue(Log::Keys::oldParticipantState, "{}", oldParticipantState); + lm.FormatKeyValue(Log::Keys::newParticipantState, "{}", newParticipantState); + lm.Dispatch(); + } // Check if transition from the old to the new participant state is valid - if (!ValidateParticipantStateUpdate(oldParticipantState, newParticipantState)) { const auto logLevel = IsRequiredParticipant(participantName) ? Log::Level::Warn : Log::Level::Debug; - Log::Log(_logger, logLevel, - "SystemMonitor detected invalid ParticipantState transition for {} from {} to {} EnterTime={}, " - "EnterReason=\"{}\"", - participantName, oldParticipantState, newParticipantState, - FormatTimePoint(newParticipantStatus.enterTime), newParticipantStatus.enterReason); + Log::LoggerMessage lm{_logger, logLevel}; + lm.SetMessage("SystemMonitor detected invalid ParticipantState transition!"); + lm.SetKeyValue(Log::Keys::participantName, participantName); + lm.FormatKeyValue(Log::Keys::oldParticipantState, "{}", oldParticipantState); + lm.FormatKeyValue(Log::Keys::newParticipantState, "{}", newParticipantState); + lm.SetKeyValue(Log::Keys::enterTime, FormatTimePoint(newParticipantStatus.enterTime)); + lm.SetKeyValue(Log::Keys::enterReason, newParticipantStatus.enterReason); + lm.Dispatch(); // NB: Failing validation doesn't actually stop the participants state from being changed, it just logs the // invalid transition } // Ignores transition if ParticipantState is Shutdown already - if (oldParticipantState == ParticipantState::Shutdown) { return UpdateParticipantStatusResult{}; } // Update the stored participant status and recompute the system state if required - SetParticipantStatus(participantName, newParticipantStatus); UpdateParticipantStatusResult result; @@ -175,19 +180,35 @@ auto SystemStateTracker::UpdateParticipantStatus(const ParticipantStatus& newPar if (oldParticipantState != newParticipantState) { result.participantStateChanged = true; - - Log::Debug(_logger, "The participant state has changed for {}", participantName); + { + Log::LoggerMessage lm{_logger, Log::Level::Debug}; + lm.SetMessage("The participant state has changed!"); + lm.SetKeyValue(Log::Keys::participantName, participantName); + lm.Dispatch(); + } if (IsRequiredParticipant(participantName)) { const auto oldSystemState{_systemState}; const auto newSystemState{ComputeSystemState(newParticipantState)}; - Log::Debug(_logger, "Computed new system state update from {} to {}", oldSystemState, newSystemState); + { + Log::LoggerMessage lm{_logger, Log::Level::Debug}; + lm.SetMessage("Computed new system state update!"); + lm.SetKeyValue(Log::Keys::participantName, participantName); + lm.FormatKeyValue(Log::Keys::oldParticipantState, "{}", oldSystemState); + lm.FormatKeyValue(Log::Keys::newParticipantState, "{}", newSystemState); + lm.Dispatch(); + } if (oldSystemState != newSystemState) { - Log::Debug(_logger, "The system state has changed from {} to {}", oldSystemState, newSystemState); + Log::LoggerMessage lm{_logger, Log::Level::Debug}; + lm.SetMessage("The system state has changed!"); + lm.SetKeyValue(Log::Keys::participantName, participantName); + lm.FormatKeyValue(Log::Keys::oldParticipantState, "{}", oldSystemState); + lm.FormatKeyValue(Log::Keys::newParticipantState, "{}", newSystemState); + lm.Dispatch(); _systemState = newSystemState; result.systemStateChanged = true; diff --git a/SilKit/source/services/orchestration/SystemStateTracker.hpp b/SilKit/source/services/orchestration/SystemStateTracker.hpp index 8d413503a..1b5d37f5c 100644 --- a/SilKit/source/services/orchestration/SystemStateTracker.hpp +++ b/SilKit/source/services/orchestration/SystemStateTracker.hpp @@ -6,7 +6,7 @@ #include "silkit/services/orchestration/OrchestrationDatatypes.hpp" -#include "silkit/services/logging/ILogger.hpp" +#include "ILoggerInternal.hpp" #include "silkit/util/Span.hpp" #include @@ -42,7 +42,7 @@ class SystemStateTracker }; public: - void SetLogger(SilKit::Services::Logging::ILogger* logger); + void SetLogger(SilKit::Services::Logging::ILoggerInternal* logger); auto IsEmpty() const -> bool; @@ -66,7 +66,7 @@ class SystemStateTracker private: mutable std::recursive_mutex _mutex; - SilKit::Services::Logging::ILogger* _logger{nullptr}; + SilKit::Services::Logging::ILoggerInternal* _logger{nullptr}; std::unordered_set _requiredParticipants; SystemState _systemState{}; diff --git a/SilKit/source/services/orchestration/TimeConfiguration.cpp b/SilKit/source/services/orchestration/TimeConfiguration.cpp index 907d631a9..ad4600eed 100644 --- a/SilKit/source/services/orchestration/TimeConfiguration.cpp +++ b/SilKit/source/services/orchestration/TimeConfiguration.cpp @@ -26,7 +26,8 @@ namespace SilKit { namespace Services { namespace Orchestration { -TimeConfiguration::TimeConfiguration(Logging::ILogger* logger) + +TimeConfiguration::TimeConfiguration(Logging::ILoggerInternal* logger) : _blocking(false) , _logger(logger) diff --git a/SilKit/source/services/orchestration/TimeConfiguration.hpp b/SilKit/source/services/orchestration/TimeConfiguration.hpp index 691abf8f4..af29776bd 100755 --- a/SilKit/source/services/orchestration/TimeConfiguration.hpp +++ b/SilKit/source/services/orchestration/TimeConfiguration.hpp @@ -25,7 +25,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ #include #include "OrchestrationDatatypes.hpp" -#include "silkit/services/logging/ILogger.hpp" +#include "ILoggerInternal.hpp" namespace SilKit { namespace Services { @@ -35,7 +35,7 @@ using namespace std::chrono_literals; class TimeConfiguration { public: //Ctor - TimeConfiguration(Logging::ILogger* logger); + TimeConfiguration(Logging::ILoggerInternal* logger); public: //Methods void SetBlockingMode(bool blocking); @@ -66,7 +66,7 @@ class TimeConfiguration bool _blocking; bool _hoppedOn = false; - Logging::ILogger* _logger; + Logging::ILoggerInternal* _logger; }; } // namespace Orchestration diff --git a/SilKit/source/services/orchestration/TimeSyncService.cpp b/SilKit/source/services/orchestration/TimeSyncService.cpp index 3d1d45316..7e0791d21 100644 --- a/SilKit/source/services/orchestration/TimeSyncService.cpp +++ b/SilKit/source/services/orchestration/TimeSyncService.cpp @@ -285,9 +285,9 @@ TimeSyncService::TimeSyncService(Core::IParticipantInternal* participant, ITimeP double animationFactor) : _participant{participant} , _lifecycleService{lifecycleService} - , _logger{participant->GetLogger()} + , _logger{participant->GetLoggerInternal()} , _timeProvider{timeProvider} - , _timeConfiguration{participant->GetLogger()} + , _timeConfiguration{participant->GetLoggerInternal()} , _simStepCounterMetric{participant->GetMetricsManager()->GetCounter("SimStepCount")} , _simStepHandlerExecutionTimeStatisticMetric{participant->GetMetricsManager()->GetStatistic("SimStepHandlerExecutionDuration")} , _simStepCompletionTimeStatisticMetric{participant->GetMetricsManager()->GetStatistic("SimStepCompletionDuration")} @@ -471,8 +471,10 @@ void TimeSyncService::ReceiveMsg(const IServiceEndpoint* from, const NextSimTask } else { - Logging::Debug(_logger, "Received NextSimTask from participant \'{}\' but TimeSyncPolicy is not yet configured", - from->GetServiceDescriptor().GetParticipantName()); + Logging::LoggerMessage lm{_logger, Logging::Level::Debug}; + lm.SetMessage("Received NextSimTask from participant \'{}\' but TimeSyncPolicy is not yet configured"); + lm.SetKeyValue(Logging::Keys::participantName, from->GetServiceDescriptor().GetParticipantName()); + lm.Dispatch(); } } @@ -487,7 +489,14 @@ void TimeSyncService::ExecuteSimStep(std::chrono::nanoseconds timePoint, std::ch const auto waitingDurationMs = std::chrono::duration_cast(waitingDuration); const auto waitingDurationS = std::chrono::duration_cast(waitingDuration); - Trace(_logger, "Starting next Simulation Task. Waiting time was: {}ms", waitingDurationMs.count()); + { + Logging::LoggerMessage lm{_logger, Logging::Level::Trace}; + lm.SetMessage("Starting next Simulation Step."); + lm.FormatKeyValue(Logging::Keys::waitingTime, "{}", std::chrono::duration_cast(_waitTimeMonitor.CurrentDuration()).count()); + lm.FormatKeyValue(Logging::Keys::virtualTimeNS, "{}", timePoint.count()); + lm.Dispatch(); + } + if (_waitTimeMonitor.SampleCount() > 1) { // skip the first sample, since it was never 'started' (it is always the current epoch of the underlying clock) @@ -522,9 +531,13 @@ void TimeSyncService::ExecuteSimStep(std::chrono::nanoseconds timePoint, std::ch } void TimeSyncService::LogicalSimStepCompleted(std::chrono::duration logicalSimStepTimeMs) -{ +{ _simStepCounterMetric->Add(1); - Trace(_logger, "Finished Simulation Step. Execution time was: {}ms", logicalSimStepTimeMs.count()); + Logging::LoggerMessage lm{_logger, Logging::Level::Trace}; + lm.SetMessage("Finished Simulation Step."); + lm.FormatKeyValue(Logging::Keys::executionTime, "{}", logicalSimStepTimeMs.count()); + lm.FormatKeyValue(Logging::Keys::virtualTimeNS, "{}", Now().count()); + lm.Dispatch(); _waitTimeMonitor.StartMeasurement(); } @@ -532,6 +545,9 @@ void TimeSyncService::CompleteSimulationStep() { if (!GetTimeSyncPolicy()->IsExecutingSimStep()) { + Logging::LoggerMessage lm{_logger, Logging::Level::Debug}; + lm.SetMessage("CompleteSimulationStep: calling _timeSyncPolicy->RequestNextStep"); + lm.Dispatch(); _logger->Warn("CompleteSimulationStep() was called before the simulation step handler was invoked."); } else @@ -659,10 +675,11 @@ bool TimeSyncService::ParticipantHasAutonomousSynchronousCapability(const std::s { // We are a participant with autonomous lifecycle and virtual time sync. // The remote participant must support this, otherwise Hop-On / Hop-Off will fail. - Error(_participant->GetLogger(), - "Participant \'{}\' does not support simulations with participants that use an autonomous lifecycle " - "and virtual time synchronization. Please consider upgrading Participant \'{}\'. Aborting simulation...", - participantName, participantName); + Logging::LoggerMessage lm{_participant->GetLoggerInternal(), Logging::Level::Error}; + lm.SetMessage("This participant does not support simulations with participants that use an autonomous lifecycle " + "and virtual time synchronization. Please consider upgrading Participant. Aborting simulation..."); + lm.SetKeyValue(Logging::Keys::participantName, participantName); + lm.Dispatch(); return false; } return true; @@ -674,9 +691,12 @@ bool TimeSyncService::AbortHopOnForCoordinatedParticipants() const { if (_lifecycleService->GetOperationMode() == OperationMode::Coordinated) { - Error(_participant->GetLogger(), - "This participant is running with a coordinated lifecycle and virtual time synchronization and wants " - "to join an already running simulation. This is not allowed, aborting simulation..."); + Logging::LoggerMessage lm{_participant->GetLoggerInternal(), Logging::Level::Error}; + lm.SetMessage("This participant is running with a coordinated lifecycle and virtual time synchronization and wants " + "to join an already running simulation. This is not allowed, aborting simulation..."); + lm.SetKeyValue(Logging::Keys::participantName, _participant->GetParticipantName()); + lm.Dispatch(); + _participant->GetSystemController()->AbortSimulation(); return true; } @@ -703,7 +723,7 @@ void TimeSyncService::HybridWait(std::chrono::nanoseconds targetWaitDuration) // By default, Windows timer have a resolution of 15.6ms // The effective time that wait_for or sleep_for actually waits will be a step function with steps every 15.6ms - const auto defaultTimerResolution = GetDefaultTimerResolution(); + const auto defaultTimerResolution = GetDefaultTimerResolution(); if (targetWaitDuration < defaultTimerResolution) { @@ -726,6 +746,7 @@ void TimeSyncService::StartWallClockCouplingThread() { _wallClockCouplingThreadRunning = true; _wallClockCouplingThread = std::thread{[this]() { + SilKit::Util::SetThreadName("SK-WallClkSync"); const auto startTime = std::chrono::steady_clock::now(); @@ -748,7 +769,11 @@ void TimeSyncService::StartWallClockCouplingThread() if (GetTimeSyncPolicy()->IsExecutingSimStep()) { // AsyncSimStepHandler not completed? Execution is lagging behind. Don't send the NextSimStep now, but after completion. - _logger->Warn("Simulation step was not completed in time to achieve wall clock coupling."); + Logging::LoggerMessage lm{_participant->GetLoggerInternal(), Logging::Level::Warn}; + lm.SetMessage("Simulation step was not completed in time to achieve wall clock coupling."); + lm.SetKeyValue(Logging::Keys::participantName, _participant->GetParticipantName()); + lm.Dispatch(); + _wallClockReachedBeforeCompletion = true; } else diff --git a/SilKit/source/services/orchestration/TimeSyncService.hpp b/SilKit/source/services/orchestration/TimeSyncService.hpp index 786f8700a..f582c1f4d 100644 --- a/SilKit/source/services/orchestration/TimeSyncService.hpp +++ b/SilKit/source/services/orchestration/TimeSyncService.hpp @@ -133,7 +133,7 @@ class TimeSyncService Core::IParticipantInternal* _participant{nullptr}; Core::ServiceDescriptor _serviceDescriptor{}; LifecycleService* _lifecycleService{nullptr}; - Services::Logging::ILogger* _logger{nullptr}; + Services::Logging::ILoggerInternal* _logger{nullptr}; ITimeProvider* _timeProvider{nullptr}; TimeConfiguration _timeConfiguration; diff --git a/SilKit/source/services/rpc/RpcTestUtilities.hpp b/SilKit/source/services/rpc/RpcTestUtilities.hpp index 9b98865bc..e6b7ce823 100644 --- a/SilKit/source/services/rpc/RpcTestUtilities.hpp +++ b/SilKit/source/services/rpc/RpcTestUtilities.hpp @@ -51,6 +51,7 @@ struct MockConnection } void SetLogger(SilKit::Services::Logging::ILogger* /*logger*/) {} + void SetLoggerInternal(SilKit::Services::Logging::ILoggerInternal* /*logger*/) {} void SetTimeSyncService(SilKit::Services::Orchestration::TimeSyncService* /*timeSyncService*/) {} void JoinSimulation(std::string /*registryUri*/) {} template diff --git a/docs/CHANGELOG.rst b/docs/CHANGELOG.rst index dcc63a83e..ffc223552 100644 --- a/docs/CHANGELOG.rst +++ b/docs/CHANGELOG.rst @@ -17,6 +17,7 @@ Added Changed ~~~~~~~ +- Changed log messages for controller and participant creation, message tracing, system state tracker and time sync service - Revised the documentation (demos, troubleshooting, doxygen output, file structure) - Improved platform/compiler/architecture detection