diff --git a/src/apps/towercalculator/KeyboardReader.cpp b/src/apps/towercalculator/KeyboardReader.cpp index da75d09780..5f294139d6 100644 --- a/src/apps/towercalculator/KeyboardReader.cpp +++ b/src/apps/towercalculator/KeyboardReader.cpp @@ -43,6 +43,7 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS +#include "log/SemanticLogger.h" #include "utils/Timeval.h" #include @@ -56,7 +57,11 @@ namespace apps::towercalculator { KeyboardReader::KeyboardReader(const std::function& cb) - : core::eventreceiver::ReadEventReceiver("KeyboardReader", 0) + : core::eventreceiver::ReadEventReceiver( + "KeyboardReader", + logger::LogScope{ + logger::LogOrigin::Application, logger::LogBoundary::Application, "app", "towercalculator", logger::LogRole::Unknown, {}}, + 0) , callBack(cb) { if (!enable(STDIN_FILENO)) { std::cout << "KeyboardReader not activated"; diff --git a/src/core/DescriptorEventReceiver.cpp b/src/core/DescriptorEventReceiver.cpp index ea330b4480..232ded83c5 100644 --- a/src/core/DescriptorEventReceiver.cpp +++ b/src/core/DescriptorEventReceiver.cpp @@ -49,6 +49,7 @@ #include #include +#include #include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -84,6 +85,17 @@ namespace core { , initialTimeout(timeout) { } + DescriptorEventReceiver::DescriptorEventReceiver(const std::string& name, + DescriptorEventPublisher& descriptorEventPublisher, + logger::LogScope logScope, + const utils::Timeval& timeout) + : EventReceiver(name) + , descriptorEventPublisher(descriptorEventPublisher) + , logScope(logger::LogScopeOwner::fromScope(logScope)) + , maxInactivity(timeout) + , initialTimeout(timeout) { + } + int DescriptorEventReceiver::getRegisteredFd() const { return observedFd; } @@ -107,20 +119,20 @@ namespace core { bool DescriptorEventReceiver::enable(int fd) { if (enabled) { - log().warn("{}: Double enable", getName()); + log().warn("{} descriptor: Double enable", descriptorEventPublisher.getName()); return false; } observedFd = fd; if (descriptorEventPublisher.enable(this)) { enabled = true; - log().trace("{}: Enabled", getName()); + log().trace("{} descriptor enabled", descriptorEventPublisher.getName()); return true; } const int registrationError = errno != 0 ? errno : EIO; observedFd = -1; - log().error("{}: Descriptor registration failed: fd={}", getName(), fd); + log().error("{} descriptor registration failed: fd={}", descriptorEventPublisher.getName(), fd); errno = registrationError; return false; } @@ -129,9 +141,9 @@ namespace core { if (enabled) { enabled = false; descriptorEventPublisher.disable(this); - log().trace("{}: Disabled", getName()); + log().trace("{} descriptor disabled", descriptorEventPublisher.getName()); } else { - log().warn("{}: Double disable", getName()); + log().warn("{} descriptor: Double disable", descriptorEventPublisher.getName()); } } @@ -141,10 +153,10 @@ namespace core { suspended = true; descriptorEventPublisher.suspend(this); } else { - log().warn("{}: Double suspend", getName()); + log().warn("{} descriptor: Double suspend", descriptorEventPublisher.getName()); } } else { - log().warn("{}: Suspend while not enabled", getName()); + log().warn("{} descriptor: Suspend while not enabled", descriptorEventPublisher.getName()); } } @@ -155,10 +167,10 @@ namespace core { lastTriggered = utils::Timeval::currentTime(); descriptorEventPublisher.resume(this); } else { - log().warn("{}: Double resume", getName()); + log().warn("{} descriptor: Double resume", descriptorEventPublisher.getName()); } } else { - log().warn("{}: Resume while not enabled", getName()); + log().warn("{} descriptor: Resume while not enabled", descriptorEventPublisher.getName()); } } diff --git a/src/core/DescriptorEventReceiver.h b/src/core/DescriptorEventReceiver.h index 73cbbcfaac..a47a8ae9fd 100644 --- a/src/core/DescriptorEventReceiver.h +++ b/src/core/DescriptorEventReceiver.h @@ -45,6 +45,7 @@ #include "core/EventReceiver.h" // IWYU pragma: export #include "core/Shutdown.h" // IWYU pragma: export #include "log/LogScopeOwner.h" +#include "log/SemanticLogger.h" namespace core { class DescriptorEventPublisher; @@ -92,6 +93,10 @@ namespace core { DescriptorEventReceiver(const std::string& name, DescriptorEventPublisher& descriptorEventPublisher, const utils::Timeval& timeout = TIMEOUT::DISABLE); + DescriptorEventReceiver(const std::string& name, + DescriptorEventPublisher& descriptorEventPublisher, + logger::LogScope logScope, + const utils::Timeval& timeout = TIMEOUT::DISABLE); public: int getRegisteredFd() const; diff --git a/src/core/eventreceiver/ExceptionalConditionEventReceiver.cpp b/src/core/eventreceiver/ExceptionalConditionEventReceiver.cpp index e93d79e362..98ee61f674 100644 --- a/src/core/eventreceiver/ExceptionalConditionEventReceiver.cpp +++ b/src/core/eventreceiver/ExceptionalConditionEventReceiver.cpp @@ -43,6 +43,7 @@ #include "core/EventLoop.h" #include "core/EventMultiplexer.h" +#include "log/SemanticLogger.h" #ifndef DOXYGEN_SHOULD_SKIP_THIS @@ -50,10 +51,13 @@ namespace core::eventreceiver { - ExceptionalConditionEventReceiver::ExceptionalConditionEventReceiver(const std::string& name, const utils::Timeval& timeout) + ExceptionalConditionEventReceiver::ExceptionalConditionEventReceiver(const std::string& name, + logger::LogScope logScope, + const utils::Timeval& timeout) : core::DescriptorEventReceiver( name + " out of band", core::EventLoop::instance().getEventMultiplexer().getDescriptorEventPublisher(core::EventMultiplexer::DISP_TYPE::EX), + logScope, timeout) { } diff --git a/src/core/eventreceiver/ExceptionalConditionEventReceiver.h b/src/core/eventreceiver/ExceptionalConditionEventReceiver.h index ee96152dde..44fc518fee 100644 --- a/src/core/eventreceiver/ExceptionalConditionEventReceiver.h +++ b/src/core/eventreceiver/ExceptionalConditionEventReceiver.h @@ -44,6 +44,10 @@ #include "core/DescriptorEventReceiver.h" // IWYU pragma: export +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -58,7 +62,9 @@ namespace core::eventreceiver { class ExceptionalConditionEventReceiver : public core::DescriptorEventReceiver { protected: - ExceptionalConditionEventReceiver(const std::string& name, const utils::Timeval& timeout = MAX_OUTOFBAND_INACTIVITY); + ExceptionalConditionEventReceiver(const std::string& name, + logger::LogScope logScope, + const utils::Timeval& timeout = MAX_OUTOFBAND_INACTIVITY); virtual void outOfBandTimeout(); diff --git a/src/core/eventreceiver/ReadEventReceiver.cpp b/src/core/eventreceiver/ReadEventReceiver.cpp index bfffcd9bf1..2b749e52ba 100644 --- a/src/core/eventreceiver/ReadEventReceiver.cpp +++ b/src/core/eventreceiver/ReadEventReceiver.cpp @@ -43,6 +43,7 @@ #include "core/EventLoop.h" #include "core/EventMultiplexer.h" +#include "log/SemanticLogger.h" #ifndef DOXYGEN_SHOULD_SKIP_THIS @@ -50,10 +51,11 @@ namespace core::eventreceiver { - ReadEventReceiver::ReadEventReceiver(const std::string& name, const utils::Timeval& timeout) + ReadEventReceiver::ReadEventReceiver(const std::string& name, logger::LogScope logScope, const utils::Timeval& timeout) : core::DescriptorEventReceiver( name + " read", core::EventLoop::instance().getEventMultiplexer().getDescriptorEventPublisher(core::EventMultiplexer::DISP_TYPE::RD), + logScope, timeout) { } diff --git a/src/core/eventreceiver/ReadEventReceiver.h b/src/core/eventreceiver/ReadEventReceiver.h index 2ccf83bffd..737c413595 100644 --- a/src/core/eventreceiver/ReadEventReceiver.h +++ b/src/core/eventreceiver/ReadEventReceiver.h @@ -44,6 +44,10 @@ #include "core/DescriptorEventReceiver.h" // IWYU pragma: export +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -56,7 +60,7 @@ namespace core::eventreceiver { class ReadEventReceiver : public core::DescriptorEventReceiver { protected: - ReadEventReceiver(const std::string& name, const utils::Timeval& timeout); + ReadEventReceiver(const std::string& name, logger::LogScope logScope, const utils::Timeval& timeout); virtual void readTimeout(); diff --git a/src/core/eventreceiver/WriteEventReceiver.cpp b/src/core/eventreceiver/WriteEventReceiver.cpp index c91e6c4883..356854a9a4 100644 --- a/src/core/eventreceiver/WriteEventReceiver.cpp +++ b/src/core/eventreceiver/WriteEventReceiver.cpp @@ -43,6 +43,7 @@ #include "core/EventLoop.h" #include "core/EventMultiplexer.h" +#include "log/SemanticLogger.h" #ifndef DOXYGEN_SHOULD_SKIP_THIS @@ -50,10 +51,11 @@ namespace core::eventreceiver { - WriteEventReceiver::WriteEventReceiver(const std::string& name, const utils::Timeval& timeout) + WriteEventReceiver::WriteEventReceiver(const std::string& name, logger::LogScope logScope, const utils::Timeval& timeout) : core::DescriptorEventReceiver( name + " write", core::EventLoop::instance().getEventMultiplexer().getDescriptorEventPublisher(core::EventMultiplexer::DISP_TYPE::WR), + logScope, timeout) { } diff --git a/src/core/eventreceiver/WriteEventReceiver.h b/src/core/eventreceiver/WriteEventReceiver.h index 98ed836aa4..1a90468505 100644 --- a/src/core/eventreceiver/WriteEventReceiver.h +++ b/src/core/eventreceiver/WriteEventReceiver.h @@ -44,6 +44,10 @@ #include "core/DescriptorEventReceiver.h" // IWYU pragma: export +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -56,7 +60,7 @@ namespace core::eventreceiver { class WriteEventReceiver : public core::DescriptorEventReceiver { protected: - WriteEventReceiver(const std::string& name, const utils::Timeval& timeout); + WriteEventReceiver(const std::string& name, logger::LogScope logScope, const utils::Timeval& timeout); virtual void writeTimeout(); diff --git a/src/core/pipe/Pipe.cpp b/src/core/pipe/Pipe.cpp index 6f06d377b9..63c427185a 100644 --- a/src/core/pipe/Pipe.cpp +++ b/src/core/pipe/Pipe.cpp @@ -47,9 +47,13 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/system/unistd.h" +#include "log/LogScopeOwner.h" +#include "log/SemanticLogger.h" #include "utils/Timeval.h" +#include #include +#include #include #include @@ -58,6 +62,11 @@ namespace core::pipe { namespace { + std::uint64_t allocateConnectionId() noexcept { + static std::atomic nextConnectionId{1}; + return nextConnectionId.fetch_add(1, std::memory_order_relaxed); + } + void closeDescriptor(int& fd) noexcept { const int descriptor = std::exchange(fd, -1); if (descriptor >= 0) { @@ -90,11 +99,13 @@ namespace core::pipe { } } // namespace - Pipe::Pipe() noexcept - : Pipe(O_CLOEXEC) { + Pipe::Pipe(const std::string& instanceName) + : Pipe(O_CLOEXEC, instanceName) { } - Pipe::Pipe(int flags) noexcept { + Pipe::Pipe(int flags, const std::string& instanceName) + : instanceName(instanceName) + , connectionId(allocateConnectionId()) { int descriptors[2] = {-1, -1}; if (core::system::pipe2(descriptors, flags) != 0) { error = errno; @@ -106,7 +117,9 @@ namespace core::pipe { } Pipe::Pipe(Pipe&& pipe) noexcept - : readFd(std::exchange(pipe.readFd, -1)) + : instanceName(std::move(pipe.instanceName)) + , connectionId(pipe.connectionId) + , readFd(std::exchange(pipe.readFd, -1)) , writeFd(std::exchange(pipe.writeFd, -1)) , error(std::exchange(pipe.error, 0)) { } @@ -120,6 +133,8 @@ namespace core::pipe { if (this != &pipe) { closeRead(); closeWrite(); + instanceName = std::move(pipe.instanceName); + connectionId = pipe.connectionId; readFd = std::exchange(pipe.readFd, -1); writeFd = std::exchange(pipe.writeFd, -1); error = std::exchange(pipe.error, 0); @@ -127,8 +142,10 @@ namespace core::pipe { return *this; } - Pipe::Pipe(const std::function& onSuccess, const std::function& onError) - : Pipe(O_NONBLOCK | O_CLOEXEC) { + Pipe::Pipe(const std::function& onSuccess, + const std::function& onError, + const std::string& instanceName) + : Pipe(O_NONBLOCK | O_CLOEXEC, instanceName) { if (!hasReadFd() || !hasWriteFd()) { onError(error); return; @@ -197,6 +214,15 @@ namespace core::pipe { closeDescriptor(writeFd); } + logger::LogScopeOwner Pipe::makeLogScope() const { + return logger::LogScopeOwner(logger::LogOrigin::Framework, + logger::LogBoundary::Connection, + "core.pipe", + instanceName.empty() ? std::nullopt : std::optional(instanceName), + std::nullopt, + std::to_string(connectionId)); + } + PipeSink* Pipe::releaseReadAsSink() { return releaseReadAsSink(PipeSink::DEFAULT_MAX_BYTES_PER_EVENT, utils::Timeval({60, 0})); } @@ -209,7 +235,8 @@ namespace core::pipe { makeNonBlocking(readFd); const int descriptor = releaseReadFd(); try { - return new PipeSink(descriptor, maxBytesPerEvent, timeout); + const logger::LogScopeOwner logScope = makeLogScope(); + return new PipeSink(descriptor, logScope.scope(), maxBytesPerEvent, timeout); } catch (...) { readFd = descriptor; throw; @@ -228,7 +255,8 @@ namespace core::pipe { makeNonBlocking(writeFd); const int descriptor = releaseWriteFd(); try { - return new PipeSource(descriptor, maxQueuedBytes, timeout); + const logger::LogScopeOwner logScope = makeLogScope(); + return new PipeSource(descriptor, logScope.scope(), maxQueuedBytes, timeout); } catch (...) { writeFd = descriptor; throw; diff --git a/src/core/pipe/Pipe.h b/src/core/pipe/Pipe.h index d71cc88a98..d9fa2e1ec8 100644 --- a/src/core/pipe/Pipe.h +++ b/src/core/pipe/Pipe.h @@ -47,6 +47,10 @@ namespace core::pipe { class PipeSource; } // namespace core::pipe +namespace logger { + class LogScopeOwner; +} + namespace utils { class Timeval; } @@ -54,7 +58,9 @@ namespace utils { #ifndef DOXYGEN_SHOULD_SKIP_THIS #include +#include #include +#include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -62,8 +68,8 @@ namespace core::pipe { class Pipe { public: - Pipe() noexcept; - explicit Pipe(int flags) noexcept; + explicit Pipe(const std::string& instanceName = {}); + explicit Pipe(int flags, const std::string& instanceName = {}); Pipe(const Pipe&) = delete; Pipe(Pipe&& pipe) noexcept; @@ -73,7 +79,9 @@ namespace core::pipe { Pipe& operator=(const Pipe&) = delete; Pipe& operator=(Pipe&& pipe) noexcept; - Pipe(const std::function& onSuccess, const std::function& onError); + Pipe(const std::function& onSuccess, + const std::function& onError, + const std::string& instanceName = {}); // True while this object still owns at least one endpoint. bool isValid() const noexcept; @@ -101,6 +109,10 @@ namespace core::pipe { PipeSource* releaseWriteAsSource(std::size_t maxQueuedBytes, const utils::Timeval& timeout); private: + logger::LogScopeOwner makeLogScope() const; + + std::string instanceName; + std::uint64_t connectionId = 0; int readFd = -1; int writeFd = -1; int error = 0; diff --git a/src/core/pipe/PipeSink.cpp b/src/core/pipe/PipeSink.cpp index 7bdc803477..b76ef29a4f 100644 --- a/src/core/pipe/PipeSink.cpp +++ b/src/core/pipe/PipeSink.cpp @@ -44,6 +44,7 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/system/unistd.h" +#include "log/SemanticLogger.h" #include #include @@ -59,8 +60,8 @@ namespace core::pipe { - PipeSink::PipeSink(int fd, std::size_t maxBytesPerEvent, const utils::Timeval& timeout) - : core::eventreceiver::ReadEventReceiver("PipeSink fd = " + std::to_string(fd), timeout) + PipeSink::PipeSink(int fd, logger::LogScope logScope, std::size_t maxBytesPerEvent, const utils::Timeval& timeout) + : core::eventreceiver::ReadEventReceiver("PipeSink", logScope, timeout) , maxBytesPerEvent(std::max(maxBytesPerEvent, 1)) { if (!ReadEventReceiver::enable(fd)) { throw std::system_error(errno != 0 ? errno : EIO, std::generic_category(), "unable to register PipeSink descriptor"); diff --git a/src/core/pipe/PipeSink.h b/src/core/pipe/PipeSink.h index c408bc4cae..283ed5b480 100644 --- a/src/core/pipe/PipeSink.h +++ b/src/core/pipe/PipeSink.h @@ -44,6 +44,10 @@ #include "core/eventreceiver/ReadEventReceiver.h" +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -80,6 +84,7 @@ namespace core::pipe { private: explicit PipeSink(int fd, + logger::LogScope logScope, std::size_t maxBytesPerEvent = DEFAULT_MAX_BYTES_PER_EVENT, const utils::Timeval& timeout = utils::Timeval({60, 0})); ~PipeSink() override; diff --git a/src/core/pipe/PipeSource.cpp b/src/core/pipe/PipeSource.cpp index a880e120cd..3877033376 100644 --- a/src/core/pipe/PipeSource.cpp +++ b/src/core/pipe/PipeSource.cpp @@ -44,6 +44,7 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/system/unistd.h" +#include "log/SemanticLogger.h" #include #include @@ -62,8 +63,8 @@ namespace core::pipe { constexpr std::size_t MAX_BYTES_PER_EVENT = 256 * 1024; } - PipeSource::PipeSource(int fd, std::size_t maxQueuedBytes, const utils::Timeval& timeout) - : core::eventreceiver::WriteEventReceiver("PipeSource fd = " + std::to_string(fd), timeout) + PipeSource::PipeSource(int fd, logger::LogScope logScope, std::size_t maxQueuedBytes, const utils::Timeval& timeout) + : core::eventreceiver::WriteEventReceiver("PipeSource", logScope, timeout) , maxQueuedBytes(maxQueuedBytes) { if (!WriteEventReceiver::enable(fd)) { throw std::system_error(errno != 0 ? errno : EIO, std::generic_category(), "unable to register PipeSource descriptor"); diff --git a/src/core/pipe/PipeSource.h b/src/core/pipe/PipeSource.h index 8465fdf5e0..014340f17b 100644 --- a/src/core/pipe/PipeSource.h +++ b/src/core/pipe/PipeSource.h @@ -44,6 +44,10 @@ #include "core/eventreceiver/WriteEventReceiver.h" +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -89,6 +93,7 @@ namespace core::pipe { private: explicit PipeSource(int fd, + logger::LogScope logScope, std::size_t maxQueuedBytes = DEFAULT_MAX_QUEUED_BYTES, const utils::Timeval& timeout = utils::Timeval({60, 0})); ~PipeSource() override; diff --git a/src/core/socket/stream/SocketClient.h b/src/core/socket/stream/SocketClient.h index 91a04bc360..37299cc398 100644 --- a/src/core/socket/stream/SocketClient.h +++ b/src/core/socket/stream/SocketClient.h @@ -214,7 +214,7 @@ namespace core::socket::stream { this->config, std::make_shared(std::forward(args)...), [onConnect, log = this->log()](SocketConnection* socketConnection) { // onConnect - log.debug("{}: OnConnect", socketConnection->getConnectionName()); + log.debug("Connection {} connecting", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); @@ -224,7 +224,7 @@ namespace core::socket::stream { } }, [onConnected, log = this->log()](SocketConnection* socketConnection) { // onConnected - log.debug("{}: OnConnected", socketConnection->getConnectionName()); + log.debug("Connection {} connected", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); @@ -234,7 +234,7 @@ namespace core::socket::stream { } }, [onDisconnect, log = this->log()](SocketConnection* socketConnection) { // onDisconnect - log.debug("{}: OnDisconnect", socketConnection->getConnectionName()); + log.debug("Connection {} disconnected", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); diff --git a/src/core/socket/stream/SocketConnection.hpp b/src/core/socket/stream/SocketConnection.hpp index 1d3878d831..1687e84b80 100644 --- a/src/core/socket/stream/SocketConnection.hpp +++ b/src/core/socket/stream/SocketConnection.hpp @@ -39,18 +39,16 @@ * THE SOFTWARE. */ -#include "SemanticLog.h" #include "core/Shutdown.h" #include "core/socket/stream/SocketConnection.h" #include "core/socket/stream/SocketContext.h" #ifndef DOXYGEN_SHOULD_SKIP_THIS -#include "log/Logger.h" +#include "log/SemanticLogger.h" #include "utils/PreserveErrno.h" #include "utils/system/signal.h" -#include #include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -86,7 +84,7 @@ namespace core::socket::stream { } // namespace detail template - SocketAddress getLocalSocketAddress(PhysicalSocket& physicalSocket, Config& config) { + SocketAddress getLocalSocketAddress(PhysicalSocket& physicalSocket, Config& config, const logger::BoundaryLogger& log) { typename SocketAddress::SockAddr localSockAddr; typename SocketAddress::SockLen localSockAddrLen = sizeof(typename SocketAddress::SockAddr); @@ -94,24 +92,20 @@ namespace core::socket::stream { if (physicalSocket.getSockName(localSockAddr, localSockAddrLen) == 0) { try { localPeerAddress = config->Local::getSocketAddress(localSockAddr, localSockAddrLen); - snode::semantic::coreSocketLog().trace() << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" - << std::setw(25) << " PeerAddress (local): " << localPeerAddress.toString(); + log.trace("PeerAddress (local): {}", localPeerAddress.toString()); } catch (const typename SocketAddress::BadSocketAddress& badSocketAddress) { - snode::semantic::coreSocketLog().warn() << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" - << std::setw(25) << " PeerAddress (local): " << badSocketAddress.what(); + log.warn("PeerAddress (local): {}", badSocketAddress.what()); } } else { const int errnum = errno; - snode::semantic::sysError(snode::semantic::coreSocketLog(), logger::LogLevel::Warn, errnum) - << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" << std::setw(25) - << " PeerAddress (local) not retrievable"; + log.sysError(logger::LogLevel::Warn, errnum, "PeerAddress (local) not retrievable"); } return localPeerAddress; } template - SocketAddress getRemoteSocketAddress(PhysicalSocket& physicalSocket, Config& config) { + SocketAddress getRemoteSocketAddress(PhysicalSocket& physicalSocket, Config& config, const logger::BoundaryLogger& log) { typename SocketAddress::SockAddr remoteSockAddr; typename SocketAddress::SockLen remoteSockAddrLen = sizeof(typename SocketAddress::SockAddr); @@ -119,17 +113,13 @@ namespace core::socket::stream { if (physicalSocket.getPeerName(remoteSockAddr, remoteSockAddrLen) == 0) { try { remotePeerAddress = config->Remote::getSocketAddress(remoteSockAddr, remoteSockAddrLen); - snode::semantic::coreSocketLog().trace() << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" - << std::setw(25) << " PeerAddress (remote): " << remotePeerAddress.toString(); + log.trace("PeerAddress (remote): {}", remotePeerAddress.toString()); } catch (const typename SocketAddress::BadSocketAddress& badSocketAddress) { - snode::semantic::coreSocketLog().warn() << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" - << std::setw(25) << " PeerAddress (remote): " << badSocketAddress.what(); + log.warn("PeerAddress (remote): {}", badSocketAddress.what()); } } else { const int errnum = errno; - snode::semantic::sysError(snode::semantic::coreSocketLog(), logger::LogLevel::Warn, errnum) - << config->getInstanceName() << " [" << physicalSocket.getFd() << "]" << std::setw(25) - << " PeerAddress (remote) not retrievble"; + log.sysError(logger::LogLevel::Warn, errnum, "PeerAddress (remote) not retrievable"); } return remotePeerAddress; @@ -143,6 +133,7 @@ namespace core::socket::stream { : SocketConnection(physicalSocket.getFd(), connectionId, config->getInstanceName(), config.get()) , SocketReader( Super::getConnectionName(), + Super::logScope.scope(), [this](int errnum) { { const utils::PreserveErrno pe(errnum); @@ -161,6 +152,7 @@ namespace core::socket::stream { config->getTerminateTimeout()) , SocketWriter( Super::getConnectionName(), + Super::logScope.scope(), [this](int errnum) { { const utils::PreserveErrno pe(errnum); @@ -178,8 +170,8 @@ namespace core::socket::stream { detail::writeQueueLowWatermark(*config)) , physicalSocket(std::move(physicalSocket)) , onDisconnect(onDisconnect) - , localAddress(getLocalSocketAddress(this->physicalSocket, config)) - , remoteAddress(getRemoteSocketAddress(this->physicalSocket, config)) + , localAddress(getLocalSocketAddress(this->physicalSocket, config, Super::log())) + , remoteAddress(getRemoteSocketAddress(this->physicalSocket, config, Super::log())) , config(config) { if (!SocketReader::enable(this->physicalSocket.getFd())) { delete this; diff --git a/src/core/socket/stream/SocketReader.cpp b/src/core/socket/stream/SocketReader.cpp index 8f8f4eec1d..805cf10fca 100644 --- a/src/core/socket/stream/SocketReader.cpp +++ b/src/core/socket/stream/SocketReader.cpp @@ -44,6 +44,7 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/system/socket.h" +#include "log/SemanticLogger.h" #include #include @@ -52,12 +53,13 @@ namespace core::socket::stream { - SocketReader::SocketReader(const std::string& instanceName, + SocketReader::SocketReader(const std::string& name, + logger::LogScope logScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, const utils::Timeval& terminateTimeout) - : core::eventreceiver::ReadEventReceiver(instanceName, timeout) + : core::eventreceiver::ReadEventReceiver(name, logScope, timeout) , onStatus(onStatus) , terminateTimeout(terminateTimeout) { setBlockSize(blockSize); diff --git a/src/core/socket/stream/SocketReader.h b/src/core/socket/stream/SocketReader.h index 203b30222e..c5d34c0276 100644 --- a/src/core/socket/stream/SocketReader.h +++ b/src/core/socket/stream/SocketReader.h @@ -44,6 +44,10 @@ #include "core/eventreceiver/ReadEventReceiver.h" +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "utils/Timeval.h" @@ -66,7 +70,8 @@ namespace core::socket::stream { SocketReader() = delete; protected: - explicit SocketReader(const std::string& instanceName, + explicit SocketReader(const std::string& name, + logger::LogScope logScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, diff --git a/src/core/socket/stream/SocketServer.h b/src/core/socket/stream/SocketServer.h index d4b10fb63b..6b8febfd1b 100644 --- a/src/core/socket/stream/SocketServer.h +++ b/src/core/socket/stream/SocketServer.h @@ -179,7 +179,7 @@ namespace core::socket::stream { this->config, std::make_shared(std::forward(args)...), [onConnect, log = this->log()](SocketConnection* socketConnection) { // onConnect - log.debug("{}: OnConnect", socketConnection->getConnectionName()); + log.debug("Connection {} connecting", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); @@ -189,7 +189,7 @@ namespace core::socket::stream { } }, [onConnected, log = this->log()](SocketConnection* socketConnection) { // onConnected - log.debug("{}: OnConnected", socketConnection->getConnectionName()); + log.debug("Connection {} connected", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); @@ -199,7 +199,7 @@ namespace core::socket::stream { } }, [onDisconnect, log = this->log()](SocketConnection* socketConnection) { // onDisconnect - log.debug("{}: OnDisconnect", socketConnection->getConnectionName()); + log.debug("Connection {} disconnected", socketConnection->getConnectionId()); log.debug("Local: {}", socketConnection->getLocalAddress().toString()); log.debug("Peer: {}", socketConnection->getRemoteAddress().toString()); diff --git a/src/core/socket/stream/SocketWriter.cpp b/src/core/socket/stream/SocketWriter.cpp index 8624435563..7bba2e9206 100644 --- a/src/core/socket/stream/SocketWriter.cpp +++ b/src/core/socket/stream/SocketWriter.cpp @@ -41,7 +41,6 @@ #include "core/socket/stream/SocketWriter.h" -#include "SemanticLog.h" #include "core/pipe/Source.h" #ifndef DOXYGEN_SHOULD_SKIP_THIS @@ -57,15 +56,8 @@ #endif // DOXYGEN_SHOULD_SKIP_THIS namespace core::socket::stream { - SocketWriter::SocketWriter(const std::string& instanceName, - const std::function& onStatus, - const utils::Timeval& timeout, - std::size_t blockSize, - const utils::Timeval& terminateTimeout) - : SocketWriter(instanceName, onStatus, timeout, blockSize, terminateTimeout, 0, 0, 0) { - } - - SocketWriter::SocketWriter(const std::string& instanceName, + SocketWriter::SocketWriter(const std::string& name, + logger::LogScope logScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, @@ -73,7 +65,7 @@ namespace core::socket::stream { std::size_t maximumWriteQueueBytes, std::size_t writeQueueHighWatermark, std::size_t writeQueueLowWatermark) - : core::eventreceiver::WriteEventReceiver(instanceName, timeout) + : core::eventreceiver::WriteEventReceiver(name, logScope, timeout) , onStatus(onStatus) , blockSize(blockSize) , maximumWriteQueueBytes(maximumWriteQueueBytes) @@ -143,7 +135,7 @@ namespace core::socket::stream { } if (markShutdown) { - snode::semantic::coreSocketLog().trace() << getName() << ": Shutdown restart"; + log().trace("Write shutdown restarted"); doWriteShutdown(onShutdown); } else { resumeSourceAtLowWatermark(); @@ -188,15 +180,14 @@ namespace core::socket::stream { case QueueResult::Queued: break; case QueueResult::WouldExceedLimit: - snode::semantic::coreSocketLog().warn() - << getName() << ": Send would exceed maximum write queue: failing the connection for " << chunkLen << " bytes"; + log().warn("Send would exceed maximum write queue: failing the connection for {} bytes", chunkLen); onStatus(ENOBUFS); break; case QueueResult::Closed: - snode::semantic::coreSocketLog().warn() << getName() << ": Send while not enabled"; + log().warn("Send while not enabled"); break; case QueueResult::ShutdownInProgress: - snode::semantic::coreSocketLog().warn() << getName() << ": Send while shutdown in progress: ignoring"; + log().warn("Send while shutdown in progress: ignoring"); break; } } @@ -209,15 +200,15 @@ namespace core::socket::stream { success = source != nullptr; if (success) { - snode::semantic::coreSocketLog().trace() << getName() << ": Stream started"; + log().trace("Stream started"); } else { - snode::semantic::coreSocketLog().warn() << getName() << ": Stream source is nullptr"; + log().warn("Stream source is nullptr"); } } else { - snode::semantic::coreSocketLog().warn() << getName() << ": Stream while not enabled"; + log().warn("Stream while not enabled"); } } else { - snode::semantic::coreSocketLog().warn() << getName() << ": Stream while shutdown in progress"; + log().warn("Stream while shutdown in progress"); } this->source = success ? source : nullptr; @@ -231,7 +222,7 @@ namespace core::socket::stream { } void SocketWriter::streamEof() { - snode::semantic::coreSocketLog().trace() << getName() << ": Stream EOF"; + log().trace("Stream EOF"); this->source = nullptr; sourceSuspended = false; } @@ -285,11 +276,11 @@ namespace core::socket::stream { SocketWriter::onShutdown = onShutdown; if (writePuffer.empty()) { - snode::semantic::coreSocketLog().trace() << getName() << ": Shutdown start"; + log().trace("Write shutdown started"); doWriteShutdown(onShutdown); } else { markShutdown = true; - snode::semantic::coreSocketLog().trace() << getName() << ": Shutdown delayed due to queued data"; + log().trace("Write shutdown delayed due to queued data"); } } } diff --git a/src/core/socket/stream/SocketWriter.h b/src/core/socket/stream/SocketWriter.h index 4719fe2afd..2da5ce3449 100644 --- a/src/core/socket/stream/SocketWriter.h +++ b/src/core/socket/stream/SocketWriter.h @@ -45,6 +45,10 @@ #include "core/eventreceiver/WriteEventReceiver.h" #include "core/socket/stream/QueueResult.h" +namespace logger { + struct LogScope; +} + namespace core::pipe { class Source; } @@ -71,13 +75,8 @@ namespace core::socket::stream { SocketWriter() = delete; protected: - explicit SocketWriter(const std::string& instanceName, - const std::function& onStatus, - const utils::Timeval& timeout, - std::size_t blockSize, - const utils::Timeval& terminateTimeout); - - SocketWriter(const std::string& instanceName, + SocketWriter(const std::string& name, + logger::LogScope logScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, diff --git a/src/core/socket/stream/tls/SocketAcceptor.hpp b/src/core/socket/stream/tls/SocketAcceptor.hpp index 1d701f361f..ee788c0d62 100644 --- a/src/core/socket/stream/tls/SocketAcceptor.hpp +++ b/src/core/socket/stream/tls/SocketAcceptor.hpp @@ -76,12 +76,12 @@ namespace core::socket::stream::tls { } }, [socketContextFactory, onConnected](SocketConnection* socketConnection) { // on Connected - static_cast(socketConnection)->log().trace("SSL/TLS: Start handshake"); + socketConnection->log().trace("SSL/TLS: Start handshake"); if (!socketConnection->doSSLHandshake( [socketContextFactory, onConnected, socketConnection, - log = static_cast(socketConnection)->log()]() { // onSuccess + log = socketConnection->log()]() { // onSuccess log.debug("SSL/TLS: Handshake success"); log.info("transport ready"); @@ -90,17 +90,18 @@ namespace core::socket::stream::tls { socketConnection->setSocketContext(socketContextFactory); }, [socketConnection, - log = static_cast(socketConnection)->log()]() { // onTimeout + log = socketConnection->log()]() { // onTimeout log.error("SSL/TLS: Handshake timed out"); socketConnection->close(); }, - [socketConnection](int sslErr) { // - ssl_log(socketConnection->getConnectionName() + " SSL/TLS: Handshake failed", sslErr); + [socketConnection, + log = socketConnection->log()](int sslErr) { // + ssl_log(log, "SSL/TLS: Handshake failed", sslErr); socketConnection->close(); })) { - static_cast(socketConnection)->log().error("SSL/TLS: Handshake failed"); + socketConnection->log().error("SSL/TLS: Handshake failed"); socketConnection->close(); } diff --git a/src/core/socket/stream/tls/SocketConnection.hpp b/src/core/socket/stream/tls/SocketConnection.hpp index b2c1bb764d..0f6aaa1d8b 100644 --- a/src/core/socket/stream/tls/SocketConnection.hpp +++ b/src/core/socket/stream/tls/SocketConnection.hpp @@ -263,6 +263,7 @@ namespace core::socket::stream::tls { TLSHandshake::doHandshakeWithRelease( Super::getConnectionName(), + core::socket::stream::SocketConnection::logScope.scope(), lifecycle->ssl, [lifecycle, onSuccess]() { // onSuccess auto* owner = lifecycle->owner; @@ -499,6 +500,7 @@ namespace core::socket::stream::tls { TLSShutdown::doShutdownTypedWithRelease( Super::getConnectionName(), + core::socket::stream::SocketConnection::logScope.scope(), lifecycle->ssl, [lifecycle](TLSShutdown::TypedSuccess success) { auto* owner = lifecycle->owner; @@ -521,7 +523,7 @@ namespace core::socket::stream::tls { if (owner == nullptr) { return; } - ssl_log(owner->Super::getConnectionName() + " SSL/TLS: Shutdown handshake failed", sslErr); + ssl_log(owner->Super::log(), "SSL/TLS: Shutdown handshake failed", sslErr); owner->markTlsShutdownFailure(errno != 0 ? errno : EPROTO); }, sslShutdownTimeout, diff --git a/src/core/socket/stream/tls/SocketConnector.hpp b/src/core/socket/stream/tls/SocketConnector.hpp index f5ef4741a9..cfb70bc1a7 100644 --- a/src/core/socket/stream/tls/SocketConnector.hpp +++ b/src/core/socket/stream/tls/SocketConnector.hpp @@ -79,12 +79,12 @@ namespace core::socket::stream::tls { } }, [socketContextFactory, onConnected](SocketConnection* socketConnection) { // onConnected - static_cast(socketConnection)->log().trace("SSL/TLS: Start handshake"); + socketConnection->log().trace("SSL/TLS: Start handshake"); if (!socketConnection->doSSLHandshake( [socketContextFactory, onConnected, socketConnection, - log = static_cast(socketConnection)->log()]() { // onSuccess + log = socketConnection->log()]() { // onSuccess log.debug("SSL/TLS: Handshake success"); log.info("transport ready"); @@ -93,17 +93,18 @@ namespace core::socket::stream::tls { socketConnection->setSocketContext(socketContextFactory); }, [socketConnection, - log = static_cast(socketConnection)->log()]() { // onTimeout + log = socketConnection->log()]() { // onTimeout log.error("SSL/TLS: Handshake timed out"); socketConnection->close(); }, - [socketConnection](int sslErr) { // onError - ssl_log(socketConnection->getConnectionName() + " SSL/TLS: Handshake failed", sslErr); + [socketConnection, + log = socketConnection->log()](int sslErr) { // onError + ssl_log(log, "SSL/TLS: Handshake failed", sslErr); socketConnection->close(); })) { - static_cast(socketConnection)->log().error("SSL/TLS: Handshake failed"); + socketConnection->log().error("SSL/TLS: Handshake failed"); socketConnection->close(); } diff --git a/src/core/socket/stream/tls/SocketReader.cpp b/src/core/socket/stream/tls/SocketReader.cpp index e976e045e3..005965008b 100644 --- a/src/core/socket/stream/tls/SocketReader.cpp +++ b/src/core/socket/stream/tls/SocketReader.cpp @@ -40,6 +40,7 @@ */ #include "core/socket/stream/tls/SocketReader.h" + #include "core/socket/stream/tls/detail/TLSResult.h" #if defined(SNODEC_BUILD_TESTS) #include "core/socket/stream/tls/detail/TLSLifecycleTestAccess.h" @@ -48,54 +49,40 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/socket/stream/tls/ssl_utils.h" -#include "log/Logger.h" +#include "log/SemanticLogger.h" #include "utils/PreserveErrno.h" #include #include +#include #include #include #include #include +#include #endif // DOXYGEN_SHOULD_SKIP_THIS - #if defined(SNODEC_BUILD_TESTS) namespace core::socket::stream::tls::detail::test { IoState& readerState() { static IoState state; return state; } -} +} // namespace core::socket::stream::tls::detail::test #endif namespace core::socket::stream::tls { SocketReader::SocketReader(const std::string& instanceName, + logger::LogScope streamLogScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, const utils::Timeval& terminateTimeout) - : Super(instanceName, onStatus, timeout, blockSize, terminateTimeout) - , logScope(logger::LogOrigin::Framework, - logger::LogBoundary::Connection, - "core.socket.stream.tls", - instanceName.empty() ? std::nullopt : std::optional(instanceName), - std::nullopt, - instanceName.empty() ? std::nullopt : std::optional(instanceName)) { - } - - logger::BoundaryLogger SocketReader::log() const { - return logScope.logger(logger::Logger::semanticSink()); + : Super(instanceName, streamLogScope, onStatus, timeout, blockSize, terminateTimeout) { } - logger::BoundaryLogger - SocketReader::log(logger::BoundaryLogger::Sink sink, logger::LogLevel threshold, logger::BoundaryLogger::Clock clock) const { - return logScope.logger(std::move(sink), threshold, std::move(clock)); - } - - ssize_t SocketReader::read(char* chunk, std::size_t chunkLen) { if (handoffCursor < handoffBuffer.size()) { const std::size_t available = std::min(chunkLen, handoffBuffer.size() - handoffCursor); @@ -124,7 +111,8 @@ namespace core::socket::stream::tls { ret = operation.returnValue; errno = operation.systemError; result = ret > 0 ? detail::TlsIoResult{detail::TlsIoSuccess{ret}} - : detail::TlsIoResult{detail::classifyOpenSslFailure(static_cast(ret), operation.sslError, operation.systemError, operation.openSslError)}; + : detail::TlsIoResult{detail::classifyOpenSslFailure( + static_cast(ret), operation.sslError, operation.systemError, operation.openSslError)}; } else #endif { @@ -152,29 +140,29 @@ namespace core::socket::stream::tls { ret = -1; break; case detail::TlsStatus::WantWrite: - log().trace("{} SSL/TLS: Start renegotiation on read", getName()); + log().trace("SSL/TLS: Start renegotiation on read"); doSSLHandshake( - [log = this->log(), name = getName()]() { - log.debug("{} SSL/TLS: Renegotiation on read success", name); + [log = this->log()]() { + log.debug("SSL/TLS: Renegotiation on read success"); }, - [log = this->log(), name = getName()]() { - log.warn("{} SSL/TLS: Renegotiation on read timed out", name); + [log = this->log()]() { + log.warn("SSL/TLS: Renegotiation on read timed out"); }, [this](int sslErr) { - ssl_log(getName() + " SSL/TLS: Renegotiation on read", sslErr); + ssl_log(log(), "SSL/TLS: Renegotiation on read", sslErr); }); errno = EAGAIN; ret = -1; break; case detail::TlsStatus::CleanPeerShutdown: - log().debug("{} SSL/TLS: Clean peer close_notify on read", getName()); + log().debug("SSL/TLS: Clean peer close_notify on read"); onReadShutdown(); errno = EAGAIN; ret = -1; break; case detail::TlsStatus::UncleanEofWithoutCloseNotify: { const int errnum = EPROTO; - log().error("{} SSL/TLS: Transport ended without TLS close_notify", getName()); + log().error("SSL/TLS: Transport ended without TLS close_notify"); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -184,7 +172,7 @@ namespace core::socket::stream::tls { case detail::TlsStatus::SyscallError: { const int errnum = detail::fatalTlsStatusToErrno(status); const utils::PreserveErrno pe; - log().sysError(logger::LogLevel::Warn, errnum, "{} SSL/TLS: Syscall error on read", getName()); + log().sysError(logger::LogLevel::Warn, errnum, "SSL/TLS: Syscall error on read"); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -193,7 +181,7 @@ namespace core::socket::stream::tls { } case detail::TlsStatus::SslProtocolError: { const int errnum = EPROTO; - ssl_log(getName() + " SSL/TLS: Read protocol failure", status.sslError); + ssl_log(log(), "SSL/TLS: Read protocol failure", status.sslError); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -202,7 +190,7 @@ namespace core::socket::stream::tls { } case detail::TlsStatus::UnknownError: { const int errnum = detail::fatalTlsStatusToErrno(status); - ssl_log(getName() + " SSL/TLS: Unknown read failure", status.sslError); + ssl_log(log(), "SSL/TLS: Unknown read failure", status.sslError); errno = errnum; onTlsFatalError(errnum); errno = errnum; diff --git a/src/core/socket/stream/tls/SocketReader.h b/src/core/socket/stream/tls/SocketReader.h index 07a8f86da4..0be88e5252 100644 --- a/src/core/socket/stream/tls/SocketReader.h +++ b/src/core/socket/stream/tls/SocketReader.h @@ -43,13 +43,19 @@ #define CORE_SOCKET_STREAM_TLS_SOCKETREADER_H #include "core/socket/stream/SocketReader.h" -#include "log/LogScopeOwner.h" + +namespace logger { + struct LogScope; +} #ifndef DOXYGEN_SHOULD_SKIP_THIS +#include "utils/Timeval.h" + #include #include #include +#include #include #include @@ -67,17 +73,12 @@ namespace core::socket::stream::tls { protected: explicit SocketReader(const std::string& instanceName, + logger::LogScope streamLogScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, const utils::Timeval& terminateTimeout); - public: - logger::BoundaryLogger log() const; - logger::BoundaryLogger log(logger::BoundaryLogger::Sink sink, - logger::LogLevel threshold = logger::LogLevel::Trace, - logger::BoundaryLogger::Clock clock = {}) const; - private: ssize_t read(char* chunk, std::size_t chunkLen) override; @@ -98,8 +99,6 @@ namespace core::socket::stream::tls { std::vector handoffBuffer; std::size_t handoffCursor = 0; - logger::LogScopeOwner logScope; - friend struct detail::TLSLifecycleTestAccess; }; diff --git a/src/core/socket/stream/tls/SocketWriter.cpp b/src/core/socket/stream/tls/SocketWriter.cpp index 2faab70468..7c5e39667b 100644 --- a/src/core/socket/stream/tls/SocketWriter.cpp +++ b/src/core/socket/stream/tls/SocketWriter.cpp @@ -40,6 +40,7 @@ */ #include "core/socket/stream/tls/SocketWriter.h" + #include "core/socket/stream/tls/detail/TLSResult.h" #if defined(SNODEC_BUILD_TESTS) #include "core/socket/stream/tls/detail/TLSLifecycleTestAccess.h" @@ -48,37 +49,31 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/socket/stream/tls/ssl_utils.h" -#include "log/Logger.h" +#include "log/SemanticLogger.h" #include "utils/PreserveErrno.h" #include +#include #include #include #include +#include #endif // DOXYGEN_SHOULD_SKIP_THIS - #if defined(SNODEC_BUILD_TESTS) namespace core::socket::stream::tls::detail::test { IoState& writerState() { static IoState state; return state; } -} +} // namespace core::socket::stream::tls::detail::test #endif namespace core::socket::stream::tls { SocketWriter::SocketWriter(const std::string& instanceName, - const std::function& onStatus, - const utils::Timeval& timeout, - std::size_t blockSize, - const utils::Timeval& terminateTimeout) - : SocketWriter(instanceName, onStatus, timeout, blockSize, terminateTimeout, 0, 0, 0) { - } - - SocketWriter::SocketWriter(const std::string& instanceName, + logger::LogScope streamLogScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, @@ -87,31 +82,16 @@ namespace core::socket::stream::tls { std::size_t writeQueueHighWatermark, std::size_t writeQueueLowWatermark) : Super(instanceName, + streamLogScope, onStatus, timeout, blockSize, terminateTimeout, maximumWriteQueueBytes, writeQueueHighWatermark, - writeQueueLowWatermark) - , logScope(logger::LogOrigin::Framework, - logger::LogBoundary::Connection, - "core.socket.stream.tls", - instanceName.empty() ? std::nullopt : std::optional(instanceName), - std::nullopt, - instanceName.empty() ? std::nullopt : std::optional(instanceName)) { - } - - logger::BoundaryLogger SocketWriter::log() const { - return logScope.logger(logger::Logger::semanticSink()); + writeQueueLowWatermark) { } - logger::BoundaryLogger - SocketWriter::log(logger::BoundaryLogger::Sink sink, logger::LogLevel threshold, logger::BoundaryLogger::Clock clock) const { - return logScope.logger(std::move(sink), threshold, std::move(clock)); - } - - ssize_t SocketWriter::write(const char* chunk, std::size_t chunkLen) { ssize_t ret = 0; @@ -128,7 +108,8 @@ namespace core::socket::stream::tls { ret = operation.returnValue; errno = operation.systemError; result = ret > 0 ? detail::TlsIoResult{detail::TlsIoSuccess{ret}} - : detail::TlsIoResult{detail::classifyOpenSslFailure(static_cast(ret), operation.sslError, operation.systemError, operation.openSslError)}; + : detail::TlsIoResult{detail::classifyOpenSslFailure( + static_cast(ret), operation.sslError, operation.systemError, operation.openSslError)}; } else #endif { @@ -152,16 +133,16 @@ namespace core::socket::stream::tls { const detail::TlsStatusInfo& status = std::get(result.value); switch (status.status) { case detail::TlsStatus::WantRead: - log().trace("{} SSL/TLS: Start renegotiation on write", getName()); + log().trace("SSL/TLS: Start renegotiation on write"); doSSLHandshake( - [log = this->log(), name = getName()]() { - log.debug("{} SSL/TLS: Renegotiation on write success", name); + [log = this->log()]() { + log.debug("SSL/TLS: Renegotiation on write success"); }, - [log = this->log(), name = getName()]() { - log.warn("{} SSL/TLS: Renegotiation on write timed out", name); + [log = this->log()]() { + log.warn("SSL/TLS: Renegotiation on write timed out"); }, [this](int sslErr) { - ssl_log(getName() + " SSL/TLS: Renegotiation on write", sslErr); + ssl_log(log(), "SSL/TLS: Renegotiation on write", sslErr); }); errno = EAGAIN; ret = -1; @@ -176,7 +157,7 @@ namespace core::socket::stream::tls { break; case detail::TlsStatus::UncleanEofWithoutCloseNotify: { const int errnum = EPROTO; - log().error("{} SSL/TLS: Transport ended without TLS close_notify on write", getName()); + log().error("SSL/TLS: Transport ended without TLS close_notify on write"); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -186,7 +167,7 @@ namespace core::socket::stream::tls { case detail::TlsStatus::SyscallError: { const int errnum = detail::fatalTlsStatusToErrno(status); const utils::PreserveErrno pe; - log().sysError(logger::LogLevel::Warn, errnum, "{} SSL/TLS: Syscall error on write", getName()); + log().sysError(logger::LogLevel::Warn, errnum, "SSL/TLS: Syscall error on write"); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -195,7 +176,7 @@ namespace core::socket::stream::tls { } case detail::TlsStatus::SslProtocolError: { const int errnum = EPROTO; - ssl_log(getName() + " SSL/TLS: Write protocol failure", status.sslError); + ssl_log(log(), "SSL/TLS: Write protocol failure", status.sslError); errno = errnum; onTlsFatalError(errnum); errno = errnum; @@ -204,7 +185,7 @@ namespace core::socket::stream::tls { } case detail::TlsStatus::UnknownError: { const int errnum = detail::fatalTlsStatusToErrno(status); - ssl_log(getName() + " SSL/TLS: Unknown write failure", status.sslError); + ssl_log(log(), "SSL/TLS: Unknown write failure", status.sslError); errno = errnum; onTlsFatalError(errnum); errno = errnum; diff --git a/src/core/socket/stream/tls/SocketWriter.h b/src/core/socket/stream/tls/SocketWriter.h index 643f2688e8..6813d52a7a 100644 --- a/src/core/socket/stream/tls/SocketWriter.h +++ b/src/core/socket/stream/tls/SocketWriter.h @@ -43,13 +43,19 @@ #define CORE_SOCKET_STREAM_TLS_SOCKETWRITER_H #include "core/socket/stream/SocketWriter.h" -#include "log/LogScopeOwner.h" + +namespace logger { + struct LogScope; +} #ifndef DOXYGEN_SHOULD_SKIP_THIS +#include "utils/Timeval.h" + #include #include #include +#include #include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -65,13 +71,8 @@ namespace core::socket::stream::tls { using Super = core::socket::stream::SocketWriter; protected: - explicit SocketWriter(const std::string& instanceName, - const std::function& onStatus, - const utils::Timeval& timeout, - std::size_t blockSize, - const utils::Timeval& terminateTimeout); - SocketWriter(const std::string& instanceName, + logger::LogScope streamLogScope, const std::function& onStatus, const utils::Timeval& timeout, std::size_t blockSize, @@ -80,12 +81,6 @@ namespace core::socket::stream::tls { std::size_t writeQueueHighWatermark, std::size_t writeQueueLowWatermark); - public: - logger::BoundaryLogger log() const; - logger::BoundaryLogger log(logger::BoundaryLogger::Sink sink, - logger::LogLevel threshold = logger::LogLevel::Trace, - logger::BoundaryLogger::Clock clock = {}) const; - private: ssize_t write(const char* chunk, std::size_t chunkLen) override; @@ -99,8 +94,6 @@ namespace core::socket::stream::tls { SSL* ssl = nullptr; private: - logger::LogScopeOwner logScope; - friend struct detail::TLSLifecycleTestAccess; }; diff --git a/src/core/socket/stream/tls/TLSHandshake.cpp b/src/core/socket/stream/tls/TLSHandshake.cpp index 918df44c7a..ee98c561af 100644 --- a/src/core/socket/stream/tls/TLSHandshake.cpp +++ b/src/core/socket/stream/tls/TLSHandshake.cpp @@ -40,7 +40,10 @@ */ #include "core/socket/stream/tls/TLSHandshake.h" + #include "core/socket/stream/tls/detail/TLSResult.h" +#include "log/LogScopeOwner.h" +#include "log/SemanticLogger.h" #if defined(SNODEC_BUILD_TESTS) #include "core/socket/stream/tls/detail/TLSLifecycleTestAccess.h" @@ -50,8 +53,11 @@ #include #include +#include #include #include +#include +#include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -75,22 +81,26 @@ namespace core::socket::stream::tls { const std::function& onTimeout, const std::function& onStatus, const utils::Timeval& timeout) { - doHandshakeWithRelease(instanceName, ssl, onSuccess, onTimeout, onStatus, timeout, {}); + const logger::LogScopeOwner logScope( + logger::LogOrigin::Framework, logger::LogBoundary::System, "core.eventreceiver", instanceName + " SSL/TLS: Handshake"); + auto* helper = new TLSHandshake(instanceName, logScope.scope(), ssl, onSuccess, onTimeout, onStatus, timeout, {}, SSL_get_fd(ssl)); + helper->start(); } void TLSHandshake::doHandshakeWithRelease(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, const std::function& onStatus, const utils::Timeval& timeout, const std::function& onReleased) { - auto* helper = new TLSHandshake(instanceName, ssl, onSuccess, onTimeout, onStatus, timeout, onReleased, SSL_get_fd(ssl)); + auto* helper = new TLSHandshake(instanceName, logScope, ssl, onSuccess, onTimeout, onStatus, timeout, onReleased, SSL_get_fd(ssl)); helper->start(); } - TLSHandshake::TLSHandshake(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, @@ -98,8 +108,8 @@ namespace core::socket::stream::tls { const utils::Timeval& timeout, const std::function& onReleased, int fd) - : ReadEventReceiver(instanceName + " SSL/TLS: Handshake", timeout) - , WriteEventReceiver(instanceName + " SSL/TLS: Handshake", timeout) + : ReadEventReceiver(instanceName + " SSL/TLS: Handshake", logScope, timeout) + , WriteEventReceiver(instanceName + " SSL/TLS: Handshake", logScope, timeout) , ssl(ssl) , onSuccess(onSuccess) , onTimeout(onTimeout) diff --git a/src/core/socket/stream/tls/TLSHandshake.h b/src/core/socket/stream/tls/TLSHandshake.h index eb117ad953..b94d07e594 100644 --- a/src/core/socket/stream/tls/TLSHandshake.h +++ b/src/core/socket/stream/tls/TLSHandshake.h @@ -45,6 +45,10 @@ #include "core/eventreceiver/ReadEventReceiver.h" #include "core/eventreceiver/WriteEventReceiver.h" +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS namespace utils { @@ -86,15 +90,16 @@ namespace core::socket::stream::tls { private: static void doHandshakeWithRelease(const std::string& instanceName, - SSL* ssl, - const std::function& onSuccess, - const std::function& onTimeout, - const std::function& onStatus, - const utils::Timeval& timeout, - const std::function& onReleased); - + logger::LogScope logScope, + SSL* ssl, + const std::function& onSuccess, + const std::function& onTimeout, + const std::function& onStatus, + const utils::Timeval& timeout, + const std::function& onReleased); TLSHandshake(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, diff --git a/src/core/socket/stream/tls/TLSShutdown.cpp b/src/core/socket/stream/tls/TLSShutdown.cpp index 4653bd6500..48c782b074 100644 --- a/src/core/socket/stream/tls/TLSShutdown.cpp +++ b/src/core/socket/stream/tls/TLSShutdown.cpp @@ -42,6 +42,8 @@ #include "core/socket/stream/tls/TLSShutdown.h" #include "core/socket/stream/tls/detail/TLSResult.h" +#include "log/LogScopeOwner.h" +#include "log/SemanticLogger.h" #if defined(SNODEC_BUILD_TESTS) #include "core/socket/stream/tls/detail/TLSLifecycleTestAccess.h" @@ -52,8 +54,11 @@ #include #include #include +#include #include #include +#include +#include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -78,18 +83,11 @@ namespace core::socket::stream::tls { const std::function& onTimeout, const std::function& onStatus, const utils::Timeval& timeout) { - doShutdownWithRelease(instanceName, ssl, onSuccess, onTimeout, onStatus, timeout, {}); - } - - void TLSShutdown::doShutdownWithRelease(const std::string& instanceName, - SSL* ssl, - const std::function& onSuccess, - const std::function& onTimeout, - const std::function& onStatus, - const utils::Timeval& timeout, - const std::function& onReleased) { + const logger::LogScopeOwner logScope( + logger::LogOrigin::Framework, logger::LogBoundary::System, "core.eventreceiver", instanceName + " SSL/TLS: Send close_notify"); auto* helper = new TLSShutdown( instanceName, + logScope.scope(), ssl, [onSuccess](TypedSuccess) { onSuccess(); @@ -97,12 +95,13 @@ namespace core::socket::stream::tls { onTimeout, onStatus, timeout, - onReleased, + {}, SSL_get_fd(ssl)); helper->start(); } void TLSShutdown::doShutdownTypedWithRelease(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, @@ -111,12 +110,14 @@ namespace core::socket::stream::tls { const std::function& onReleased, CompletionRequirement completionRequirement, const std::function& onApplicationData) { - auto* helper = new TLSShutdown(instanceName, ssl, onSuccess, onTimeout, onStatus, timeout, onReleased, SSL_get_fd(ssl), onApplicationData); + auto* helper = new TLSShutdown( + instanceName, logScope, ssl, onSuccess, onTimeout, onStatus, timeout, onReleased, SSL_get_fd(ssl), onApplicationData); helper->completionRequirement = completionRequirement; helper->start(); } TLSShutdown::TLSShutdown(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, @@ -125,8 +126,8 @@ namespace core::socket::stream::tls { const std::function& onReleased, int fd, const std::function& onApplicationData) - : ReadEventReceiver(instanceName + " SSL/TLS: Send close_notify", timeout) - , WriteEventReceiver(instanceName + " SSL/TLS: Send close_notify", timeout) + : ReadEventReceiver(instanceName + " SSL/TLS: Send close_notify", logScope, timeout) + , WriteEventReceiver(instanceName + " SSL/TLS: Send close_notify", logScope, timeout) , ssl(ssl) , onSuccess(onSuccess) , onTimeout(onTimeout) diff --git a/src/core/socket/stream/tls/TLSShutdown.h b/src/core/socket/stream/tls/TLSShutdown.h index b0e4aa5225..92b0459198 100644 --- a/src/core/socket/stream/tls/TLSShutdown.h +++ b/src/core/socket/stream/tls/TLSShutdown.h @@ -45,6 +45,10 @@ #include "core/eventreceiver/ReadEventReceiver.h" #include "core/eventreceiver/WriteEventReceiver.h" +namespace logger { + struct LogScope; +} + #ifndef DOXYGEN_SHOULD_SKIP_THIS namespace utils { @@ -86,14 +90,6 @@ namespace core::socket::stream::tls { const utils::Timeval& timeout); private: - static void doShutdownWithRelease(const std::string& instanceName, - SSL* ssl, - const std::function& onSuccess, - const std::function& onTimeout, - const std::function& onStatus, - const utils::Timeval& timeout, - const std::function& onReleased); - enum class TypedSuccess { CloseNotifySent, FullShutdownComplete @@ -105,6 +101,7 @@ namespace core::socket::stream::tls { }; static void doShutdownTypedWithRelease(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, @@ -114,8 +111,8 @@ namespace core::socket::stream::tls { CompletionRequirement completionRequirement = CompletionRequirement::RequireFullShutdown, const std::function& onApplicationData = {}); - TLSShutdown(const std::string& instanceName, + logger::LogScope logScope, SSL* ssl, const std::function& onSuccess, const std::function& onTimeout, diff --git a/src/core/socket/stream/tls/detail/TLSLifecycleTestAccess.h b/src/core/socket/stream/tls/detail/TLSLifecycleTestAccess.h index 39060f8518..6f5792618c 100644 --- a/src/core/socket/stream/tls/detail/TLSLifecycleTestAccess.h +++ b/src/core/socket/stream/tls/detail/TLSLifecycleTestAccess.h @@ -7,6 +7,7 @@ #include "core/socket/stream/tls/SocketWriter.h" #include "core/socket/stream/tls/TLSShutdown.h" #include "core/socket/stream/tls/detail/TLSResult.h" +#include "log/LogScopeOwner.h" #include #include @@ -113,7 +114,10 @@ namespace core::socket::stream::tls::detail { const std::function& onStatus, const utils::Timeval& timeout, const std::function& onReleased) { - auto* helper = new TLSHandshake(instanceName, nullptr, onSuccess, onTimeout, onStatus, timeout, onReleased, fd); + const logger::LogScopeOwner logScope( + logger::LogOrigin::Framework, logger::LogBoundary::System, "core.eventreceiver", instanceName + " SSL/TLS: Handshake"); + auto* helper = new TLSHandshake( + instanceName, logScope.scope(), nullptr, onSuccess, onTimeout, onStatus, timeout, onReleased, fd); helper->start(); } @@ -124,7 +128,22 @@ namespace core::socket::stream::tls::detail { const std::function& onStatus, const utils::Timeval& timeout, const std::function& onReleased) { - auto* helper = new TLSShutdown(instanceName, nullptr, [onSuccess](TLSShutdown::TypedSuccess) { onSuccess(); }, onTimeout, onStatus, timeout, onReleased, fd); + const logger::LogScopeOwner logScope(logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + instanceName + " SSL/TLS: Send close_notify"); + auto* helper = new TLSShutdown( + instanceName, + logScope.scope(), + nullptr, + [onSuccess](TLSShutdown::TypedSuccess) { + onSuccess(); + }, + onTimeout, + onStatus, + timeout, + onReleased, + fd); helper->start(); } diff --git a/src/core/socket/stream/tls/ssl_utils.cpp b/src/core/socket/stream/tls/ssl_utils.cpp index e3282692e4..ee0d80461a 100644 --- a/src/core/socket/stream/tls/ssl_utils.cpp +++ b/src/core/socket/stream/tls/ssl_utils.cpp @@ -45,6 +45,7 @@ #include "log/LogScopeOwner.h" #include "log/Logger.h" +#include "log/SemanticLogger.h" #include "utils/PreserveErrno.h" #include @@ -57,6 +58,7 @@ #include #include #include +#include #include #endif /* DOXYGEN_SHOULD_SKIP_THIS */ @@ -77,6 +79,21 @@ namespace core::socket::stream::tls { logger::BoundaryLogger tlsLog() { return tlsLogScope().logger(logger::Logger::semanticSink()); } + + void emitOpenSslErrors(const logger::BoundaryLogger& log, logger::LogLevel level, const std::string& message) { + if (!log.enabled(level)) { + return; + } + + log.emit(level, message); + const unsigned long firstErrorCode = ERR_get_error(); + log.emit(level, std::string(" ") + ERR_error_string(firstErrorCode, nullptr)); + + unsigned long errorCode = 0; + while ((errorCode = ERR_get_error()) != 0) { + log.emit(level, std::string(" ") + ERR_error_string(errorCode, nullptr)); + } + } } // namespace static int password_callback(char* buf, int size, [[maybe_unused]] int a, void* u) { @@ -333,76 +350,44 @@ namespace core::socket::stream::tls { } void ssl_log(const std::string& message, int sslErr) { + ssl_log(tlsLog(), message, sslErr); + } + + void ssl_log(const logger::BoundaryLogger& log, const std::string& message, int sslErr) { const utils::PreserveErrno preserveErrno; switch (sslErr) { case SSL_ERROR_NONE: [[fallthrough]]; case SSL_ERROR_ZERO_RETURN: - ssl_log_info(message); + emitOpenSslErrors(log, logger::LogLevel::Info, message); break; case SSL_ERROR_SYSCALL: if (errno != 0) { - ssl_log_error(message); + emitOpenSslErrors(log, logger::LogLevel::Error, message); } else { - ssl_log_info(message); + emitOpenSslErrors(log, logger::LogLevel::Info, message); } break; case SSL_ERROR_SSL: - ssl_log_error(message); + emitOpenSslErrors(log, logger::LogLevel::Error, message); break; default: - ssl_log_warning(message); + emitOpenSslErrors(log, logger::LogLevel::Warn, message); break; } } void ssl_log_error(const std::string& message) { - auto log = tlsLog(); - if (!log.enabled(logger::LogLevel::Error)) { - return; - } - - log.error("{}", message); - const unsigned long firstErrorCode = ERR_get_error(); - log.error(" {}", ERR_error_string(firstErrorCode, nullptr)); - - unsigned long errorCode = 0; - while ((errorCode = ERR_get_error()) != 0) { - log.error(" {}", ERR_error_string(errorCode, nullptr)); - } + emitOpenSslErrors(tlsLog(), logger::LogLevel::Error, message); } void ssl_log_warning(const std::string& message) { - auto log = tlsLog(); - if (!log.enabled(logger::LogLevel::Warn)) { - return; - } - - log.warn("{}", message); - const unsigned long firstErrorCode = ERR_get_error(); - log.warn(" {}", ERR_error_string(firstErrorCode, nullptr)); - - unsigned long errorCode = 0; - while ((errorCode = ERR_get_error()) != 0) { - log.warn(" {}", ERR_error_string(errorCode, nullptr)); - } + emitOpenSslErrors(tlsLog(), logger::LogLevel::Warn, message); } void ssl_log_info(const std::string& message) { - auto log = tlsLog(); - if (!log.enabled(logger::LogLevel::Info)) { - return; - } - - log.info("{}", message); - const unsigned long firstErrorCode = ERR_get_error(); - log.info(" {}", ERR_error_string(firstErrorCode, nullptr)); - - unsigned long errorCode = 0; - while ((errorCode = ERR_get_error()) != 0) { - log.info(" {}", ERR_error_string(errorCode, nullptr)); - } + emitOpenSslErrors(tlsLog(), logger::LogLevel::Info, message); } bool match(const char* first, const char* second) { diff --git a/src/core/socket/stream/tls/ssl_utils.h b/src/core/socket/stream/tls/ssl_utils.h index ce4970b254..9990200c42 100644 --- a/src/core/socket/stream/tls/ssl_utils.h +++ b/src/core/socket/stream/tls/ssl_utils.h @@ -60,6 +60,10 @@ #endif /* DOXYGEN_SHOULD_SKIP_THIS */ +namespace logger { + class BoundaryLogger; +} + #if OPENSSL_VERSION_NUMBER >= 0x30000000L using ssl_option_t = uint64_t; @@ -99,6 +103,7 @@ namespace core::socket::stream::tls { void ssl_log_warning(const std::string& message); void ssl_log_info(const std::string& message); void ssl_log(const std::string& message, int sslErr); + void ssl_log(const logger::BoundaryLogger& log, const std::string& message, int sslErr); // From https://www.geeksforgeeks.org/wildcard-character-matching/ // diff --git a/src/database/mariadb/MariaDBClient.cpp b/src/database/mariadb/MariaDBClient.cpp index 2153e2a039..8376c438b5 100644 --- a/src/database/mariadb/MariaDBClient.cpp +++ b/src/database/mariadb/MariaDBClient.cpp @@ -53,8 +53,11 @@ namespace database::mariadb { - MariaDBClient::MariaDBClient(const MariaDBConnectionDetails& details, const std::function& onStateChanged) + MariaDBClient::MariaDBClient(const MariaDBConnectionDetails& details, + const std::function& onStateChanged, + const std::string& instanceName) : details(details) + , instanceName(instanceName) , onStateChanged(onStateChanged) { } @@ -66,7 +69,7 @@ namespace database::mariadb { MariaDBCommandSequence& MariaDBClient::execute_async(MariaDBCommand* mariaDBCommand) { if (mariaDBConnection == nullptr) { - mariaDBConnection = new MariaDBConnection(this, details, onStateChanged); + mariaDBConnection = new MariaDBConnection(this, details, onStateChanged, instanceName); } return mariaDBConnection->execute_async(std::move(MariaDBCommandSequence().execute_async(mariaDBCommand))); @@ -74,7 +77,7 @@ namespace database::mariadb { void MariaDBClient::execute_sync(MariaDBCommandSync* mariaDBCommand) { if (mariaDBConnection == nullptr) { - mariaDBConnection = new MariaDBConnection(this, details, onStateChanged); + mariaDBConnection = new MariaDBConnection(this, details, onStateChanged, instanceName); } mariaDBConnection->execute_sync(mariaDBCommand); diff --git a/src/database/mariadb/MariaDBClient.h b/src/database/mariadb/MariaDBClient.h index db68ec70e8..3a3f97cd28 100644 --- a/src/database/mariadb/MariaDBClient.h +++ b/src/database/mariadb/MariaDBClient.h @@ -94,7 +94,9 @@ namespace database::mariadb { : public MariaDBClientASyncAPI , public MariaDBClientSyncAPI { public: - explicit MariaDBClient(const MariaDBConnectionDetails& details, const std::function& onStateChanged); + explicit MariaDBClient(const MariaDBConnectionDetails& details, + const std::function& onStateChanged, + const std::string& instanceName = {}); ~MariaDBClient() override; private: @@ -106,6 +108,7 @@ namespace database::mariadb { MariaDBConnection* mariaDBConnection = nullptr; MariaDBConnectionDetails details; + std::string instanceName; std::function onStateChanged = nullptr; diff --git a/src/database/mariadb/MariaDBConnection.cpp b/src/database/mariadb/MariaDBConnection.cpp index da05d87354..cf32341372 100644 --- a/src/database/mariadb/MariaDBConnection.cpp +++ b/src/database/mariadb/MariaDBConnection.cpp @@ -42,7 +42,6 @@ #include "database/mariadb/MariaDBConnection.h" -#include "SemanticLog.h" #include "database/mariadb/MariaDBClient.h" #include "database/mariadb/MariaDBLibrary.h" #include "database/mariadb/commands/async/MariaDBConnectCommand.h" @@ -50,10 +49,10 @@ #ifndef DOXYGEN_SHOULD_SKIP_THIS #include "core/SNodeC.h" -#include "log/SemanticLogger.h" #include "utils/Timeval.h" #include +#include #include #include @@ -63,12 +62,21 @@ namespace database::mariadb { MariaDBConnection::MariaDBConnection(MariaDBClient* mariaDBClient, const MariaDBConnectionDetails& connectionDetails, - const std::function& onStateChanged) - : ReadEventReceiver("MariaDBConnectionRead", core::DescriptorEventReceiver::TIMEOUT::DISABLE) - , WriteEventReceiver("MariaDBConnectionWrite", core::DescriptorEventReceiver::TIMEOUT::DISABLE) - , ExceptionalConditionEventReceiver("MariaDBConnectionExceptional", core::DescriptorEventReceiver::TIMEOUT::DISABLE) + const std::function& onStateChanged, + const std::string& instanceName) + : MariaDBConnection( + mariaDBClient, connectionDetails, onStateChanged, makeLogScope(instanceName, connectionDetails.connectionName)) { + } + + MariaDBConnection::MariaDBConnection(MariaDBClient* mariaDBClient, + const MariaDBConnectionDetails& connectionDetails, + const std::function& onStateChanged, + logger::LogScopeOwner logScope) + : ReadEventReceiver("MariaDBConnectionRead", logScope.scope(), core::DescriptorEventReceiver::TIMEOUT::DISABLE) + , WriteEventReceiver("MariaDBConnectionWrite", logScope.scope(), core::DescriptorEventReceiver::TIMEOUT::DISABLE) + , ExceptionalConditionEventReceiver( + "MariaDBConnectionExceptional", logScope.scope(), core::DescriptorEventReceiver::TIMEOUT::DISABLE) , mariaDBClient(mariaDBClient) - , connectionName(connectionDetails.connectionName) , commandStartEvent("MariaDBCommandStartEvent", this) , onStateChanged(onStateChanged) { MariaDBLibrary::ensureInitialized(); @@ -99,19 +107,19 @@ namespace database::mariadb { ExceptionalConditionEventReceiver::disable(); } - snode::semantic::mariaDbLog().error() << this->connectionName << ": Descriptor not registered in SNode.C eventloop"; + log().error() << "Descriptor not registered in SNode.C eventloop"; } } }, [this]() { - snode::semantic::mariaDbLog().debug() << this->connectionName << ": connect: success"; + log().debug() << "connect: success"; this->sessionEstablished = true; - snode::semantic::mariaDbLog().info() << "database session established: connection=" << this->connectionName; + log().info() << "database session established"; this->onStateChanged({.error = 0, .errorMessage = "", .connected = true}); }, [this](const std::string& errorString, unsigned int errorNumber) { - snode::semantic::mariaDbLog().warn() << this->connectionName << ": connect: error: " << errorString << " : " << errorNumber; + log().warn() << "connect: error: " << errorString << " : " << errorNumber; this->onStateChanged({.error = errorNumber, .errorMessage = errorString}); })))); @@ -119,9 +127,8 @@ namespace database::mariadb { MariaDBConnection::~MariaDBConnection() { if (currentCommandStarted && currentCommand != nullptr) { - snode::semantic::mariaDbLog().debug() - << "database request " << (closing || core::SNodeC::state() != core::State::RUNNING ? "cancelled" : "failed") - << ": connection=" << connectionName << " command=" << currentCommand->commandInfo(); + log().debug() << "database request " << (closing || core::SNodeC::state() != core::State::RUNNING ? "cancelled" : "failed") + << ": command=" << currentCommand->commandInfo(); currentCommandStarted = false; } @@ -145,7 +152,7 @@ namespace database::mariadb { } if (sessionEstablished) { - snode::semantic::mariaDbLog().info() << "database session ended: connection=" << connectionName; + log().info() << "database session ended"; sessionEstablished = false; } } @@ -179,8 +186,7 @@ namespace database::mariadb { currentCommandStarted = true; currentCommandFailed = false; - snode::semantic::mariaDbLog().debug() - << "database request started: connection=" << connectionName << " command=" << currentCommand->commandInfo(); + log().debug() << "database request started: command=" << currentCommand->commandInfo(); currentCommand->setMariaDBConnection(this); checkStatus(currentCommand->commandStart(mysql, currentTime)); @@ -207,8 +213,8 @@ namespace database::mariadb { void MariaDBConnection::commandCompleted() { if (currentCommandStarted) { - snode::semantic::mariaDbLog().debug() << "database request " << (currentCommandFailed ? "failed" : "completed") - << ": connection=" << connectionName << " command=" << currentCommand->commandInfo(); + log().debug() << "database request " << (currentCommandFailed ? "failed" : "completed") + << ": command=" << currentCommand->commandInfo(); currentCommandStarted = false; } commandSequenceQueue.front().commandCompleted(); @@ -323,7 +329,7 @@ namespace database::mariadb { void MariaDBConnection::unobservedEvent() { if (!closing) { - snode::semantic::mariaDbLog().error() << connectionName << ": Lost connection"; + log().error() << "Lost connection"; } if (mariaDBClient != nullptr) { @@ -333,6 +339,19 @@ namespace database::mariadb { delete this; } + logger::LogScopeOwner MariaDBConnection::makeLogScope(const std::string& instanceName, const std::string& connectionName) { + return logger::LogScopeOwner(logger::LogOrigin::Framework, + logger::LogBoundary::Connection, + "db.mariadb", + instanceName.empty() ? std::nullopt : std::optional(instanceName), + std::nullopt, + connectionName.empty() ? std::nullopt : std::optional(connectionName)); + } + + logger::BoundaryLogger MariaDBConnection::log() const { + return static_cast(*this).log(); + } + MariaDBCommandStartEvent::MariaDBCommandStartEvent(const std::string& name, MariaDBConnection* mariaDBConnection) : core::EventReceiver(name) , mariaDBConnection(mariaDBConnection) { diff --git a/src/database/mariadb/MariaDBConnection.h b/src/database/mariadb/MariaDBConnection.h index 211ccc91ab..5497882ba9 100644 --- a/src/database/mariadb/MariaDBConnection.h +++ b/src/database/mariadb/MariaDBConnection.h @@ -47,6 +47,8 @@ #include "core/eventreceiver/ReadEventReceiver.h" #include "core/eventreceiver/WriteEventReceiver.h" #include "database/mariadb/MariaDBCommandSequence.h" // IWYU pragma: export +#include "log/LogScopeOwner.h" +#include "log/SemanticLogger.h" namespace database::mariadb { class MariaDBCommand; @@ -92,7 +94,8 @@ namespace database::mariadb { public: explicit MariaDBConnection(MariaDBClient* mariaDBClient, const MariaDBConnectionDetails& connectionDetails, - const std::function& onStateChanged); + const std::function& onStateChanged, + const std::string& instanceName = {}); MariaDBConnection(const MariaDBConnection&) = delete; ~MariaDBConnection() override; @@ -122,9 +125,16 @@ namespace database::mariadb { void unobservedEvent() override; private: + MariaDBConnection(MariaDBClient* mariaDBClient, + const MariaDBConnectionDetails& connectionDetails, + const std::function& onStateChanged, + logger::LogScopeOwner logScope); + + static logger::LogScopeOwner makeLogScope(const std::string& instanceName, const std::string& connectionName); + logger::BoundaryLogger log() const; + MariaDBClient* mariaDBClient = nullptr; MYSQL* mysql = nullptr; - const std::string connectionName; std::deque commandSequenceQueue; diff --git a/src/net/phy/PhysicalSocketOption.cpp b/src/net/phy/PhysicalSocketOption.cpp index ddfd0237f3..bc40b281b8 100644 --- a/src/net/phy/PhysicalSocketOption.cpp +++ b/src/net/phy/PhysicalSocketOption.cpp @@ -74,7 +74,7 @@ namespace net::phy { } const void* PhysicalSocketOption::getOptValue() const { - return static_cast(optValue.data()); + return optValue.data(); } socklen_t PhysicalSocketOption::getOptLen() const { diff --git a/tests/component/core/DescriptorRegistrationFailureTest.cpp b/tests/component/core/DescriptorRegistrationFailureTest.cpp index e295cd3621..fdd0f78e5f 100644 --- a/tests/component/core/DescriptorRegistrationFailureTest.cpp +++ b/tests/component/core/DescriptorRegistrationFailureTest.cpp @@ -86,7 +86,14 @@ namespace { class RealPublisherProbe final : public core::eventreceiver::ReadEventReceiver { public: RealPublisherProbe() - : ReadEventReceiver("real descriptor registration probe", TIMEOUT::DISABLE) { + : ReadEventReceiver("real descriptor registration probe", + logger::LogScope{logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + "real descriptor registration probe read", + logger::LogRole::Unknown, + {}}, + TIMEOUT::DISABLE) { } ~RealPublisherProbe() override = default; diff --git a/tests/component/core/PipeImmediateCloseTest.cpp b/tests/component/core/PipeImmediateCloseTest.cpp index b466313eb2..5135803c8c 100644 --- a/tests/component/core/PipeImmediateCloseTest.cpp +++ b/tests/component/core/PipeImmediateCloseTest.cpp @@ -10,12 +10,16 @@ #include "core/pipe/Pipe.h" #include "core/pipe/PipeSource.h" #include "core/timer/Timer.h" +#include "log/SemanticLogger.h" #include "support/TestResult.h" #include "utils/Timeval.h" #include #include +#include #include +#include +#include int main(int argc, char* argv[]) { tests::support::TestResult testResult; @@ -25,7 +29,7 @@ int main(int argc, char* argv[]) { } core::SNodeC::init(argc, argv); - core::pipe::Pipe pipe(O_NONBLOCK | O_CLOEXEC); + core::pipe::Pipe pipe(O_NONBLOCK | O_CLOEXEC, "immediate-close-pipe"); const bool completePipe = pipe.hasReadFd() && pipe.hasWriteFd(); testResult.expectTrue(completePipe, "immediate-close test pipe is created"); if (!completePipe) { @@ -39,6 +43,25 @@ int main(int argc, char* argv[]) { core::SNodeC::free(); return testResult.processResult(); } + + std::vector scopeRecords; + source + ->log( + [&scopeRecords](logger::LogRecord record) { + scopeRecords.push_back(std::move(record)); + }, + logger::LogLevel::Trace) + .info("pipe scope probe"); + testResult.expectEqual(static_cast(1), scopeRecords.size(), "PipeSource exposes one captured semantic scope record"); + if (!scopeRecords.empty()) { + const logger::LogRecord& record = scopeRecords.front(); + testResult.expectTrue(record.origin == logger::LogOrigin::Framework && record.boundary == logger::LogBoundary::Connection, + "PipeSource uses the framework connection boundary"); + testResult.expectTrue(record.component == "core.pipe", "PipeSource uses the core.pipe component"); + testResult.expectTrue(record.instance && *record.instance == "immediate-close-pipe", + "PipeSource inherits the configured Pipe instance name"); + testResult.expectTrue(record.connection && !record.connection->empty(), "PipeSource inherits a logical Pipe connection ID"); + } const int readFd = pipe.getReadFd(); bool closed = false; int closureCount = 0; diff --git a/tests/component/core/ShutdownReceiverNotificationTest.cpp b/tests/component/core/ShutdownReceiverNotificationTest.cpp index e4a669ffbe..94b154a696 100644 --- a/tests/component/core/ShutdownReceiverNotificationTest.cpp +++ b/tests/component/core/ShutdownReceiverNotificationTest.cpp @@ -23,7 +23,14 @@ namespace { class ShutdownReceiver final : public core::eventreceiver::ReadEventReceiver { public: ShutdownReceiver(int readFd, int writeFd, int& callbackCount, core::ShutdownContext& receivedContext) - : core::eventreceiver::ReadEventReceiver("shutdown notification test", TIMEOUT::DISABLE) + : core::eventreceiver::ReadEventReceiver("shutdown notification test", + logger::LogScope{logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + "shutdown notification test read", + logger::LogRole::Unknown, + {}}, + TIMEOUT::DISABLE) , writeFd(writeFd) , callbackCount(callbackCount) , receivedContext(receivedContext) { diff --git a/tests/policy/log/ParameterlessSemanticLoggerPolicyTest.cpp b/tests/policy/log/ParameterlessSemanticLoggerPolicyTest.cpp index 9888964a57..87b7c24716 100644 --- a/tests/policy/log/ParameterlessSemanticLoggerPolicyTest.cpp +++ b/tests/policy/log/ParameterlessSemanticLoggerPolicyTest.cpp @@ -36,10 +36,10 @@ namespace { using SourceMap = std::map; constexpr std::size_t kBaselineParameterlessCallCount = 81; - constexpr std::size_t kTransferredParameterlessCallCount = 4; + constexpr std::size_t kTransferredParameterlessCallCount = 13; constexpr std::size_t kExpectedParameterlessCallCount = kBaselineParameterlessCallCount - kTransferredParameterlessCallCount; - static_assert(kExpectedParameterlessCallCount == 77); + static_assert(kExpectedParameterlessCallCount == 68); bool isIdentifierCharacter(char character) { const unsigned char value = static_cast(character); @@ -454,27 +454,9 @@ namespace { Entry{"src/iot/mqtt/server/broker/SubscriptionTree.cpp", "mqttBrokerLog", "SubscriptionTree::TopicLevel::log() const", "GLOBAL_COMPONENT_DIAGNOSTIC", "Subscription topic level belongs to the process-wide broker."}, - // MariaDB operations have protocol/domain identity, not SocketConnection identity. + // MariaDB library initialization is process-wide. Entry{"src/database/mariadb/MariaDBLibrary.cpp", "mariaDbLog", "mysql_library_init failed", "GLOBAL_COMPONENT_DIAGNOSTIC", "MariaDB library initialization is a process-wide component diagnostic."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "Descriptor not registered in SNode.C eventloop", - "DOMAIN_OR_PROTOCOL_SCOPE", "MariaDB connection name is the available database-domain identity."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "connect: success", "DOMAIN_OR_PROTOCOL_SCOPE", - "MariaDB connection has no SocketConnection semantic scope."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "database session established:", - "DOMAIN_OR_PROTOCOL_SCOPE", "Database session identity is carried by the MariaDB connection name."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "connect: error:", "DOMAIN_OR_PROTOCOL_SCOPE", - "MariaDB connection failure has no SocketConnection semantic scope."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "closing || core::SNodeC::state()", - "DOMAIN_OR_PROTOCOL_SCOPE", "Destructor request terminal belongs to the MariaDB command domain."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "database session ended:", - "DOMAIN_OR_PROTOCOL_SCOPE", "Database session identity is carried by the MariaDB connection name."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "database request started:", - "DOMAIN_OR_PROTOCOL_SCOPE", "Database request identity is the MariaDB command and connection name."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "currentCommandFailed ? \"failed\" : \"completed\"", - "DOMAIN_OR_PROTOCOL_SCOPE", "Database request terminal is owned by the active MariaDB command."}, - Entry{"src/database/mariadb/MariaDBConnection.cpp", "mariaDbLog", "Lost connection", "DOMAIN_OR_PROTOCOL_SCOPE", - "MariaDB has no SocketConnection logger and retains its database connection identity."}, }; } diff --git a/tests/unit/core/SocketWriterResourcePolicyTest.cpp b/tests/unit/core/SocketWriterResourcePolicyTest.cpp index 9dced9b55f..4ec860edee 100644 --- a/tests/unit/core/SocketWriterResourcePolicyTest.cpp +++ b/tests/unit/core/SocketWriterResourcePolicyTest.cpp @@ -12,6 +12,7 @@ #include "core/pipe/Source.h" #include "core/socket/stream/QueueResult.h" #include "core/socket/stream/SocketWriter.h" +#include "log/SemanticLogger.h" #include "net/config/ConfigConnection.h" #include "net/config/ConfigInstance.h" #include "tests/support/TestResult.h" @@ -85,11 +86,21 @@ namespace { int stops = 0; }; + logger::LogScope writerLogScope() { + return {logger::LogOrigin::Framework, + logger::LogBoundary::Connection, + "core.socket.stream", + "SocketWriterResourcePolicyTest", + logger::LogRole::Client, + "1"}; + } + class TestWriter final : public core::socket::stream::SocketWriter { public: TestWriter(std::size_t blockSize, std::size_t maximum, std::size_t high, std::size_t low) : SocketWriter( "SocketWriterResourcePolicyTest", + writerLogScope(), [this](int errnum) { lastError = errnum; }, @@ -102,13 +113,18 @@ namespace { } explicit TestWriter(std::size_t blockSize) - : SocketWriter("SocketWriterResourcePolicyTest", - [this](int errnum) { - lastError = errnum; - }, - {1, 0}, - blockSize, - {1, 0}) { + : SocketWriter( + "SocketWriterResourcePolicyTest", + writerLogScope(), + [this](int errnum) { + lastError = errnum; + }, + {1, 0}, + blockSize, + {1, 0}, + 0, + 0, + 0) { } bool open(int fd) { diff --git a/tests/unit/core/StreamFrameworkShutdownTest.cpp b/tests/unit/core/StreamFrameworkShutdownTest.cpp index b7397205af..cafa50d155 100644 --- a/tests/unit/core/StreamFrameworkShutdownTest.cpp +++ b/tests/unit/core/StreamFrameworkShutdownTest.cpp @@ -403,7 +403,14 @@ namespace { class CooperativePeer final : public core::eventreceiver::ReadEventReceiver { public: CooperativePeer(int fd, std::size_t expectedBytes, LifecycleState& state, const std::shared_ptr& physical) - : ReadEventReceiver("stream framework shutdown peer", utils::Timeval({0, 10000})) + : ReadEventReceiver("stream framework shutdown peer", + logger::LogScope{logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + "stream framework shutdown peer read", + logger::LogRole::Unknown, + {}}, + utils::Timeval({0, 10000})) , fd(fd) , expectedBytes(expectedBytes) , state(state) @@ -946,6 +953,43 @@ namespace { std::optional("41")); } + for (const std::string& message : {"PeerAddress (local): stream-framework-shutdown-address", + "PeerAddress (remote): stream-framework-shutdown-address", + "READ descriptor enabled", + "WRITE descriptor enabled", + "Write shutdown started"}) { + expectRecordIdentity(message, + "framework", + "connection", + "core.socket.stream", + std::optional("client"), + std::optional("41")); + } + + for (const CapturedRecord& record : records) { + if (record.component == "core.socket.stream" && record.connection == std::optional("41")) { + result.expectTrue(record.message.find("] stream-framework-shutdown") == std::string::npos, + "established connection message excludes legacy descriptor identity"); + result.expectTrue(record.instance && record.instance->find('[') == std::string::npos, + "established connection instance excludes descriptor identity"); + result.expectTrue(record.connection->find('[') == std::string::npos, + "established connection ID excludes descriptor identity"); + } + } + + const auto genericReceiver = std::find_if(records.begin(), records.end(), [](const CapturedRecord& record) { + return record.message == "READ descriptor enabled" && record.component == "core.eventreceiver"; + }); + result.expectTrue(genericReceiver != records.end(), "generic descriptor receiver record is available"); + if (genericReceiver != records.end()) { + result.expectTrue(genericReceiver->origin == "framework", "generic descriptor receiver retains framework origin"); + result.expectTrue(genericReceiver->boundary == "system", "generic descriptor receiver retains system boundary"); + result.expectTrue(genericReceiver->instance == std::optional("stream framework shutdown peer read"), + "generic descriptor receiver retains receiver instance"); + result.expectTrue(!genericReceiver->role.has_value(), "generic descriptor receiver has no connection role"); + result.expectTrue(!genericReceiver->connection.has_value(), "generic descriptor receiver has no connection ID"); + } + const auto disconnected = findRecord(records, "transport disconnected"); result.expectTrue(disconnected.has_value(), "framework shutdown emits the canonical transport disconnect exactly once"); if (disconnected) { diff --git a/tests/unit/core/TLSFrameworkShutdownTest.cpp b/tests/unit/core/TLSFrameworkShutdownTest.cpp index 43ddbf9b09..de85213530 100644 --- a/tests/unit/core/TLSFrameworkShutdownTest.cpp +++ b/tests/unit/core/TLSFrameworkShutdownTest.cpp @@ -291,7 +291,14 @@ namespace { class ReadSentinel final : public core::eventreceiver::ReadEventReceiver { public: ReadSentinel(int fd, const std::shared_ptr& state) - : ReadEventReceiver("TLS shutdown read traversal sentinel", utils::Timeval()) + : ReadEventReceiver("TLS shutdown read traversal sentinel", + logger::LogScope{logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + "TLS shutdown read traversal sentinel read", + logger::LogRole::Unknown, + {}}, + utils::Timeval()) , state(state) { ReadEventReceiver::enable(fd); } @@ -321,7 +328,14 @@ namespace { class WriteSentinel final : public core::eventreceiver::WriteEventReceiver { public: WriteSentinel(int fd, const std::shared_ptr& state) - : WriteEventReceiver("TLS shutdown write traversal sentinel", utils::Timeval()) + : WriteEventReceiver("TLS shutdown write traversal sentinel", + logger::LogScope{logger::LogOrigin::Framework, + logger::LogBoundary::System, + "core.eventreceiver", + "TLS shutdown write traversal sentinel write", + logger::LogRole::Unknown, + {}}, + utils::Timeval()) , state(state) { WriteEventReceiver::enable(fd); }