dev: Usage of InternalLogger and key values

SilKit/source/core/internal/LoggingDatatypesInternal.hpp

@@ -25,7 +25,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */
 #include <string>
 #include <sstream>
 #include <ostream>
-#include <unordered_map>
+#include <vector>
 
 #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<std::string, std::string> keyValues;
+    std::vector<std::pair<std::string, std::string>> 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<std::string, std::string>& kv);
-inline std::ostream& operator<<(std::ostream& out, const std::unordered_map<std::string, std::string>& kv);
+inline std::string to_string(const std::vector<std::pair<std::string, std::string>>& kv);
+inline std::ostream& operator<<(std::ostream& out, const std::vector<std::pair<std::string, std::string>>& kv);
 
 // ================================================================================
 //  Inline Implementations
@@ -98,15 +98,16 @@ std::ostream& operator<<(std::ostream& out, const SourceLoc& sourceLoc)
                << "line=" << sourceLoc.line << ", funcname={\"" << sourceLoc.funcname << "\"}";
 }
 
-inline std::string to_string(const std::unordered_map<std::string, std::string>& kv)
+
+inline std::string to_string(const std::vector<std::pair<std::string, std::string>>& kv)
 {
     std::stringstream outStream;
     outStream << kv;
     return outStream.str();
 }
 
 
-inline std::ostream& operator<<(std::ostream& out, const std::unordered_map<std::string, std::string>& kv)
+inline std::ostream& operator<<(std::ostream& out, const std::vector<std::pair<std::string, std::string>>& kv)
 {
     std::string result;
     result.reserve(kv.size() * 2);
@@ -115,7 +116,7 @@ inline std::ostream& operator<<(std::ostream& out, const std::unordered_map<std:
     {
         result.append(", kv: ");
 
-        std::unordered_map<std::string, std::string>::const_iterator it = kv.begin();
+        std::vector<std::pair<std::string, std::string>>::const_iterator it = kv.begin();
         result.append("{");
         while (it != kv.end())
         {

SilKit/source/core/internal/MessageBuffer.hpp

@@ -229,6 +229,12 @@ class MessageBuffer
     template <typename ValueT, size_t SIZE>
     inline MessageBuffer& operator>>(std::array<ValueT, SIZE>& array);
     // --------------------------------------------------------------------------------
+    // std::pair<T, U>
+    template <typename T, typename U>
+    inline MessageBuffer& operator<<(const std::pair<T, U>& pair);
+    template <typename T, typename U>
+    inline MessageBuffer& operator>>(std::pair<T, U>& pair);
+    // --------------------------------------------------------------------------------
     // std::chrono::duration<Rep, Period> and system_clock::time_point
     template <class Rep, class Period>
     inline MessageBuffer& operator<<(std::chrono::duration<Rep, Period> duration);
@@ -632,6 +638,21 @@ inline MessageBuffer& MessageBuffer::operator>>(std::unordered_map<std::string,
     return *this;
 }
 
+template <typename T, typename U>
+inline MessageBuffer& MessageBuffer::operator<<(const std::pair<T, U>& pair)
+{
+    *this << pair.first << pair.second;
+    return *this;
+}
+
+template <typename T, typename U>
+inline MessageBuffer& MessageBuffer::operator>>(std::pair<T, U>& pair)
+{
+    *this >> pair.first >> pair.second;
+    return *this;
+}
+
+
 // --------------------------------------------------------------------------------
 // Uuid
 

SilKit/source/core/internal/ServiceDescriptor.hpp

@@ -24,6 +24,7 @@ WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */
 #include <sstream>
 #include <map>
 
+#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<std::pair<std::string, std::string>> 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<std::pair<std::string, std::string>> ServiceDescriptor::to_keyValues() const
+{
+    namespace Keys = SilKit::Services::Logging::Keys;
+
+    std::vector<std::pair<std::string, std::string>> 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()};

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*/) {}
 

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<SilKitConnectionT>::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<Services::Logging::Logger>(GetParticipantName(), _participantConfig.logging);
-
     dynamic_cast<VSilKit::MetricsProcessor&>(*_metricsProcessor).SetLogger(*_logger);
     dynamic_cast<VSilKit::MetricsManager&>(*_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<SilKitConnectionT>::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<SilKitConnectionT>::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<SilKitConnectionT>::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<ITraceMessageSource*>(controller);
     if (traceSource)
@@ -416,9 +432,13 @@ auto Participant<SilKitConnectionT>::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)
     {
@@ -558,12 +578,17 @@ auto Participant<SilKitConnectionT>::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(Logging::Keys::label, FormatLabelsForLogging(configuredDataNodeSpec.Labels()));
+        lm.Dispatch();
     }
 
     auto* traceSource = dynamic_cast<ITraceMessageSource*>(controller);
@@ -623,12 +648,16 @@ auto Participant<SilKitConnectionT>::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(Logging::Keys::label, FormatLabelsForLogging(configuredDataNodeSpec.Labels()));
+        lm.Dispatch();
     }
 
     auto* traceSource = dynamic_cast<ITraceMessageSource*>(controller);
@@ -697,8 +726,8 @@ auto Participant<SilKitConnectionT>::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 +741,16 @@ auto Participant<SilKitConnectionT>::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(Logging::Keys::label, FormatLabelsForLogging(configuredRpcSpec.Labels()));
+        lm.Dispatch();
     }
 
     return controller;
@@ -751,8 +784,8 @@ auto Participant<SilKitConnectionT>::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 +797,16 @@ auto Participant<SilKitConnectionT>::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(Logging::Keys::label, FormatLabelsForLogging(configuredRpcSpec.Labels()));
+        lm.Dispatch();
     }
 
     return controller;
@@ -1333,7 +1370,7 @@ template <class SilKitConnectionT>
 template <typename SilKitMessageT>
 void Participant<SilKitConnectionT>::SendMsgImpl(const IServiceEndpoint* from, SilKitMessageT&& msg)
 {
-    TraceTx(GetLogger(), from, msg);
+    TraceTx(GetLoggerInternal(), from, msg);
     _connection.SendMsg(from, std::forward<SilKitMessageT>(msg));
 }
 
@@ -1637,7 +1674,7 @@ template <typename SilKitMessageT>
 void Participant<SilKitConnectionT>::SendMsgImpl(const IServiceEndpoint* from, const std::string& targetParticipantName,
                                                  SilKitMessageT&& msg)
 {
-    TraceTx(GetLogger(), from, msg);
+    TraceTx(GetLoggerInternal(), from, msg);
     _connection.SendMsg(from, targetParticipantName, std::forward<SilKitMessageT>(msg));
 }