From 5ddde6a9a13b309a9c0e34472e4c65f632b8c23c Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 14:11:16 +0200 Subject: [PATCH 01/10] refactor: store a logger's name as a plain string Logger held an owned string, a string_view either aliasing it or pointing at a literal, and a flag saying which, so the move operations were written by hand and their failure mode was a string_view left aliasing a moved-from string. One string halves the object, 48 bytes to 24, and defaults the moves. It costs an allocation for the two static names past libstdc++'s small-buffer limit, both process-lifetime singletons. The tests that went with it covered only the machinery: which constructor is noexcept, and the char array without a trailing NUL that was the one case telling the array constructor from the literal one. --- src/reflector/logger.h | 57 +++------------------------- tests/logger_test.cpp | 86 ++++++------------------------------------ 2 files changed, 17 insertions(+), 126 deletions(-) diff --git a/src/reflector/logger.h b/src/reflector/logger.h index d59523c..ac64400 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -35,15 +35,6 @@ constexpr const char* Basename(const char* path) noexcept { return base; } -template -constexpr size_t StaticStringLength(const char (&s)[N]) noexcept { - if constexpr (N == 0) { - return 0; - } else { - return s[N - 1] == '\0' ? N - 1 : N; - } -} - template struct LogFmt { std::format_string fmt; @@ -58,42 +49,12 @@ struct LogFmt { class Logger : NoCopy { public: - explicit Logger(std::string_view name) : owned_name_{name}, name_{owned_name_}, owns_name_{true} {} - - template - explicit Logger(const char (&name)[N]) noexcept : name_{name, detail::StaticStringLength(name)} {} - - Logger(Logger&& other) noexcept - : owned_name_{std::move(other.owned_name_)} - , name_{other.owns_name_ ? std::string_view{owned_name_} : other.name_} - , owns_name_{other.owns_name_} { - other.ResetName(); - } - - Logger& operator=(Logger&& other) noexcept { - if (this == &other) { - return *this; - } + explicit Logger(std::string_view name) : name_{name} {} - owned_name_ = std::move(other.owned_name_); - owns_name_ = other.owns_name_; - name_ = owns_name_ ? std::string_view{owned_name_} : other.name_; - other.ResetName(); - return *this; - } + Logger(Logger&&) noexcept = default; + Logger& operator=(Logger&&) noexcept = default; - void SetName(std::string_view name) { - owned_name_ = name; - name_ = owned_name_; - owns_name_ = true; - } - - template - void SetName(const char (&name)[N]) noexcept { - owned_name_.clear(); - name_ = std::string_view{name, detail::StaticStringLength(name)}; - owns_name_ = false; - } + void SetName(std::string_view name) { name_ = name; } static void SetMinLevel(LogLevel level) noexcept { min_level_ = level; } [[nodiscard]] static LogLevel MinLevel() noexcept { return min_level_; } @@ -161,17 +122,9 @@ class Logger : NoCopy { // Plus the timestamp, level, logger name and source location wrapped around it. static constexpr size_t MAX_RECORD_SIZE = MAX_MESSAGE_SIZE + 512; - void ResetName() noexcept { - owned_name_.clear(); - name_ = {}; - owns_name_ = false; - } - inline static LogLevel min_level_ = LogLevel::Info; - std::string owned_name_; - std::string_view name_; - bool owns_name_ = false; + std::string name_; }; } // namespace reflector diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index 11e445b..afbba85 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -18,15 +18,6 @@ namespace { using namespace reflector; -constexpr char STATIC_ARRAY_NAME[] = "StaticArrayLogger"; - -static_assert(noexcept(Logger{"LiteralLogger"})); -static_assert(noexcept(Logger{STATIC_ARRAY_NAME})); -static_assert(!noexcept(Logger{std::string_view{"DynamicLogger"}})); -static_assert(noexcept(std::declval().SetName("LiteralLogger"))); -static_assert(noexcept(std::declval().SetName(STATIC_ARRAY_NAME))); -static_assert(!noexcept(std::declval().SetName(std::string_view{"DynamicLogger"}))); - } // namespace namespace reflector { @@ -55,88 +46,35 @@ TEST(LoggerTest, MinLevelSuppressesLowerSeverityMessages) { EXPECT_NE(output.find("visible error message"), std::string::npos) << output; } -TEST(LoggerTest, StaticLiteralNameAppearsInOutput) { - const ScopedMinLogLevel level{LogLevel::Info}; - Logger logger{"StaticLiteralLogger"}; - - const std::string output = CaptureStdout([&] { - logger.Info("message from static literal logger"); - }); - - EXPECT_NE(output.find("[StaticLiteralLogger]"), std::string::npos) << output; - EXPECT_NE(output.find("message from static literal logger"), std::string::npos) << output; -} - -TEST(LoggerTest, NonNullTerminatedArrayNameAppearsInOutput) { - // A char array without a trailing NUL: StaticStringLength takes its `: N` branch (a terminated - // array and any string literal take `N - 1`), so the whole extent is the name — the one case - // that distinguishes the array ctor from the literal ctor. - const ScopedMinLogLevel level{LogLevel::Info}; - constexpr char name[] = {'N', 'o', 'N', 'u', 'l'}; - Logger logger{name}; - - const std::string output = CaptureStdout([&] { - logger.Info("message from unterminated array logger"); - }); - - EXPECT_NE(output.find("[NoNul]"), std::string::npos) << output; -} - -TEST(LoggerTest, DynamicTemporaryNameAppearsInOutput) { - const ScopedMinLogLevel level{LogLevel::Info}; - Logger logger{std::string{"DynamicTemporaryLoggerName"}}; - - const std::string output = CaptureStdout([&] { - logger.Info("message from dynamic temporary logger"); - }); - - EXPECT_NE(output.find("[DynamicTemporaryLoggerName]"), std::string::npos) << output; - EXPECT_NE(output.find("message from dynamic temporary logger"), std::string::npos) << output; -} - -TEST(LoggerTest, SetNameWithStaticLiteralUpdatesOutput) { - const ScopedMinLogLevel level{LogLevel::Info}; - Logger logger{std::string{"InitialDynamicLoggerName"}}; - logger.SetName("RenamedStaticLiteralLogger"); - - const std::string output = CaptureStdout([&] { - logger.Info("message from renamed static literal logger"); - }); - - EXPECT_NE(output.find("[RenamedStaticLiteralLogger]"), std::string::npos) << output; - EXPECT_NE(output.find("message from renamed static literal logger"), std::string::npos) << output; -} - -TEST(LoggerTest, SetNameWithDynamicTemporaryUpdatesOutput) { +TEST(LoggerTest, NameAppearsInOutput) { const ScopedMinLogLevel level{LogLevel::Info}; - Logger logger{"InitialStaticLogger"}; - logger.SetName(std::string{"RenamedDynamicLoggerName"}); + Logger logger{"NamedLogger"}; const std::string output = CaptureStdout([&] { - logger.Info("message from renamed dynamic logger"); + logger.Info("message from a named logger"); }); - EXPECT_NE(output.find("[RenamedDynamicLoggerName]"), std::string::npos) << output; - EXPECT_NE(output.find("message from renamed dynamic logger"), std::string::npos) << output; + EXPECT_NE(output.find("[NamedLogger]"), std::string::npos) << output; + EXPECT_NE(output.find("message from a named logger"), std::string::npos) << output; } -TEST(LoggerTest, StaticNameSurvivesMoveConstructionAndAssignment) { +TEST(LoggerTest, NameSurvivesMoveConstructionAndAssignment) { const ScopedMinLogLevel level{LogLevel::Info}; - Logger constructed_from{STATIC_ARRAY_NAME}; + Logger constructed_from{"MoveConstructedLogger"}; Logger move_constructed{std::move(constructed_from)}; Logger move_assigned_target{"InitialLogger"}; Logger assigned_from{"MoveAssignedStaticLogger"}; move_assigned_target = std::move(assigned_from); const std::string output = CaptureStdout([&] { - move_constructed.Info("message from move constructed static logger"); - move_assigned_target.Info("message from move assigned static logger"); + move_constructed.Info("message from the move constructed logger"); + move_assigned_target.Info("message from the move assigned logger"); }); - EXPECT_NE(output.find(STATIC_ARRAY_NAME), std::string::npos) << output; + EXPECT_NE(output.find("[MoveConstructedLogger]"), std::string::npos) << output; EXPECT_NE(output.find("[MoveAssignedStaticLogger]"), std::string::npos) << output; - EXPECT_NE(output.find("message from move constructed static logger"), std::string::npos) << output; - EXPECT_NE(output.find("message from move assigned static logger"), std::string::npos) << output; + EXPECT_NE(output.find("message from the move constructed logger"), std::string::npos) << output; + EXPECT_NE(output.find("message from the move assigned logger"), std::string::npos) << output; } TEST(LoggerTest, DynamicNameSurvivesMoveConstructionAndAssignment) { From 7102a387c177c21ebcbbf3ee2278b91b7257c19a Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 14:28:51 +0200 Subject: [PATCH 02/10] feat!: rename the warning log level to warn log_level = "warning" is no longer accepted, and records that read WARNING now read WARN, so configs and any log tooling matching the old spelling need updating. "warn" is the conventional short form and puts the four levels on an even footing: debug, info, warn, error. --- README.md | 2 +- config.toml | 2 +- src/reflector/application.cpp | 8 ++++---- src/reflector/config/config.cpp | 4 ++-- src/reflector/default_address_monitor.cpp | 4 ++-- src/reflector/default_packet_dispatcher.cpp | 4 ++-- src/reflector/dial_proxy.cpp | 2 +- src/reflector/event_loop_dispatcher.cpp | 6 +++--- src/reflector/interface_address.cpp | 2 +- src/reflector/logger.h | 8 ++++---- src/reflector/raw_socket.cpp | 8 ++++---- src/reflector/ssdp_reflector.cpp | 2 +- src/reflector/tcp_socket.cpp | 2 +- tests/config_test.cpp | 16 ++++++++-------- tests/logger_test.cpp | 6 +++--- tests/util/udp_socket.cpp | 2 +- 16 files changed, 39 insertions(+), 39 deletions(-) diff --git a/README.md b/README.md index 5e42f14..07ffd22 100644 --- a/README.md +++ b/README.md @@ -202,7 +202,7 @@ On RouterOS, setting the container's environment variables is usually easier tha `config.toml` contains optional top-level settings plus at least one reflector entry. Entries are tables under `reflectors`, keyed by name (`[reflectors.]`) — the name is the label used in logs — each describing one `source_if` → `target_if` bridge that enables any combination of the protocols. The top-level settings are `log_level` and `debug_memory`: ```toml -log_level = "info" # optional; one of debug | info | warning | error (default: info) +log_level = "info" # optional; one of debug | info | warn | error (default: info) debug_memory = false # optional; periodically log RSS + heap arena stats for footprint debugging (default false) [reflectors.tv] diff --git a/config.toml b/config.toml index d2c0b9b..83f9190 100644 --- a/config.toml +++ b/config.toml @@ -1,4 +1,4 @@ -# log_level = "info" # debug | info | warning | error +# log_level = "info" # debug | info | warn | error # debug_memory = false # periodically log RSS + heap arena stats for footprint debugging # A single device: bridge its Wake-on-LAN, mDNS, and SSDP. The one mac is the device's NIC MAC — diff --git a/src/reflector/application.cpp b/src/reflector/application.cpp index e002d2c..c1f34d0 100644 --- a/src/reflector/application.cpp +++ b/src/reflector/application.cpp @@ -76,7 +76,7 @@ void Application::StartMonitor() { // Address-change refresh is best-effort: if the monitor can't start (it logs the cause), // carry on without it rather than failing the daemon. if (!address_monitor_->Start(CreateDelegate<&Application::OnInterfacesChanged>(this))) { - GetLogger().Warning("Address monitor unavailable; source addresses will not refresh on interface changes"); + GetLogger().Warn("Address monitor unavailable; source addresses will not refresh on interface changes"); } } @@ -246,7 +246,7 @@ void Application::NotifyReflectors() noexcept { int Application::PrepareSignalWakeup() { int fds[2]; if (::pipe(fds) != 0) { - GetLogger().Warning("Cannot create signal wakeup pipe: {}; shutdown bounded by the poll interval", + GetLogger().Warn("Cannot create signal wakeup pipe: {}; shutdown bounded by the poll interval", Error::FromErrno()); return -1; } @@ -258,7 +258,7 @@ int Application::PrepareSignalWakeup() { // the daemon never execs (like every other fd here), so there is nothing to leak across an exec. for (const int fd : {wakeup_read_.Get(), wakeup_write_.Get()}) { if (!SetNonBlocking(fd)) { - GetLogger().Warning("Cannot configure signal wakeup pipe: {}; shutdown bounded by the poll interval", + GetLogger().Warn("Cannot configure signal wakeup pipe: {}; shutdown bounded by the poll interval", Error::FromErrno()); wakeup_read_.Reset(); wakeup_write_.Reset(); @@ -268,7 +268,7 @@ int Application::PrepareSignalWakeup() { wakeup_reg_ = dispatcher_->Register(wakeup_read_.Get(), CreateDelegate<&Application::OnWakeup>(this)); if (!wakeup_reg_.IsValid()) { - GetLogger().Warning("Cannot register the signal wakeup pipe; shutdown bounded by the poll interval"); + GetLogger().Warn("Cannot register the signal wakeup pipe; shutdown bounded by the poll interval"); wakeup_read_.Reset(); wakeup_write_.Reset(); return -1; diff --git a/src/reflector/config/config.cpp b/src/reflector/config/config.cpp index 696a55a..5c5e5c5 100644 --- a/src/reflector/config/config.cpp +++ b/src/reflector/config/config.cpp @@ -31,9 +31,9 @@ std::expected LogLevelFromString(std::string_view s) { const auto lower = AsciiToLower(s); if (lower == "debug") return LogLevel::Debug; if (lower == "info") return LogLevel::Info; - if (lower == "warning") return LogLevel::Warning; + if (lower == "warn") return LogLevel::Warn; if (lower == "error") return LogLevel::Error; - return std::unexpected(Error{"log_level must be one of: debug, info, warning, error; got \"{}\"", s}); + return std::unexpected(Error{"log_level must be one of: debug, info, warn, error; got \"{}\"", s}); } std::expected AddressFamilyFromString(std::string_view section, std::string_view s) { diff --git a/src/reflector/default_address_monitor.cpp b/src/reflector/default_address_monitor.cpp index 57e9221..c1a7b92 100644 --- a/src/reflector/default_address_monitor.cpp +++ b/src/reflector/default_address_monitor.cpp @@ -126,7 +126,7 @@ bool DefaultAddressMonitor::Open() noexcept { // Kernel-clamped, and the default still works, so a failure only warns — it doesn't fail Open. if (setsockopt(fd_.Get(), SOL_SOCKET, SO_RCVBUF, &ROUTE_RECEIVE_BUFFER_BYTES, sizeof(ROUTE_RECEIVE_BUFFER_BYTES)) != 0) { - GetLogger().Warning("Cannot enlarge the route socket receive buffer: {}", Error::FromErrno()); + GetLogger().Warn("Cannot enlarge the route socket receive buffer: {}", Error::FromErrno()); } #if defined(__FreeBSD__) // Without SO_RERROR (FreeBSD 13+) a receive-buffer overflow is dropped silently, so the ENOBUFS @@ -213,7 +213,7 @@ void DefaultAddressMonitor::OnReadable(int /*fd*/) noexcept { } if (overflowed) { - GetLogger().Warning("Address notifications overflowed; refreshing all interfaces"); + GetLogger().Warn("Address notifications overflowed; refreshing all interfaces"); } else if (changed.overflowed) { GetLogger().Debug("More than {} interfaces changed in one drain; refreshing all", MAX_CHANGED_INTERFACES); diff --git a/src/reflector/default_packet_dispatcher.cpp b/src/reflector/default_packet_dispatcher.cpp index 3f69fb4..84f99b0 100644 --- a/src/reflector/default_packet_dispatcher.cpp +++ b/src/reflector/default_packet_dispatcher.cpp @@ -62,7 +62,7 @@ bool DefaultPacketDispatcher::Unregister(RegistrationId id) noexcept { return r.id == id && r.enabled; }); if (it == registrations_.end()) { - GetLogger().Warning("Cannot unregister packet callback {}: not found", std::to_underlying(id)); + GetLogger().Warn("Cannot unregister packet callback {}: not found", std::to_underlying(id)); return false; } GetLogger().Debug("Unregistered packet callback {}", std::to_underlying(id)); @@ -83,7 +83,7 @@ bool DefaultPacketDispatcher::Unregister(RegistrationId id) noexcept { void DefaultPacketDispatcher::OnReadable(int fd) noexcept { const auto it = capture_sources_.find(fd); if (it == capture_sources_.end()) { - GetLogger().Warning("Readable callback for unknown capture fd {}", fd); + GetLogger().Warn("Readable callback for unknown capture fd {}", fd); return; } // Reported after the drain, not from inside it: the sweep may have dropped this capture diff --git a/src/reflector/dial_proxy.cpp b/src/reflector/dial_proxy.cpp index 0d84595..f6b8b05 100644 --- a/src/reflector/dial_proxy.cpp +++ b/src/reflector/dial_proxy.cpp @@ -326,7 +326,7 @@ void DialProxy::OnAccept(int listener_fd) noexcept { } if (connections_.size() >= MAX_CONNECTIONS) { - logger_.Warning("Dropping accept for {}: connection cap reached", ep->device); + logger_.Warn("Dropping accept for {}: connection cap reached", ep->device); return; // the accepted client TcpSocket drops here -> RAII close } diff --git a/src/reflector/event_loop_dispatcher.cpp b/src/reflector/event_loop_dispatcher.cpp index d9c8842..b45887b 100644 --- a/src/reflector/event_loop_dispatcher.cpp +++ b/src/reflector/event_loop_dispatcher.cpp @@ -97,7 +97,7 @@ Dispatcher::Registration EventLoopDispatcher::Register(int fd, FdCallbacks callb bool EventLoopDispatcher::SetWriteInterest(int fd, bool enabled) noexcept { const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warning("Cannot set write interest for fd {}: not registered", fd); + GetLogger().Warn("Cannot set write interest for fd {}: not registered", fd); return false; } if (it->second.write_armed == enabled) { @@ -113,7 +113,7 @@ bool EventLoopDispatcher::SetWriteInterest(int fd, bool enabled) noexcept { bool EventLoopDispatcher::Unregister(int fd) noexcept { const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warning("Cannot unregister fd callback for fd {}: not found", fd); + GetLogger().Warn("Cannot unregister fd callback for fd {}: not found", fd); return false; } @@ -189,7 +189,7 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warning("Dispatcher woke for unwatched fd {}", fd); + GetLogger().Warn("Dispatcher woke for unwatched fd {}", fd); return false; } diff --git a/src/reflector/interface_address.cpp b/src/reflector/interface_address.cpp index af00ba8..b4d1c73 100644 --- a/src/reflector/interface_address.cpp +++ b/src/reflector/interface_address.cpp @@ -271,7 +271,7 @@ bool IsUsableIpv6(int inet6_fd, const char* interface, const sockaddr_in6& sin6) std::strncpy(request.ifr_name, interface, sizeof(request.ifr_name) - 1); request.ifr_ifru.ifru_addr = sin6; if (ioctl(inet6_fd, SIOCGIFAFLAG_IN6, &request) != 0) { - GetLogger().Warning("Cannot query IPv6 address flags on interface \"{}\": {}", interface, Error::FromErrno()); + GetLogger().Warn("Cannot query IPv6 address flags on interface \"{}\": {}", interface, Error::FromErrno()); return false; } return detail::Ipv6SourceFlagsUsable(request.ifr_ifru.ifru_flags6); diff --git a/src/reflector/logger.h b/src/reflector/logger.h index ac64400..6cb5de9 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -19,7 +19,7 @@ namespace reflector { enum class LogLevel : uint8_t { Debug, Info, - Warning, + Warn, Error, }; @@ -108,8 +108,8 @@ class Logger : NoCopy { } template - void Warning(detail::LogFmt...> fmt, Args&& ...args) noexcept { - Log(LogLevel::Warning, std::move(fmt), std::forward(args)...); + void Warn(detail::LogFmt...> fmt, Args&& ...args) noexcept { + Log(LogLevel::Warn, std::move(fmt), std::forward(args)...); } template @@ -148,7 +148,7 @@ struct std::formatter using enum reflector::LogLevel; case Debug: return std::format_to(ctx.out(), "DEBUG"); case Info: return std::format_to(ctx.out(), "INFO"); - case Warning: return std::format_to(ctx.out(), "WARNING"); + case Warn: return std::format_to(ctx.out(), "WARN"); case Error: return std::format_to(ctx.out(), "ERROR"); } diff --git a/src/reflector/raw_socket.cpp b/src/reflector/raw_socket.cpp index 0340047..639a00c 100644 --- a/src/reflector/raw_socket.cpp +++ b/src/reflector/raw_socket.cpp @@ -636,7 +636,7 @@ std::expected RawSocket::Receive() noexcept { return std::unexpected(ReceiveError::Failed); } if (static_cast(bytes) > receive_buffer_.size()) { - logger_.Warning("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + logger_.Warn("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", bytes, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -685,7 +685,7 @@ std::expected RawSocket::Receive() noexcept { // BPF captured fewer bytes than the frame's real length, so it didn't fit the buffer; drop it // rather than parse a truncated frame. (Offset already advanced to the next record above.) if (header.bh_datalen > header.bh_caplen) { - logger_.Warning("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + logger_.Warn("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", header.bh_datalen, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -694,7 +694,7 @@ std::expected RawSocket::Receive() noexcept { // batch buffer admits frames the MAX_FRAME_SIZE-sized Linux scratch would have refused, so // enforce the same ceiling here at capture. if (header.bh_caplen > MAX_FRAME_SIZE) { - logger_.Warning("Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", + logger_.Warn("Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", header.bh_caplen, MAX_FRAME_SIZE); return std::unexpected(ReceiveError::Dropped); } @@ -838,7 +838,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no const auto dest_port = ReadU16Be(l4.subspan<2, 2>()); const auto udp_length = ReadU16Be(l4.subspan<4, 2>()); if (udp_length < UDP_HEADER_SIZE || udp_length > l4.size()) { - logger_.Warning("UDP length {} invalid (header min {}, l4 size {})", + logger_.Warn("UDP length {} invalid (header min {}, l4 size {})", udp_length, UDP_HEADER_SIZE, l4.size()); return std::nullopt; } diff --git a/src/reflector/ssdp_reflector.cpp b/src/reflector/ssdp_reflector.cpp index 412a3e8..d73e373 100644 --- a/src/reflector/ssdp_reflector.cpp +++ b/src/reflector/ssdp_reflector.cpp @@ -210,7 +210,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { std::optional SsdpReflector::MakeSession(const Packet& packet, std::chrono::steady_clock::time_point expiry) { if (sessions_.size() >= MAX_SESSIONS) { - logger_.Warning("Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", + logger_.Warn("Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", packet.header.source, sessions_.size()); return std::nullopt; } diff --git a/src/reflector/tcp_socket.cpp b/src/reflector/tcp_socket.cpp index 5db8304..f623db4 100644 --- a/src/reflector/tcp_socket.cpp +++ b/src/reflector/tcp_socket.cpp @@ -414,7 +414,7 @@ SendStatus TcpSocket::Send(std::span> chunks) n // buffers and flushes on later writable edges — but a caller only ever passes a header + body (2 chunks), // so a scatter this large is unexpected: warn and carry on. if (chunks.size() > MAX_SEND_CHUNKS) { - logger_.Warning("Scatter-send of {} chunks exceeds the {}-chunk sendmsg cap; the overflow " + logger_.Warn("Scatter-send of {} chunks exceeds the {}-chunk sendmsg cap; the overflow " "buffers and flushes on later writable edges", chunks.size(), MAX_SEND_CHUNKS); } // Write through only when nothing is already queued; otherwise the chunks follow the backlog in order diff --git a/tests/config_test.cpp b/tests/config_test.cpp index 46d057a..56add9a 100644 --- a/tests/config_test.cpp +++ b/tests/config_test.cpp @@ -357,10 +357,10 @@ TEST(ConfigTest, ParsesLogLevelInfo) { EXPECT_EQ(config->MinLogLevel(), LogLevel::Info); } -TEST(ConfigTest, ParsesLogLevelWarning) { - const auto config = Config::FromString(TomlWithLogLevel("warning")); +TEST(ConfigTest, ParsesLogLevelWarn) { + const auto config = Config::FromString(TomlWithLogLevel("warn")); ASSERT_TRUE(config.has_value()) << config.error().Message(); - EXPECT_EQ(config->MinLogLevel(), LogLevel::Warning); + EXPECT_EQ(config->MinLogLevel(), LogLevel::Warn); } TEST(ConfigTest, ParsesLogLevelError) { @@ -1394,7 +1394,7 @@ TEST(ConfigTest, SsdpFormatterPrintsMacAndDialFalse) { TEST(ConfigTest, ConfigFormatterRendersAllSections) { const auto config = Config::FromString(R"( -log_level = "warning" +log_level = "warn" [reflectors.tv] source_if = "lan" target_if = "iot" @@ -1674,13 +1674,13 @@ TEST(ConfigTest, EnvSetsLogLevel) { TEST(ConfigTest, EnvLogLevelIsCaseInsensitive) { const auto config = Config::Load(std::nullopt, Env({ - {"REFLECTOR_LOG_LEVEL", "WARNING"}, + {"REFLECTOR_LOG_LEVEL", "WARN"}, {"REFLECTOR_1_SOURCE_IF", "eth0"}, {"REFLECTOR_1_TARGET_IF", "eth1"}, {"REFLECTOR_1_WOL", "true"}, })); ASSERT_TRUE(config.has_value()) << config.error().Message(); - EXPECT_EQ(config->MinLogLevel(), LogLevel::Warning); + EXPECT_EQ(config->MinLogLevel(), LogLevel::Warn); } TEST(ConfigTest, EnvRejectsInvalidLogLevel) { @@ -1857,14 +1857,14 @@ wol = true TEST(ConfigTest, FileLogLevelKeptWhenEnvUnset) { const auto config = Config::Load(R"( -log_level = "warning" +log_level = "warn" [reflectors.tv] source_if = "eth0" target_if = "eth1" wol = true )", std::span{}); ASSERT_TRUE(config.has_value()) << config.error().Message(); - EXPECT_EQ(config->MinLogLevel(), LogLevel::Warning); + EXPECT_EQ(config->MinLogLevel(), LogLevel::Warn); } TEST(ConfigTest, EnvLogLevelSetsWhenFileOmitsIt) { diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index afbba85..adc7ed6 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -30,13 +30,13 @@ TEST(LoggerTest, SetMinLevelUpdatesMinLevel) { } TEST(LoggerTest, MinLevelSuppressesLowerSeverityMessages) { - const ScopedMinLogLevel level{LogLevel::Warning}; + const ScopedMinLogLevel level{LogLevel::Warn}; Logger logger{"LoggerTest"}; const std::string output = CaptureStdout([&] { logger.Debug("hidden debug message"); logger.Info("hidden info message"); - logger.Warning("visible warning message"); + logger.Warn("visible warning message"); logger.Error("visible error message"); }); @@ -99,7 +99,7 @@ TEST(LoggerTest, DynamicNameSurvivesMoveConstructionAndAssignment) { TEST(LoggerTest, FormatsLogLevelNames) { EXPECT_EQ(std::format("{}", LogLevel::Debug), "DEBUG"); EXPECT_EQ(std::format("{}", LogLevel::Info), "INFO"); - EXPECT_EQ(std::format("{}", LogLevel::Warning), "WARNING"); + EXPECT_EQ(std::format("{}", LogLevel::Warn), "WARN"); EXPECT_EQ(std::format("{}", LogLevel::Error), "ERROR"); } diff --git a/tests/util/udp_socket.cpp b/tests/util/udp_socket.cpp index b10ba7e..3839294 100644 --- a/tests/util/udp_socket.cpp +++ b/tests/util/udp_socket.cpp @@ -17,7 +17,7 @@ UdpSocket::UdpSocket(IpAddress::Family family) : family_{family} { fd_.Reset(socket(family == IpAddress::Family::V6 ? AF_INET6 : AF_INET, SOCK_DGRAM, IPPROTO_UDP)); if (!fd_) { if (errno == EAFNOSUPPORT || errno == EPROTONOSUPPORT) { - logger_.Warning("Cannot create socket: address family not supported: {}", Error::FromErrno()); + logger_.Warn("Cannot create socket: address family not supported: {}", Error::FromErrno()); } else { logger_.Error("Cannot create socket: {}", Error::FromErrno()); } From 443448919bfb21a5e7caa25609ddbe5369a39ee0 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 15:20:57 +0200 Subject: [PATCH 03/10] refactor: log through macros Rate limiting needs per-call-site state, and a function API cannot get it: the call site's identity reaches a function only as a value, never as something that can name a distinct object. A macro expands at the call site, so a static there belongs to that statement alone. Converting everything now rather than mixing two spellings later. The macros take the logger explicitly, so the per-object loggers carrying "RawSocket:eth0" and "DialProxy:tv:src->dst" are unchanged. The level gate lives at the call site, so a filtered record no longer evaluates its arguments: Interface::Refresh's Debug line was building three address strings on every refresh at the default Info level, and raw_socket built an Error::FromErrno for three suppressed lines. Emit replaces the four per-level methods, which would otherwise be public and ungated. --- src/main.cpp | 10 +- src/reflector/application.cpp | 16 +-- src/reflector/default_address_monitor.cpp | 26 ++--- src/reflector/default_packet_dispatcher.cpp | 14 +-- src/reflector/dial_proxy.cpp | 28 ++--- src/reflector/event_loop_dispatcher.cpp | 74 ++++++------- src/reflector/family_capability.cpp | 6 +- src/reflector/frame_builder.cpp | 4 +- src/reflector/http_message.cpp | 20 ++-- src/reflector/interface.cpp | 12 +-- src/reflector/interface_address.cpp | 18 ++-- src/reflector/ip_address.cpp | 6 +- src/reflector/logger.h | 41 +++----- src/reflector/mdns_reflector.cpp | 22 ++-- src/reflector/memory_report.cpp | 10 +- src/reflector/port_reservation.cpp | 8 +- src/reflector/raw_socket.cpp | 110 ++++++++++---------- src/reflector/ssdp_message.cpp | 2 +- src/reflector/ssdp_reflector.cpp | 52 ++++----- src/reflector/tcp_socket.cpp | 56 +++++----- src/reflector/wol_reflector.cpp | 24 ++--- tests/logger_test.cpp | 44 +++++--- tests/util/udp_socket.cpp | 72 ++++++------- 23 files changed, 342 insertions(+), 333 deletions(-) diff --git a/src/main.cpp b/src/main.cpp index 6c694b6..d93fe47 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -92,7 +92,7 @@ int Run(int argc, char* argv[]) { reflector::Logger logger("main"); if (argc > 2) { - logger.Error("Usage: {} [config.toml]", argv[0]); + NFL_LOG_ERROR(logger, "Usage: {} [config.toml]", argv[0]); return 2; } @@ -102,7 +102,7 @@ int Run(int argc, char* argv[]) { if (argc == 2) { auto contents = reflector::Config::ReadFileToString(argv[1]); if (!contents) { - logger.Error("Cannot read configuration file: {}", contents.error()); + NFL_LOG_ERROR(logger, "Cannot read configuration file: {}", contents.error()); return 1; } file_contents = *std::move(contents); @@ -113,14 +113,14 @@ int Run(int argc, char* argv[]) { file_contents ? std::optional{*file_contents} : std::nullopt; auto config = reflector::Config::Load(toml_text, env_vars); if (!config) { - logger.Error("Invalid configuration: {}", config.error()); + NFL_LOG_ERROR(logger, "Invalid configuration: {}", config.error()); return 1; } - logger.Info("Setting minimum log level to {}", config->MinLogLevel()); + NFL_LOG_INFO(logger, "Setting minimum log level to {}", config->MinLogLevel()); reflector::Logger::SetMinLevel(config->MinLogLevel()); - logger.Debug("Config: {}", *config); + NFL_LOG_DEBUG(logger, "Config: {}", *config); reflector::Application app; if (!app.Configure(*config)) { diff --git a/src/reflector/application.cpp b/src/reflector/application.cpp index c1f34d0..e62c804 100644 --- a/src/reflector/application.cpp +++ b/src/reflector/application.cpp @@ -76,7 +76,7 @@ void Application::StartMonitor() { // Address-change refresh is best-effort: if the monitor can't start (it logs the cause), // carry on without it rather than failing the daemon. if (!address_monitor_->Start(CreateDelegate<&Application::OnInterfacesChanged>(this))) { - GetLogger().Warn("Address monitor unavailable; source addresses will not refresh on interface changes"); + NFL_LOG_WARN(GetLogger(), "Address monitor unavailable; source addresses will not refresh on interface changes"); } } @@ -111,20 +111,20 @@ bool Application::ConfigureReflectors(const std::vector& configs, st for (const auto& config : configs) { auto* source_socket = GetOrCreateSocket(config.source_if); if (source_socket == nullptr) { - GetLogger().Error("Cannot configure {} reflector \"{}\": socket on interface \"{}\" is invalid", + NFL_LOG_ERROR(GetLogger(), "Cannot configure {} reflector \"{}\": socket on interface \"{}\" is invalid", protocol, config.name, config.source_if); return false; } auto* target_socket = GetOrCreateSocket(config.target_if); if (target_socket == nullptr) { - GetLogger().Error("Cannot configure {} reflector \"{}\": socket on interface \"{}\" is invalid", + NFL_LOG_ERROR(GetLogger(), "Cannot configure {} reflector \"{}\": socket on interface \"{}\" is invalid", protocol, config.name, config.target_if); return false; } auto reflector = std::make_unique(packet_dispatcher_, *source_socket, *target_socket, config); if (!reflector->IsValid()) { - GetLogger().Error("Cannot configure {} reflector \"{}\": setup failed", protocol, config.name); + NFL_LOG_ERROR(GetLogger(), "Cannot configure {} reflector \"{}\": setup failed", protocol, config.name); return false; } reflectors_.push_back(std::move(reflector)); @@ -139,7 +139,7 @@ bool Application::Configure(const Config& config) { reconcile_timer_.Start( RECONCILE_BACKSTOP_INTERVAL, CreateDelegate<&Application::OnReconcileTick>(this)); if (config.DebugMemory()) { - GetLogger().Info("Memory diagnostics enabled; reporting RSS/heap every {}s", + NFL_LOG_INFO(GetLogger(), "Memory diagnostics enabled; reporting RSS/heap every {}s", MEMORY_REPORT_INTERVAL.count()); LogMemoryReport(); // a baseline at startup, then every interval via the timer memory_timer_.emplace(*dispatcher_); @@ -246,7 +246,7 @@ void Application::NotifyReflectors() noexcept { int Application::PrepareSignalWakeup() { int fds[2]; if (::pipe(fds) != 0) { - GetLogger().Warn("Cannot create signal wakeup pipe: {}; shutdown bounded by the poll interval", + NFL_LOG_WARN(GetLogger(), "Cannot create signal wakeup pipe: {}; shutdown bounded by the poll interval", Error::FromErrno()); return -1; } @@ -258,7 +258,7 @@ int Application::PrepareSignalWakeup() { // the daemon never execs (like every other fd here), so there is nothing to leak across an exec. for (const int fd : {wakeup_read_.Get(), wakeup_write_.Get()}) { if (!SetNonBlocking(fd)) { - GetLogger().Warn("Cannot configure signal wakeup pipe: {}; shutdown bounded by the poll interval", + NFL_LOG_WARN(GetLogger(), "Cannot configure signal wakeup pipe: {}; shutdown bounded by the poll interval", Error::FromErrno()); wakeup_read_.Reset(); wakeup_write_.Reset(); @@ -268,7 +268,7 @@ int Application::PrepareSignalWakeup() { wakeup_reg_ = dispatcher_->Register(wakeup_read_.Get(), CreateDelegate<&Application::OnWakeup>(this)); if (!wakeup_reg_.IsValid()) { - GetLogger().Warn("Cannot register the signal wakeup pipe; shutdown bounded by the poll interval"); + NFL_LOG_WARN(GetLogger(), "Cannot register the signal wakeup pipe; shutdown bounded by the poll interval"); wakeup_read_.Reset(); wakeup_write_.Reset(); return -1; diff --git a/src/reflector/default_address_monitor.cpp b/src/reflector/default_address_monitor.cpp index c1a7b92..69dc08b 100644 --- a/src/reflector/default_address_monitor.cpp +++ b/src/reflector/default_address_monitor.cpp @@ -83,7 +83,7 @@ DefaultAddressMonitor DefaultAddressMonitor::ForTesting(Dispatcher& dispatcher, bool DefaultAddressMonitor::Start(const OnInterfacesChanged& on_change) noexcept { if (!on_change.IsValid()) { - GetLogger().Error("Cannot start address monitor: the change callback is not bound"); + NFL_LOG_ERROR(GetLogger(), "Cannot start address monitor: the change callback is not bound"); Close(); return false; } @@ -101,7 +101,7 @@ bool DefaultAddressMonitor::Open() noexcept { #if defined(__linux__) fd_.Reset(socket(AF_NETLINK, SOCK_RAW | SOCK_NONBLOCK, NETLINK_ROUTE)); if (!fd_) { - GetLogger().Error("Cannot open netlink socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot open netlink socket: {}", Error::FromErrno()); return false; } @@ -109,24 +109,24 @@ bool DefaultAddressMonitor::Open() noexcept { address.nl_family = AF_NETLINK; address.nl_groups = RTMGRP_IPV4_IFADDR | RTMGRP_IPV6_IFADDR | RTMGRP_LINK; if (bind(fd_.Get(), reinterpret_cast(&address), sizeof(address)) != 0) { - GetLogger().Error("Cannot subscribe to netlink notification groups: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot subscribe to netlink notification groups: {}", Error::FromErrno()); return false; } #else fd_.Reset(socket(PF_ROUTE, SOCK_RAW, 0)); if (!fd_) { - GetLogger().Error("Cannot open route socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot open route socket: {}", Error::FromErrno()); return false; } if (!SetNonBlocking(fd_.Get())) { - GetLogger().Error("Cannot set route socket non-blocking: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set route socket non-blocking: {}", Error::FromErrno()); return false; } // Best-effort: a bigger receive queue so a routing-message burst is less likely to overflow it. // Kernel-clamped, and the default still works, so a failure only warns — it doesn't fail Open. if (setsockopt(fd_.Get(), SOL_SOCKET, SO_RCVBUF, &ROUTE_RECEIVE_BUFFER_BYTES, sizeof(ROUTE_RECEIVE_BUFFER_BYTES)) != 0) { - GetLogger().Warn("Cannot enlarge the route socket receive buffer: {}", Error::FromErrno()); + NFL_LOG_WARN(GetLogger(), "Cannot enlarge the route socket receive buffer: {}", Error::FromErrno()); } #if defined(__FreeBSD__) // Without SO_RERROR (FreeBSD 13+) a receive-buffer overflow is dropped silently, so the ENOBUFS @@ -134,7 +134,7 @@ bool DefaultAddressMonitor::Open() noexcept { // Enabling it surfaces the overflow as ENOBUFS on the next recv. macOS has no equivalent. const int rerror = 1; if (setsockopt(fd_.Get(), SOL_SOCKET, SO_RERROR, &rerror, sizeof(rerror)) != 0) { - GetLogger().Error("Cannot enable SO_RERROR on the route socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot enable SO_RERROR on the route socket: {}", Error::FromErrno()); return false; } #endif @@ -146,10 +146,10 @@ bool DefaultAddressMonitor::Open() noexcept { bool DefaultAddressMonitor::Watch() noexcept { registration_ = dispatcher_->Register(fd_.Get(), CreateDelegate<&DefaultAddressMonitor::OnReadable>(this)); if (!registration_.IsValid()) { - GetLogger().Error("Cannot register the address-notification socket with the dispatcher"); + NFL_LOG_ERROR(GetLogger(), "Cannot register the address-notification socket with the dispatcher"); return false; } - GetLogger().Debug("Watching for interface address changes on fd {}", fd_.Get()); + NFL_LOG_DEBUG(GetLogger(), "Watching for interface address changes on fd {}", fd_.Get()); return true; } @@ -192,7 +192,7 @@ void DefaultAddressMonitor::OnReadable(int /*fd*/) noexcept { overflowed = true; continue; } - GetLogger().Error("Cannot read address notifications: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot read address notifications: {}", Error::FromErrno()); break; } if (received == 0) { @@ -201,7 +201,7 @@ void DefaultAddressMonitor::OnReadable(int /*fd*/) noexcept { // A local process can unicast a netlink datagram to this socket (user-to-user needs no // privilege), spoofing an address change; drop anything whose source isn't the kernel. if (verify_sender_ && !detail::NetlinkSenderIsKernel(src, addrlen)) { - GetLogger().Debug("Dropping an address notification from a non-kernel sender"); + NFL_LOG_DEBUG(GetLogger(), "Dropping an address notification from a non-kernel sender"); continue; } // Once overflowed we'll emit a single refresh-all, so keep draining the socket but stop @@ -213,9 +213,9 @@ void DefaultAddressMonitor::OnReadable(int /*fd*/) noexcept { } if (overflowed) { - GetLogger().Warn("Address notifications overflowed; refreshing all interfaces"); + NFL_LOG_WARN(GetLogger(), "Address notifications overflowed; refreshing all interfaces"); } else if (changed.overflowed) { - GetLogger().Debug("More than {} interfaces changed in one drain; refreshing all", + NFL_LOG_DEBUG(GetLogger(), "More than {} interfaces changed in one drain; refreshing all", MAX_CHANGED_INTERFACES); } else if (changed.count == 0) { return; // the drain carried nothing we track, so there is nothing to tell anyone diff --git a/src/reflector/default_packet_dispatcher.cpp b/src/reflector/default_packet_dispatcher.cpp index 84f99b0..b866cd1 100644 --- a/src/reflector/default_packet_dispatcher.cpp +++ b/src/reflector/default_packet_dispatcher.cpp @@ -25,14 +25,14 @@ DefaultPacketDispatcher::DefaultPacketDispatcher(Dispatcher& dispatcher) DefaultPacketDispatcher::~DefaultPacketDispatcher() noexcept { if (!registrations_.empty()) { - GetLogger().Error("Destroying packet dispatcher with {} registration(s) still active", registrations_.size()); + NFL_LOG_ERROR(GetLogger(), "Destroying packet dispatcher with {} registration(s) still active", registrations_.size()); } } PacketDispatcher::Registration DefaultPacketDispatcher::Register( LinkSocket& socket, const PacketFilter& filter, const PacketCallback& callback) { if (!socket.IsValid()) { - GetLogger().Error("Cannot register packet callback: capture socket is invalid"); + NFL_LOG_ERROR(GetLogger(), "Cannot register packet callback: capture socket is invalid"); return {}; } @@ -42,7 +42,7 @@ PacketDispatcher::Registration DefaultPacketDispatcher::Register( // First subscriber for this socket: start watching its fd through the Dispatcher. auto dispatcher_reg = dispatcher_->Register(fd, CreateDelegate<&DefaultPacketDispatcher::OnReadable>(this)); if (!dispatcher_reg.IsValid()) { - GetLogger().Error("Cannot register packet callback: dispatcher registration failed for fd {}", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot register packet callback: dispatcher registration failed for fd {}", fd); return {}; } source = capture_sources_.emplace( @@ -53,7 +53,7 @@ PacketDispatcher::Registration DefaultPacketDispatcher::Register( // capture source's count. const auto id = static_cast(next_registration_id_++); registrations_.emplace_back(id, &source->second, callback, filter); - GetLogger().Debug("Registered packet callback {} for fd {}", std::to_underlying(id), fd); + NFL_LOG_DEBUG(GetLogger(), "Registered packet callback {} for fd {}", std::to_underlying(id), fd); return MakeRegistration(id); } @@ -62,10 +62,10 @@ bool DefaultPacketDispatcher::Unregister(RegistrationId id) noexcept { return r.id == id && r.enabled; }); if (it == registrations_.end()) { - GetLogger().Warn("Cannot unregister packet callback {}: not found", std::to_underlying(id)); + NFL_LOG_WARN(GetLogger(), "Cannot unregister packet callback {}: not found", std::to_underlying(id)); return false; } - GetLogger().Debug("Unregistered packet callback {}", std::to_underlying(id)); + NFL_LOG_DEBUG(GetLogger(), "Unregistered packet callback {}", std::to_underlying(id)); if (dispatching_) { it->enabled = false; // DrainReadableFd is walking; defer the erase + teardown to its sweep return true; @@ -83,7 +83,7 @@ bool DefaultPacketDispatcher::Unregister(RegistrationId id) noexcept { void DefaultPacketDispatcher::OnReadable(int fd) noexcept { const auto it = capture_sources_.find(fd); if (it == capture_sources_.end()) { - GetLogger().Warn("Readable callback for unknown capture fd {}", fd); + NFL_LOG_WARN(GetLogger(), "Readable callback for unknown capture fd {}", fd); return; } // Reported after the drain, not from inside it: the sweep may have dropped this capture diff --git a/src/reflector/dial_proxy.cpp b/src/reflector/dial_proxy.cpp index f6b8b05..ef8b3fb 100644 --- a/src/reflector/dial_proxy.cpp +++ b/src/reflector/dial_proxy.cpp @@ -48,7 +48,7 @@ void DialProxy::OnInterfaceChanged() noexcept { endpoints_.clear(); } if (connections > 0 || listeners > 0) { - logger_.Info("{}_if was replaced; dropped {} connection(s) and {} listener(s)", + NFL_LOG_INFO(logger_, "{}_if was replaced; dropped {} connection(s) and {} listener(s)", source_replaced ? "source" : "target", connections, listeners); } } @@ -68,7 +68,7 @@ void DialProxy::OnInterfaceChanged() noexcept { const auto dropped = std::erase_if(endpoints_, [&](const auto& entry) { return is_stale(entry.second); }); if (dropped > 0) { - logger_.Info("source_if V4 source is now {}; dropped {} stale DIAL listener(s) for re-mint", + NFL_LOG_INFO(logger_, "source_if V4 source is now {}; dropped {} stale DIAL listener(s) for re-mint", current ? current->ToString() : "none", dropped); } if (connections_.empty() && endpoints_.empty()) { @@ -102,7 +102,7 @@ std::optional DialProxy::EnsureListener(const IpEndpoint& device, En // Over cap: refuse without demoting (close-don't-forward, as a fresh over-cap mint does). if (role == Endpoint::Role::Rest && endpoint.role == Endpoint::Role::Discovery) { if (CountInRole(Endpoint::Role::Rest) >= MAX_REST_LISTENERS) { - logger_.Error("Cannot promote {} to rest: rest listener cap reached", device); + NFL_LOG_ERROR(logger_, "Cannot promote {} to rest: rest listener cap reached", device); return std::nullopt; } endpoint.role = Endpoint::Role::Rest; @@ -114,14 +114,14 @@ std::optional DialProxy::EnsureListener(const IpEndpoint& device, En ? MAX_DISCOVERY_LISTENERS : MAX_REST_LISTENERS; if (CountInRole(role) >= role_cap) { - logger_.Error("Cannot proxy {}: {} listener cap reached", device, + NFL_LOG_ERROR(logger_, "Cannot proxy {}: {} listener cap reached", device, role == Endpoint::Role::Rest ? "rest" : "discovery"); return std::nullopt; } auto listener = TcpSocket::Listen(*source_if_, IpAddress::Family::V4); if (!listener) { - logger_.Error("Cannot proxy {}: failed to open a listener", device); // Listen logged the cause + NFL_LOG_ERROR(logger_, "Cannot proxy {}: failed to open a listener", device); // Listen logged the cause return std::nullopt; } const auto authority = listener->LocalEndpoint(); @@ -134,7 +134,7 @@ std::optional DialProxy::EnsureListener(const IpEndpoint& device, En auto registration = dispatcher_->Register(listener_fd, CreateDelegate<&DialProxy::OnAccept>(this)); if (!registration.IsValid()) { - logger_.Error("Cannot proxy {}: failed to register the listener", device); + NFL_LOG_ERROR(logger_, "Cannot proxy {}: failed to register the listener", device); endpoints_.erase(it); // drops the listener (registration was never valid) return std::nullopt; } @@ -148,7 +148,7 @@ std::optional DialProxy::EnsureListener(const IpEndpoint& device, En eviction_timer_.Start(EVICTION_INTERVAL, CreateDelegate<&DialProxy::EvictExpired>(this)); } - logger_.Debug("Created {} listener {} for {}", role == Endpoint::Role::Rest ? "rest" : "discovery", + NFL_LOG_DEBUG(logger_, "Created {} listener {} for {}", role == Endpoint::Role::Rest ? "rest" : "discovery", authority, device); return authority; } @@ -183,7 +183,7 @@ void DialProxy::Connection::Abort() noexcept { void DialProxy::Connection::Sync(TcpSocket& sock) noexcept { if (!owner->dispatcher_->SetWriteInterest(sock.Fd(), sock.WantsWrite())) { - owner->logger_.Error("Cannot set write interest for fd {} (device {}); aborting connection", + NFL_LOG_ERROR(owner->logger_, "Cannot set write interest for fd {} (device {}); aborting connection", sock.Fd(), endpoint->device); Abort(); } @@ -315,7 +315,7 @@ void DialProxy::OnAccept(int listener_fd) noexcept { auto* ep = FindEndpointByListenerFd(listener_fd); if (ep == nullptr) { - logger_.Error("Accept on fd {} has no owning endpoint; ignoring", listener_fd); + NFL_LOG_ERROR(logger_, "Accept on fd {} has no owning endpoint; ignoring", listener_fd); return; } ep->last_active = now; @@ -326,13 +326,13 @@ void DialProxy::OnAccept(int listener_fd) noexcept { } if (connections_.size() >= MAX_CONNECTIONS) { - logger_.Warn("Dropping accept for {}: connection cap reached", ep->device); + NFL_LOG_WARN(logger_, "Dropping accept for {}: connection cap reached", ep->device); return; // the accepted client TcpSocket drops here -> RAII close } auto upstream = TcpSocket::Connect(ep->device, target_if_.Get()); if (!upstream) { - logger_.Error("Dropping accept for {}: failed to start the upstream connect", ep->device); + NFL_LOG_ERROR(logger_, "Dropping accept for {}: failed to start the upstream connect", ep->device); return; } @@ -363,13 +363,13 @@ void DialProxy::OnAccept(int listener_fd) noexcept { client_reg = {}; upstream_reg = {}; connections_.erase(it); - logger_.Error("Dropping accept for {}: failed to register the connection fds", ep->device); + NFL_LOG_ERROR(logger_, "Dropping accept for {}: failed to register the connection fds", ep->device); return; } conn.client_reg = std::move(client_reg); conn.upstream_reg = std::move(upstream_reg); - logger_.Debug("Opened connection {} (client fd {}, upstream fd {}) for {}", id, client_fd, upstream_fd, + NFL_LOG_DEBUG(logger_, "Opened connection {} (client fd {}, upstream fd {}) for {}", id, client_fd, upstream_fd, ep->device); } @@ -401,7 +401,7 @@ void DialProxy::EvictExpired(std::chrono::steady_clock::time_point now) noexcept }); if (connections_reaped > 0 || endpoints_reaped > 0) { - logger_.Debug("Evicted {} connection(s) and {} listener(s); {} connection(s), {} listener(s) remain", + NFL_LOG_DEBUG(logger_, "Evicted {} connection(s) and {} listener(s); {} connection(s), {} listener(s) remain", connections_reaped, endpoints_reaped, connections_.size(), endpoints_.size()); } diff --git a/src/reflector/event_loop_dispatcher.cpp b/src/reflector/event_loop_dispatcher.cpp index b45887b..6bbb336 100644 --- a/src/reflector/event_loop_dispatcher.cpp +++ b/src/reflector/event_loop_dispatcher.cpp @@ -46,37 +46,37 @@ EventLoopDispatcher::EventLoopDispatcher() { #endif if (!event_fd_) { - GetLogger().Error("Cannot create dispatcher event queue: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot create dispatcher event queue: {}", Error::FromErrno()); } else { - GetLogger().Debug("Created dispatcher event queue fd {}", event_fd_.Get()); + NFL_LOG_DEBUG(GetLogger(), "Created dispatcher event queue fd {}", event_fd_.Get()); } } EventLoopDispatcher::~EventLoopDispatcher() noexcept { if (!callbacks_.empty()) { - GetLogger().Error("Destroying dispatcher with {} fd callback registration(s) still active", callbacks_.size()); + NFL_LOG_ERROR(GetLogger(), "Destroying dispatcher with {} fd callback registration(s) still active", callbacks_.size()); } if (!timers_.empty()) { - GetLogger().Error("Destroying dispatcher with {} timer registration(s) still active", timers_.size()); + NFL_LOG_ERROR(GetLogger(), "Destroying dispatcher with {} timer registration(s) still active", timers_.size()); } if (event_fd_) { - GetLogger().Debug("Closing dispatcher event queue fd {}", event_fd_.Get()); + NFL_LOG_DEBUG(GetLogger(), "Closing dispatcher event queue fd {}", event_fd_.Get()); event_fd_.Reset(); } } Dispatcher::Registration EventLoopDispatcher::Register(int fd, FdCallbacks callbacks) { if (fd < 0) { - GetLogger().Error("Cannot register fd callback: fd is invalid"); + NFL_LOG_ERROR(GetLogger(), "Cannot register fd callback: fd is invalid"); return {}; } if (!callbacks.read.IsValid()) { - GetLogger().Error("Cannot register fd callback: a read handler is required for fd {}", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot register fd callback: a read handler is required for fd {}", fd); return {}; } if (callbacks_.contains(fd)) { - GetLogger().Error("Cannot register fd callback: a callback for fd {} is already registered", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot register fd callback: a callback for fd {} is already registered", fd); return {}; } // Insert first so SetEvents reads the requested initial write arm state from the entry, then @@ -86,18 +86,18 @@ Dispatcher::Registration EventLoopDispatcher::Register(int fd, FdCallbacks callb if (!SetEvents(fd, it->second.write_armed)) { RemoveEvents(fd); callbacks_.erase(it); - GetLogger().Error("Cannot register fd callback: event registration failed for fd {}", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot register fd callback: event registration failed for fd {}", fd); return {}; } - GetLogger().Debug("Registered fd callback for fd {}", fd); + NFL_LOG_DEBUG(GetLogger(), "Registered fd callback for fd {}", fd); return MakeRegistration(fd); } bool EventLoopDispatcher::SetWriteInterest(int fd, bool enabled) noexcept { const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warn("Cannot set write interest for fd {}: not registered", fd); + NFL_LOG_WARN(GetLogger(), "Cannot set write interest for fd {}: not registered", fd); return false; } if (it->second.write_armed == enabled) { @@ -113,23 +113,23 @@ bool EventLoopDispatcher::SetWriteInterest(int fd, bool enabled) noexcept { bool EventLoopDispatcher::Unregister(int fd) noexcept { const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warn("Cannot unregister fd callback for fd {}: not found", fd); + NFL_LOG_WARN(GetLogger(), "Cannot unregister fd callback for fd {}: not found", fd); return false; } callbacks_.erase(it); if (!RemoveEvents(fd)) { - GetLogger().Error("Cannot remove events for fd {} after unregistering its callback", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot remove events for fd {} after unregistering its callback", fd); } - GetLogger().Debug("Unregistered fd callback for fd {}", fd); + NFL_LOG_DEBUG(GetLogger(), "Unregistered fd callback for fd {}", fd); return true; } void EventLoopDispatcher::Run(const volatile std::sig_atomic_t& stop_requested) { - GetLogger().Info("Starting dispatcher event loop"); + NFL_LOG_INFO(GetLogger(), "Starting dispatcher event loop"); if (!event_fd_) { - GetLogger().Error("Cannot run dispatcher: event queue is invalid"); + NFL_LOG_ERROR(GetLogger(), "Cannot run dispatcher: event queue is invalid"); return; } while (stop_requested == 0) { @@ -140,12 +140,12 @@ void EventLoopDispatcher::Run(const volatile std::sig_atomic_t& stop_requested) FireDueTimers(now); PollOnce(NextTimeout(now)); } - GetLogger().Info("Stopped dispatcher event loop"); + NFL_LOG_INFO(GetLogger(), "Stopped dispatcher event loop"); } bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { if (!event_fd_) { - GetLogger().Error("Cannot poll dispatcher: event queue is invalid"); + NFL_LOG_ERROR(GetLogger(), "Cannot poll dispatcher: event queue is invalid"); return false; } @@ -157,7 +157,7 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { // Expected when a signal interrupts polling; callers decide whether to retry or shut down. return false; } - GetLogger().Error("Cannot poll dispatcher read events: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot poll dispatcher read events: {}", Error::FromErrno()); return false; } if (event_count == 0) { @@ -174,7 +174,7 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { // Expected when a signal interrupts polling; callers decide whether to retry or shut down. return false; } - GetLogger().Error("Cannot poll dispatcher read events: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot poll dispatcher read events: {}", Error::FromErrno()); return false; } if (event_count == 0) { @@ -182,14 +182,14 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { } const auto fd = static_cast(event.ident); if ((event.flags & EV_ERROR) != 0) { - GetLogger().Error("Dispatcher read event failed for fd {}: {}", fd, event.data); + NFL_LOG_ERROR(GetLogger(), "Dispatcher read event failed for fd {}: {}", fd, event.data); return false; } #endif const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Warn("Dispatcher woke for unwatched fd {}", fd); + NFL_LOG_WARN(GetLogger(), "Dispatcher woke for unwatched fd {}", fd); return false; } @@ -237,13 +237,13 @@ EventLoopDispatcher::TimerId EventLoopDispatcher::AllocateTimerId() noexcept { bool EventLoopDispatcher::RegisterTimer( TimerId id, std::chrono::milliseconds interval, const OnTimerCallback& callback) { if (static_cast(id) >= next_timer_id_) { - GetLogger().Error("Cannot register timer: TimerId {} was not allocated by this dispatcher", + NFL_LOG_ERROR(GetLogger(), "Cannot register timer: TimerId {} was not allocated by this dispatcher", static_cast(id)); return false; } if (interval <= std::chrono::milliseconds{0} || !callback.IsValid()) { UnregisterTimer(id); // an invalid (re-)registration leaves the timer stopped, like Start with bad args - GetLogger().Error("Cannot register timer: non-positive interval or invalid callback"); + NFL_LOG_ERROR(GetLogger(), "Cannot register timer: non-positive interval or invalid callback"); return false; } // Reuse the existing entry for this id rather than append: an appended entry sits past FireDueTimers' @@ -261,7 +261,7 @@ bool EventLoopDispatcher::RegisterTimer( } else { timers_.push_back(registration); } - GetLogger().Debug("Registered timer {} (interval {}ms); {} active", static_cast(id), + NFL_LOG_DEBUG(GetLogger(), "Registered timer {} (interval {}ms); {} active", static_cast(id), interval.count(), std::ranges::count_if(timers_, [](const TimerEntry& entry) { return entry.enabled; })); return true; } @@ -278,7 +278,7 @@ void EventLoopDispatcher::UnregisterTimer(TimerId id) noexcept { } else { timers_.erase(it); // no walk in progress; erase in place } - GetLogger().Debug("Unregistered timer {}; {} active", static_cast(id), + NFL_LOG_DEBUG(GetLogger(), "Unregistered timer {}; {} active", static_cast(id), std::ranges::count_if(timers_, [](const TimerEntry& t) { return t.enabled; })); } @@ -316,18 +316,18 @@ std::chrono::milliseconds EventLoopDispatcher::NextTimeout(std::chrono::steady_c bool EventLoopDispatcher::SetEvents(int fd, bool enable_write) noexcept { if (!event_fd_) { - GetLogger().Error("Cannot set events for fd {}: event queue is invalid", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot set events for fd {}: event queue is invalid", fd); return false; } const auto it = callbacks_.find(fd); if (it == callbacks_.end()) { - GetLogger().Error("Cannot set events for fd {}: not registered", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot set events for fd {}: not registered", fd); return false; } // Refuse to arm write with no write handler: a writable fd with nothing to invoke would busy-spin // the level-triggered loop. (Read is always armed; Register guarantees a read handler.) if (enable_write && !it->second.write.IsValid()) { - GetLogger().Error("Cannot arm write interest for fd {}: no write callback registered", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot arm write interest for fd {}: no write callback registered", fd); return false; } @@ -340,7 +340,7 @@ bool EventLoopDispatcher::SetEvents(int fd, bool enable_write) noexcept { event.data.fd = fd; if (epoll_ctl(event_fd_.Get(), EPOLL_CTL_MOD, fd, &event) != 0 && (errno != ENOENT || epoll_ctl(event_fd_.Get(), EPOLL_CTL_ADD, fd, &event) != 0)) { - GetLogger().Error("Cannot set events for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set events for fd {}: {}", fd, Error::FromErrno()); return false; } #else @@ -350,24 +350,24 @@ bool EventLoopDispatcher::SetEvents(int fd, bool enable_write) noexcept { struct kevent change{}; EV_SET(&change, fd, EVFILT_READ, EV_ADD | EV_ENABLE, 0, 0, nullptr); if (kevent(event_fd_.Get(), &change, 1, nullptr, 0, nullptr) != 0) { - GetLogger().Error("Cannot arm read interest for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot arm read interest for fd {}: {}", fd, Error::FromErrno()); return false; } const auto write_flags = static_cast(enable_write ? (EV_ADD | EV_ENABLE) : EV_DISABLE); EV_SET(&change, fd, EVFILT_WRITE, write_flags, 0, 0, nullptr); if (kevent(event_fd_.Get(), &change, 1, nullptr, 0, nullptr) != 0 && (enable_write || errno != ENOENT)) { - GetLogger().Error("Cannot set write interest for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set write interest for fd {}: {}", fd, Error::FromErrno()); return false; } #endif - GetLogger().Debug("Set events for fd {}: write {}", fd, enable_write); + NFL_LOG_DEBUG(GetLogger(), "Set events for fd {}: write {}", fd, enable_write); return true; } bool EventLoopDispatcher::RemoveEvents(int fd) noexcept { if (!event_fd_) { - GetLogger().Error("Cannot remove events for fd {}: event queue is invalid", fd); + NFL_LOG_ERROR(GetLogger(), "Cannot remove events for fd {}: event queue is invalid", fd); return false; } @@ -375,7 +375,7 @@ bool EventLoopDispatcher::RemoveEvents(int fd) noexcept { // ENOENT is benign: the kernel auto-removes a closed fd, so a DEL issued after the owner already // closed it hits ENOENT (matching the kqueue branch below). Any other failure is a real error. if (epoll_ctl(event_fd_.Get(), EPOLL_CTL_DEL, fd, nullptr) != 0 && errno != ENOENT) { - GetLogger().Error("Cannot remove events for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot remove events for fd {}: {}", fd, Error::FromErrno()); return false; } #else @@ -387,7 +387,7 @@ bool EventLoopDispatcher::RemoveEvents(int fd) noexcept { struct kevent change{}; EV_SET(&change, fd, static_cast(filter), EV_DELETE, 0, 0, nullptr); if (kevent(event_fd_.Get(), &change, 1, nullptr, 0, nullptr) != 0 && errno != ENOENT) { - GetLogger().Error("Cannot remove events for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot remove events for fd {}: {}", fd, Error::FromErrno()); ok = false; } } @@ -396,7 +396,7 @@ bool EventLoopDispatcher::RemoveEvents(int fd) noexcept { } #endif - GetLogger().Debug("Removed events for fd {}", fd); + NFL_LOG_DEBUG(GetLogger(), "Removed events for fd {}", fd); return true; } diff --git a/src/reflector/family_capability.cpp b/src/reflector/family_capability.cpp index d6fa668..b919654 100644 --- a/src/reflector/family_capability.cpp +++ b/src/reflector/family_capability.cpp @@ -34,11 +34,11 @@ void FamilyCapability::ObserveFamily() noexcept { // An unused family's CanSend is always false, so it never reaches a transition here — it stays // silent without a separate guard. if (can_send) { - logger_->Info("Starting {} reflection: a source address is available", family); + NFL_LOG_INFO(*logger_, "Starting {} reflection: a source address is available", family); } else if (policy_.required.Get()) { - logger_->Error("Cannot reflect {} packets: a source address is no longer available", family); + NFL_LOG_ERROR(*logger_, "Cannot reflect {} packets: a source address is no longer available", family); } else { - logger_->Info("Stopping {} reflection: a source address is no longer available", family); + NFL_LOG_INFO(*logger_, "Stopping {} reflection: a source address is no longer available", family); } } diff --git a/src/reflector/frame_builder.cpp b/src/reflector/frame_builder.cpp index c58ebe7..2ec58a6 100644 --- a/src/reflector/frame_builder.cpp +++ b/src/reflector/frame_builder.cpp @@ -38,12 +38,12 @@ size_t CheckedFrameSize(size_t l2_size, bool v4, size_t payload_size, size_t out const size_t ip_size = v4 ? IPV4_HEADER_SIZE : IPV6_HEADER_SIZE; const size_t udp_length = UDP_HEADER_SIZE + payload_size; if (udp_length > MAX_UDP_LENGTH || (v4 && ip_size + udp_length > MAX_UDP_LENGTH)) { - GetLogger().Error("Cannot build UDP frame: {}-byte payload overflows the UDP length field", payload_size); + NFL_LOG_ERROR(GetLogger(), "Cannot build UDP frame: {}-byte payload overflows the UDP length field", payload_size); return 0; } const size_t frame_size = l2_size + ip_size + udp_length; if (out_size < frame_size) { - GetLogger().Error("Cannot build UDP frame: {}-byte buffer too small for {}-byte frame", out_size, frame_size); + NFL_LOG_ERROR(GetLogger(), "Cannot build UDP frame: {}-byte buffer too small for {}-byte frame", out_size, frame_size); return 0; } return frame_size; diff --git a/src/reflector/http_message.cpp b/src/reflector/http_message.cpp index 35dde66..da628ad 100644 --- a/src/reflector/http_message.cpp +++ b/src/reflector/http_message.cpp @@ -101,7 +101,7 @@ bool HttpFraming::ScanAndRewriteHeader() { // real body without correlating the request method across the two framers: refuse HEAD at the // request side instead. DIAL clients never issue it. if (type_ == MessageType::Request && std::string_view{header_}.starts_with("HEAD ")) { - GetLogger().Error("refusing a HEAD request: its response cannot be framed"); + NFL_LOG_ERROR(GetLogger(), "refusing a HEAD request: its response cannot be framed"); return false; } size_t pos = 0; @@ -119,13 +119,13 @@ bool HttpFraming::ScanAndRewriteHeader() { // at the first non-digit and reports success, so "12abc" would otherwise frame a body of 12 and // mis-parse the rest. Trailing OWS (RFC 7230 §3.2.4) is tolerated; any other trailing byte rejects. if (result.ec != std::errc{} || !TrimLeadingSpace({result.ptr, v.data() + v.size()}).empty()) { - GetLogger().Error("malformed Content-Length value \"{}\"", v); + NFL_LOG_ERROR(GetLogger(), "malformed Content-Length value \"{}\"", v); return false; } // A second, differing Content-Length is a request-smuggling vector (RFC 9112 §6.3): refuse // the message rather than pick a winner. Identical repeats agree on the framing, so they pass. if (has_content_length && parsed != content_length) { - GetLogger().Error("conflicting Content-Length values {} and {}", content_length, parsed); + NFL_LOG_ERROR(GetLogger(), "conflicting Content-Length values {} and {}", content_length, parsed); return false; } content_length = parsed; @@ -147,7 +147,7 @@ bool HttpFraming::ScanAndRewriteHeader() { if (const auto found = ParseAuthority(value, /*bare=*/is_host)) { if (const auto repl = rewrite_(found->endpoint)) { // Log before the splice: `line` views into header_, which the replace may reallocate. - GetLogger().Debug("rewrote {} authority {} -> {}", line.substr(0, colon), + NFL_LOG_DEBUG(GetLogger(), "rewrote {} authority {} -> {}", line.substr(0, colon), found->endpoint, *repl); const std::string repl_text = std::format("{}", *repl); const size_t auth_off = @@ -190,7 +190,7 @@ std::optional HttpFraming::Feed(std::string_view input) { const size_t term = input.find(HEADER_TERMINATOR); if (term == std::string_view::npos) { if (input.size() > MAX_HEADER_BYTES) { - GetLogger().Error("header block exceeds the {}-byte cap with no terminator", MAX_HEADER_BYTES); + NFL_LOG_ERROR(GetLogger(), "header block exceeds the {}-byte cap with no terminator", MAX_HEADER_BYTES); return std::nullopt; } return Output{}; // incomplete header: nothing forwardable yet, read more and feed again @@ -200,7 +200,7 @@ std::optional HttpFraming::Feed(std::string_view input) { // header past it that a segmented one could not (the unterminated check above never fires // when the terminator is already in the buffer). if (header_len > MAX_HEADER_BYTES) { - GetLogger().Error("header block exceeds the {}-byte cap", MAX_HEADER_BYTES); + NFL_LOG_ERROR(GetLogger(), "header block exceeds the {}-byte cap", MAX_HEADER_BYTES); return std::nullopt; } header_.assign(input.data(), header_len); // copy only the header, to rewrite it @@ -244,7 +244,7 @@ std::optional HttpFraming::Feed(std::string_view input) { const size_t eol = input.find(CRLF, pos); if (eol == std::string_view::npos) { if (input.size() - pos > MAX_CHUNK_LINE_BYTES) { - GetLogger().Error("chunk-size line exceeds the {}-byte cap with no terminator", + NFL_LOG_ERROR(GetLogger(), "chunk-size line exceeds the {}-byte cap with no terminator", MAX_CHUNK_LINE_BYTES); return std::nullopt; } @@ -258,7 +258,7 @@ std::optional HttpFraming::Feed(std::string_view input) { size_t chunk_size = 0; if (std::from_chars(size_field.data(), size_field.data() + size_field.size(), chunk_size, 16).ec != std::errc{}) { - GetLogger().Error("malformed chunk size \"{}\"", size_field); + NFL_LOG_ERROR(GetLogger(), "malformed chunk size \"{}\"", size_field); return std::nullopt; } pos = eol + CRLF.size(); @@ -266,7 +266,7 @@ std::optional HttpFraming::Feed(std::string_view input) { phase_ = BodyChunkedDone; // an optional trailer section + the closing CRLF remain } else if (chunk_size > std::numeric_limits::max() - CRLF.size()) { // A near-SIZE_MAX size (hostile/buggy device) would wrap the addition below and misframe. - GetLogger().Error("chunk size {:#x} too large to frame", chunk_size); + NFL_LOG_ERROR(GetLogger(), "chunk size {:#x} too large to frame", chunk_size); return std::nullopt; } else { chunk_remaining_ = chunk_size + CRLF.size(); // chunk DATA + its terminating CRLF @@ -281,7 +281,7 @@ std::optional HttpFraming::Feed(std::string_view input) { const size_t eol = input.find(CRLF, pos); if (eol == std::string_view::npos) { if (input.size() - pos > MAX_TRAILER_LINE_BYTES) { - GetLogger().Error("chunked trailer line exceeds the {}-byte cap with no terminator", + NFL_LOG_ERROR(GetLogger(), "chunked trailer line exceeds the {}-byte cap with no terminator", MAX_TRAILER_LINE_BYTES); return std::nullopt; } diff --git a/src/reflector/interface.cpp b/src/reflector/interface.cpp index 3817beb..5ea5a33 100644 --- a/src/reflector/interface.cpp +++ b/src/reflector/interface.cpp @@ -23,12 +23,12 @@ Interface::Interface(std::string_view name) : logger_{std::format("Interface:{}", name)} , name_{name} { if (name_.size() >= IFNAMSIZ) { - logger_.Error("Interface name \"{}\" is too long (max {} characters)", name_, IFNAMSIZ - 1); + NFL_LOG_ERROR(logger_, "Interface name \"{}\" is too long (max {} characters)", name_, IFNAMSIZ - 1); return; } index_ = ResolveIndex().value_or(0); if (index_ == 0) { - logger_.Error("Cannot resolve interface index: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot resolve interface index: {}", Error::FromErrno()); return; } // In-constructor dispatch resolves to Interface::Refresh — intended: construction always @@ -56,7 +56,7 @@ std::optional Interface::ResolveIndex() const noexcept { Interface::IdentityChange Interface::Reidentify() noexcept { const auto resolved = ResolveIndex(); if (!resolved) { - logger_.Error("Cannot resolve interface index: {}; keeping index {}", Error::FromErrno(), index_); + NFL_LOG_ERROR(logger_, "Cannot resolve interface index: {}; keeping index {}", Error::FromErrno(), index_); return IdentityChange::Unresolved; } if (*resolved == index_) { @@ -66,12 +66,12 @@ Interface::IdentityChange Interface::Reidentify() noexcept { const unsigned previous = std::exchange(index_, *resolved); if (index_ == 0) { addresses_ = {}; // nothing may send or join against an identity that is gone - logger_.Info("Interface is gone (was index {}); parked until it returns", previous); + NFL_LOG_INFO(logger_, "Interface is gone (was index {}); parked until it returns", previous); return IdentityChange::Parked; } Refresh(); - logger_.Info("Interface reappeared as index {} (was {})", index_, previous); + NFL_LOG_INFO(logger_, "Interface reappeared as index {} (was {})", index_, previous); return IdentityChange::Repointed; } @@ -112,7 +112,7 @@ void Interface::Refresh() noexcept { return; } addresses_ = *resolved; - logger_.Debug("Resolved addresses (index {}): MAC {}, IPv4 {}, IPv6 {}, IPv6 routable {}", index_, + NFL_LOG_DEBUG(logger_, "Resolved addresses (index {}): MAC {}, IPv4 {}, IPv6 {}, IPv6 routable {}", index_, addresses_.mac, addresses_.v4 ? addresses_.v4->ToString() : "none", addresses_.v6 ? addresses_.v6->ToString() : "none", addresses_.v6_routable ? addresses_.v6_routable->ToString() : "none"); diff --git a/src/reflector/interface_address.cpp b/src/reflector/interface_address.cpp index b4d1c73..6b55e45 100644 --- a/src/reflector/interface_address.cpp +++ b/src/reflector/interface_address.cpp @@ -120,7 +120,7 @@ template // body left zero: ifi_family / ifa_family = AF_UNSPEC dumps every family. if (send(fd, &request, request.header.nlmsg_len, 0) < 0) { - GetLogger().Error("Cannot send netlink dump request: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot send netlink dump request: {}", Error::FromErrno()); return false; } @@ -134,7 +134,7 @@ template while (true) { const auto needed = recv(fd, buffer.data(), buffer.size(), MSG_PEEK | MSG_TRUNC); if (needed < 0) { - GetLogger().Error("Cannot read netlink dump reply: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot read netlink dump reply: {}", Error::FromErrno()); return false; } if (static_cast(needed) > buffer.size()) { @@ -146,13 +146,13 @@ template const auto received = recvfrom(fd, buffer.data(), buffer.size(), 0, reinterpret_cast(&src), &addrlen); if (received < 0) { - GetLogger().Error("Cannot read netlink dump reply: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot read netlink dump reply: {}", Error::FromErrno()); return false; } // Only the kernel (nl_pid 0) may answer the dump; a local process could unicast a spoofed // reply to inject a bogus address. Discard anything else and read the next datagram. if (addrlen < sizeof(src) || src.nl_pid != 0) { - GetLogger().Debug("Ignoring a netlink dump reply from a non-kernel sender (pid {})", src.nl_pid); + NFL_LOG_DEBUG(GetLogger(), "Ignoring a netlink dump reply from a non-kernel sender (pid {})", src.nl_pid); continue; } @@ -169,7 +169,7 @@ template // nlmsgerr.error is a negative errno (0 is an ACK, not a failure). const auto* error = start_lifetime_as(NLMSG_DATA(header)); if (error->error != 0) { - GetLogger().Error("Netlink dump returned an error: {}", Error::FromErrno(-error->error)); + NFL_LOG_ERROR(GetLogger(), "Netlink dump returned an error: {}", Error::FromErrno(-error->error)); return false; } return true; @@ -182,7 +182,7 @@ template bool ResolveViaNetlink(unsigned index, InterfaceAddresses& result) noexcept { const int fd = socket(AF_NETLINK, SOCK_RAW, NETLINK_ROUTE); if (fd < 0) { - GetLogger().Error("Cannot open netlink socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot open netlink socket: {}", Error::FromErrno()); return false; } @@ -271,7 +271,7 @@ bool IsUsableIpv6(int inet6_fd, const char* interface, const sockaddr_in6& sin6) std::strncpy(request.ifr_name, interface, sizeof(request.ifr_name) - 1); request.ifr_ifru.ifru_addr = sin6; if (ioctl(inet6_fd, SIOCGIFAFLAG_IN6, &request) != 0) { - GetLogger().Warn("Cannot query IPv6 address flags on interface \"{}\": {}", interface, Error::FromErrno()); + NFL_LOG_WARN(GetLogger(), "Cannot query IPv6 address flags on interface \"{}\": {}", interface, Error::FromErrno()); return false; } return detail::Ipv6SourceFlagsUsable(request.ifr_ifru.ifru_flags6); @@ -283,13 +283,13 @@ bool ResolveViaGetifaddrs(std::string_view interface, InterfaceAddresses& result // can't verify any IPv6 source, so fail early rather than guess. const int inet6_fd = socket(AF_INET6, SOCK_DGRAM, 0); if (inet6_fd < 0) { - GetLogger().Error("Cannot open IPv6 socket to query address flags: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot open IPv6 socket to query address flags: {}", Error::FromErrno()); return false; } ifaddrs* head = nullptr; if (getifaddrs(&head) != 0) { - GetLogger().Error("Cannot enumerate interface addresses: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot enumerate interface addresses: {}", Error::FromErrno()); close(inet6_fd); return false; } diff --git a/src/reflector/ip_address.cpp b/src/reflector/ip_address.cpp index 3babb61..7abd7f6 100644 --- a/src/reflector/ip_address.cpp +++ b/src/reflector/ip_address.cpp @@ -150,7 +150,7 @@ std::optional IpAddress::FromString(const std::string& address) { return IpAddress{Family::V6, bytes}; } - GetLogger().Error("Cannot parse IP address \"{}\"", address); + NFL_LOG_ERROR(GetLogger(), "Cannot parse IP address \"{}\"", address); return std::nullopt; } @@ -178,7 +178,7 @@ std::optional IpAddress::FromSockaddr(const sockaddr* address) noexce return IpAddress{Family::V6, bytes}; } - GetLogger().Error("Cannot convert sockaddr with address family {} to IpAddress", + NFL_LOG_ERROR(GetLogger(), "Cannot convert sockaddr with address family {} to IpAddress", static_cast(address->sa_family)); return std::nullopt; } @@ -224,7 +224,7 @@ std::string_view IpAddress::ToChars(TextBuffer& buffer) const noexcept { const int address_family = family_ == Family::V6 ? AF_INET6 : AF_INET; if (inet_ntop(address_family, bytes_.data(), buffer.data(), narrow_cast(buffer.size())) == nullptr) { - GetLogger().Error("Cannot convert IP address to string: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot convert IP address to string: {}", Error::FromErrno()); return ""; } return {buffer.data(), std::char_traits::length(buffer.data())}; diff --git a/src/reflector/logger.h b/src/reflector/logger.h index 6cb5de9..2892b4e 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -59,11 +59,9 @@ class Logger : NoCopy { static void SetMinLevel(LogLevel level) noexcept { min_level_ = level; } [[nodiscard]] static LogLevel MinLevel() noexcept { return min_level_; } + // Ungated: the NFL_LOG macros check the level before they reach here. template - void Log(LogLevel level, detail::LogFmt...> fmt, Args&& ...args) noexcept { - if (level < min_level_) { - return; - } + void Emit(LogLevel level, detail::LogFmt...> fmt, Args&& ...args) noexcept { try { // Clang 17 does not support std::chrono::current_zone(). Maybe next time. const auto time = std::time({}); @@ -97,26 +95,6 @@ class Logger : NoCopy { } } - template - void Debug(detail::LogFmt...> fmt, Args&& ...args) noexcept { - Log(LogLevel::Debug, std::move(fmt), std::forward(args)...); - } - - template - void Info(detail::LogFmt...> fmt, Args&& ...args) noexcept { - Log(LogLevel::Info, std::move(fmt), std::forward(args)...); - } - - template - void Warn(detail::LogFmt...> fmt, Args&& ...args) noexcept { - Log(LogLevel::Warn, std::move(fmt), std::forward(args)...); - } - - template - void Error(detail::LogFmt...> fmt, Args&& ...args) noexcept { - Log(LogLevel::Error, std::move(fmt), std::forward(args)...); - } - private: static constexpr size_t MAX_MESSAGE_SIZE = 1024; // Plus the timestamp, level, logger name and source location wrapped around it. @@ -155,3 +133,18 @@ struct std::formatter std::unreachable(); } }; + +// The only level gate. A filtered record never reaches Emit, so it never evaluates its arguments: +// a suppressed Debug line would otherwise still build every Error::FromErrno() and ToString() it +// passes. NFL_ rather than a bare LOG_, which syslog.h already defines. +#define NFL_LOG(logger, level, ...) \ + do { \ + if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ + (logger).Emit(::reflector::LogLevel::level, __VA_ARGS__); \ + } \ + } while (false) + +#define NFL_LOG_DEBUG(logger, ...) NFL_LOG(logger, Debug, __VA_ARGS__) +#define NFL_LOG_INFO(logger, ...) NFL_LOG(logger, Info, __VA_ARGS__) +#define NFL_LOG_WARN(logger, ...) NFL_LOG(logger, Warn, __VA_ARGS__) +#define NFL_LOG_ERROR(logger, ...) NFL_LOG(logger, Error, __VA_ARGS__) diff --git a/src/reflector/mdns_reflector.cpp b/src/reflector/mdns_reflector.cpp index bbb97f7..6f5f616 100644 --- a/src/reflector/mdns_reflector.cpp +++ b/src/reflector/mdns_reflector.cpp @@ -36,7 +36,7 @@ MdnsReflector::MdnsReflector(PacketDispatcher& packet_dispatcher, LinkSocket& so bool MdnsReflector::ValidateConfig(const MdnsConfig& config) { if (const auto error = config.Verify()) { - logger_.Error("Cannot create mdns reflector \"{}\": invalid config: {}", config.name, *error); + NFL_LOG_ERROR(logger_, "Cannot create mdns reflector \"{}\": invalid config: {}", config.name, *error); return false; } return true; @@ -44,7 +44,7 @@ bool MdnsReflector::ValidateConfig(const MdnsConfig& config) { void MdnsReflector::Initialize(const MdnsConfig& config) { if (config.mac && !target_socket_->LinkCarriesMacs()) { - logger_.Error("Cannot create mdns reflector \"{}\": mac cannot match on \"{}\" (the link carries no MAC addresses)", + NFL_LOG_ERROR(logger_, "Cannot create mdns reflector \"{}\": mac cannot match on \"{}\" (the link carries no MAC addresses)", config.name, config.target_if); return; } @@ -52,12 +52,12 @@ void MdnsReflector::Initialize(const MdnsConfig& config) { // tracks the AND): the target re-emits relayed queries, the source re-emits relayed responses. // A required family must already be reflectable; an optional one comes up later if it ever is. if (config.RequiresIPv4() && !capability_.CanSend(IpAddress::Family::V4)) { - logger_.Error("Cannot create mdns reflector \"{}\": IPv4 requires a source address on both \"{}\" and \"{}\"", + NFL_LOG_ERROR(logger_, "Cannot create mdns reflector \"{}\": IPv4 requires a source address on both \"{}\" and \"{}\"", config.name, config.source_if, config.target_if); return; } if (config.RequiresIPv6() && !capability_.CanSend(IpAddress::Family::V6)) { - logger_.Error("Cannot create mdns reflector \"{}\": IPv6 requires a source address on both \"{}\" and \"{}\"", + NFL_LOG_ERROR(logger_, "Cannot create mdns reflector \"{}\": IPv6 requires a source address on both \"{}\" and \"{}\"", config.name, config.source_if, config.target_if); return; } @@ -67,7 +67,7 @@ void MdnsReflector::Initialize(const MdnsConfig& config) { } valid_ = true; - logger_.Info("Created mdns reflector (IPv4: {}, IPv6: {})", + NFL_LOG_INFO(logger_, "Created mdns reflector (IPv4: {}, IPv6: {})", capability_.CanSend(IpAddress::Family::V4) ? "enabled" : "disabled", capability_.CanSend(IpAddress::Family::V6) ? "enabled" : "disabled"); } @@ -81,7 +81,7 @@ bool MdnsReflector::BringUpFamily(IpAddress::Family family) { auto source_membership = source_socket_->JoinMulticastGroup(group); auto target_membership = target_socket_->JoinMulticastGroup(group); if (!source_membership.IsValid() || !target_membership.IsValid()) { - logger_.Error("Cannot reflect mdns {}: cannot join the group on both interfaces", group); + NFL_LOG_ERROR(logger_, "Cannot reflect mdns {}: cannot join the group on both interfaces", group); return false; } @@ -90,7 +90,7 @@ bool MdnsReflector::BringUpFamily(IpAddress::Family family) { PacketFilter{.dest_ip = group, .dest_port = MDNS_PORT}, CreateDelegate<&MdnsReflector::OnSourcePacket>(this)); if (!source_registration.IsValid()) { - logger_.Error("Cannot reflect mdns {}: registration failed (source)", group); + NFL_LOG_ERROR(logger_, "Cannot reflect mdns {}: registration failed (source)", group); return false; } @@ -99,7 +99,7 @@ bool MdnsReflector::BringUpFamily(IpAddress::Family family) { PacketFilter{.dest_ip = group, .dest_port = MDNS_PORT, .source_mac = config_mac_}, CreateDelegate<&MdnsReflector::OnTargetPacket>(this)); if (!target_registration.IsValid()) { - logger_.Error("Cannot reflect mdns {}: registration failed (target)", group); + NFL_LOG_ERROR(logger_, "Cannot reflect mdns {}: registration failed (target)", group); return false; } @@ -130,7 +130,7 @@ bool MdnsReflector::ShouldRelay(const Packet& packet, MdnsMessageKind kind) noex // The group + port 5353 should carry only mDNS, so a payload too short to be a DNS message // is anomalous and worth surfacing — the dedicated group means this won't spam a healthy // network. A message of the other kind, by contrast, is normal and dropped silently. - logger_.Info("Ignoring non-mDNS packet on {} from {}: {}-byte payload too short for a DNS header", + NFL_LOG_INFO(logger_, "Ignoring non-mDNS packet on {} from {}: {}-byte payload too short for a DNS header", packet.header.dest, packet.header.source, packet.payload.size()); return false; } @@ -141,10 +141,10 @@ void MdnsReflector::Relay(LinkSocket& egress, const Packet& packet) noexcept { // Re-emit to the same group it was sent to (the filter guarantees dest_ip is that group), from // the mDNS port, with the conventional 255 hop limit. if (!egress.SendUdpMulticastDatagram(packet.header.dest, MDNS_PORT, packet.payload, MDNS_TTL)) { - logger_.Error("Cannot reflect mdns packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR(logger_, "Cannot reflect mdns packet from {} to {}", packet.header.source, packet.header.dest); return; } - logger_.Debug("Reflected mdns packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_DEBUG(logger_, "Reflected mdns packet from {} to {}", packet.header.source, packet.header.dest); } } // namespace reflector diff --git a/src/reflector/memory_report.cpp b/src/reflector/memory_report.cpp index fd7e7fa..7da0733 100644 --- a/src/reflector/memory_report.cpp +++ b/src/reflector/memory_report.cpp @@ -201,7 +201,7 @@ CgroupMemory ReadCgroupMemory() noexcept { void LogCgroupMemory() { const auto cg = ReadCgroupMemory(); if (!cg.available) { - GetLogger().Info("cgroup memory unavailable (not cgroup v2, or /sys/fs/cgroup not mounted)"); + NFL_LOG_INFO(GetLogger(), "cgroup memory unavailable (not cgroup v2, or /sys/fs/cgroup not mounted)"); return; } const auto kib = [](size_t bytes) { return bytes / 1024; }; @@ -220,7 +220,7 @@ void LogCgroupMemory() { + val(cg.slab_unreclaimable) + val(cg.pagetables) + val(cg.sec_pagetables) + val(cg.kernel_stack) + val(cg.percpu) + val(cg.vmalloc) + val(cg.zswap); const size_t other = cg.current > known ? cg.current - known : 0; - GetLogger().Info( + NFL_LOG_INFO(GetLogger(), "cgroup (KiB) {} | breakdown: anon={} file={} (shmem={}) sock={} slab_reclaimable={} " "slab_unreclaimable={} pagetables={} sec_pagetables={} kernel_stack={} percpu={} vmalloc={} " "zswap={} other={}", @@ -242,16 +242,16 @@ void LogMemoryReport() { const size_t rss = StatusValueKib("VmRSS").value_or(0); #if defined(REFLECTOR_HAVE_MALLINFO2) const auto info = mallinfo2(); - GetLogger().Info( + NFL_LOG_INFO(GetLogger(), "rss={} KiB, peak={} KiB; heap in_use={} KiB, free_retained={} KiB, arena={} KiB, mmap={} KiB", rss, peak, info.uordblks / 1024, info.fordblks / 1024, info.arena / 1024, info.hblkhd / 1024); #else - GetLogger().Info("rss={} KiB, peak={} KiB (heap arena stats need glibc >= 2.33)", rss, peak); + NFL_LOG_INFO(GetLogger(), "rss={} KiB, peak={} KiB (heap arena stats need glibc >= 2.33)", rss, peak); #endif LogCgroupMemory(); #else // Non-Linux (macOS/FreeBSD): no /proc or cgroup; getrusage still gives the peak RSS. - GetLogger().Info("peak={} KiB (detailed RSS/heap/cgroup stats are glibc/Linux-only)", peak); + NFL_LOG_INFO(GetLogger(), "peak={} KiB (detailed RSS/heap/cgroup stats are glibc/Linux-only)", peak); #endif } diff --git a/src/reflector/port_reservation.cpp b/src/reflector/port_reservation.cpp index bfa5854..6c10ec0 100644 --- a/src/reflector/port_reservation.cpp +++ b/src/reflector/port_reservation.cpp @@ -31,7 +31,7 @@ std::optional PortReservation::Create(const IpAddress& source_i const bool v6 = source_ip.IsV6(); const int fd = socket(v6 ? AF_INET6 : AF_INET, SOCK_DGRAM, 0); if (fd < 0) { - GetLogger().Error("Cannot open port reservation socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot open port reservation socket: {}", Error::FromErrno()); return std::nullopt; } @@ -41,7 +41,7 @@ std::optional PortReservation::Create(const IpAddress& source_i sock_filter drop_all[] = {{0x06, 0, 0, 0x00000000}}; // BPF_RET | BPF_K, 0 sock_fprog program{.len = 1, .filter = drop_all}; if (setsockopt(fd, SOL_SOCKET, SO_ATTACH_FILTER, &program, sizeof(program)) != 0) { - GetLogger().Error("Cannot attach drop-all filter to port reservation socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot attach drop-all filter to port reservation socket: {}", Error::FromErrno()); close(fd); return std::nullopt; } @@ -50,7 +50,7 @@ std::optional PortReservation::Create(const IpAddress& source_i sockaddr_storage storage{}; const socklen_t length = source_ip.ToSockaddr(storage, /*port=*/0, scope_id); if (bind(fd, reinterpret_cast(&storage), length) != 0) { - GetLogger().Error("Cannot bind port reservation socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot bind port reservation socket: {}", Error::FromErrno()); close(fd); return std::nullopt; } @@ -58,7 +58,7 @@ std::optional PortReservation::Create(const IpAddress& source_i sockaddr_storage bound{}; socklen_t bound_length = sizeof(bound); if (getsockname(fd, reinterpret_cast(&bound), &bound_length) != 0) { - GetLogger().Error("Cannot query the reserved port: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot query the reserved port: {}", Error::FromErrno()); close(fd); return std::nullopt; } diff --git a/src/reflector/raw_socket.cpp b/src/reflector/raw_socket.cpp index 639a00c..f5d3feb 100644 --- a/src/reflector/raw_socket.cpp +++ b/src/reflector/raw_socket.cpp @@ -154,7 +154,7 @@ RawSocket::RawSocket(const Interface& interface) : logger_{std::format("RawSocket:{}", interface.Name())} , interface_{&interface} { if (!interface_->IsValid()) { - logger_.Error("Cannot open capture socket: interface is invalid"); + NFL_LOG_ERROR(logger_, "Cannot open capture socket: interface is invalid"); return; } @@ -164,7 +164,7 @@ RawSocket::RawSocket(const Interface& interface) // unfiltered frames (e.g. IGMP from multicast joins) would otherwise queue and reach the parser. fd_.Reset(socket(AF_PACKET, SOCK_RAW | SOCK_NONBLOCK, 0)); if (!fd_) { - logger_.Error("Cannot open AF_PACKET socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot open AF_PACKET socket: {}", Error::FromErrno()); return; } @@ -183,14 +183,14 @@ RawSocket::RawSocket(const Interface& interface) program = sock_fprog{.len = ETHERNET_UDP_FILTER.size(), .filter = reinterpret_cast(ETHERNET_UDP_FILTER.data())}; } else { - logger_.Info("PACKET_IGNORE_OUTGOING unavailable ({}); dropping our own frames in the BPF filter", + NFL_LOG_INFO(logger_, "PACKET_IGNORE_OUTGOING unavailable ({}); dropping our own frames in the BPF filter", Error::FromErrno()); std::ranges::copy(ETHERNET_UDP_FILTER, std::ranges::copy(DROP_OUTGOING_PROLOGUE, amended.begin()).out); program = sock_fprog{.len = amended.size(), .filter = reinterpret_cast(amended.data())}; } if (setsockopt(fd_.Get(), SOL_SOCKET, SO_ATTACH_FILTER, &program, sizeof(program)) != 0) { - logger_.Error("Cannot attach BPF UDP filter: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot attach BPF UDP filter: {}", Error::FromErrno()); Close(); return; } @@ -204,19 +204,19 @@ RawSocket::RawSocket(const Interface& interface) receive_buffer_.resize(MAX_FRAME_SIZE); - logger_.Debug("Opened AF_PACKET socket fd {} on interface", fd_.Get()); + NFL_LOG_DEBUG(logger_, "Opened AF_PACKET socket fd {} on interface", fd_.Get()); #else for (int n = 0; n < 256 && !fd_; ++n) { const auto path = std::format("/dev/bpf{}", n); fd_.Reset(open(path.c_str(), O_RDWR)); if (!fd_ && errno != EBUSY) { - logger_.Error("Cannot open {}: {}", path, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot open {}: {}", path, Error::FromErrno()); return; } } if (!fd_) { - logger_.Error("Cannot open any /dev/bpfN device"); + NFL_LOG_ERROR(logger_, "Cannot open any /dev/bpfN device"); return; } @@ -227,19 +227,19 @@ RawSocket::RawSocket(const Interface& interface) u_int blen = 0; if (ioctl(fd_.Get(), BIOCGBLEN, &blen) != 0) { - logger_.Error("Cannot query BPF buffer length: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot query BPF buffer length: {}", Error::FromErrno()); Close(); return; } receive_buffer_.resize(blen); if (!SetNonBlocking(fd_.Get())) { - logger_.Error("Cannot set BPF socket non-blocking: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set BPF socket non-blocking: {}", Error::FromErrno()); Close(); return; } - logger_.Debug("Opened BPF fd {} on interface (buffer {} bytes)", fd_.Get(), blen); + NFL_LOG_DEBUG(logger_, "Opened BPF fd {} on interface (buffer {} bytes)", fd_.Get(), blen); #endif } @@ -252,7 +252,7 @@ bool RawSocket::AttachToInterface() noexcept { addr.sll_protocol = htons(ETH_P_ALL); addr.sll_ifindex = static_cast(interface_->Index()); if (bind(fd_.Get(), reinterpret_cast(&addr), sizeof(addr)) != 0) { - logger_.Error("Cannot bind AF_PACKET socket to interface: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot bind AF_PACKET socket to interface: {}", Error::FromErrno()); return false; } return true; @@ -261,7 +261,7 @@ bool RawSocket::AttachToInterface() noexcept { // ifr is zero-initialized and Interface guarantees Name().size() < IFNAMSIZ. std::memcpy(ifr.ifr_name, interface_->Name().data(), interface_->Name().size()); if (ioctl(fd_.Get(), BIOCSETIF, &ifr) != 0) { - logger_.Error("Cannot bind BPF to interface: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot bind BPF to interface: {}", Error::FromErrno()); return false; } @@ -269,7 +269,7 @@ bool RawSocket::AttachToInterface() noexcept { // type, and the see-sent mode and filter below are both chosen from it. u_int dlt = 0; if (ioctl(fd_.Get(), BIOCGDLT, &dlt) != 0) { - logger_.Error("Cannot query BPF link type: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot query BPF link type: {}", Error::FromErrno()); return false; } if (dlt == DLT_EN10MB) { @@ -277,13 +277,13 @@ bool RawSocket::AttachToInterface() noexcept { } else if (dlt == DLT_NULL) { link_type_ = LinkType::Loopback; } else { - logger_.Error("BPF link type {} is not supported (need DLT_EN10MB or DLT_NULL)", dlt); + NFL_LOG_ERROR(logger_, "BPF link type {} is not supported (need DLT_EN10MB or DLT_NULL)", dlt); return false; } u_int immediate = 1; if (ioctl(fd_.Get(), BIOCIMMEDIATE, &immediate) != 0) { - logger_.Error("Cannot set BIOCIMMEDIATE: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set BIOCIMMEDIATE: {}", Error::FromErrno()); return false; } @@ -302,7 +302,7 @@ bool RawSocket::AttachToInterface() noexcept { // copy. Set both ways, so a re-attach onto different framing restores the right mode. u_int see_sent = link_type_ == LinkType::Ethernet ? 0 : 1; if (ioctl(fd_.Get(), BIOCSSEESENT, &see_sent) != 0) { - logger_.Error("Cannot set BIOCSSEESENT: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set BIOCSSEESENT: {}", Error::FromErrno()); return false; } @@ -315,7 +315,7 @@ bool RawSocket::AttachToInterface() noexcept { .bf_insns = reinterpret_cast(filter.data()), }; if (ioctl(fd_.Get(), BIOCSETF, &program) != 0) { - logger_.Error("Cannot attach BPF UDP filter: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot attach BPF UDP filter: {}", Error::FromErrno()); return false; } return true; @@ -356,7 +356,7 @@ bool RawSocket::Rebind() noexcept { int pending = 0; socklen_t length = sizeof(pending); if (getsockopt(fd_.Get(), SOL_SOCKET, SO_ERROR, &pending, &length) == 0 && pending != 0) { - logger_.Debug("Cleared a pending error on the re-bound capture: {}", Error::FromErrno(pending)); + NFL_LOG_DEBUG(logger_, "Cleared a pending error on the re-bound capture: {}", Error::FromErrno(pending)); } #else // BPF reset its buffer at the re-attach, so drop the drained-batch cursor to match rather @@ -364,7 +364,7 @@ bool RawSocket::Rebind() noexcept { receive_buffer_filled_ = 0; receive_buffer_offset_ = 0; #endif - logger_.Debug("Re-bound capture to interface index {}", interface_->Index()); + NFL_LOG_DEBUG(logger_, "Re-bound capture to interface index {}", interface_->Index()); // Nothing else re-joins them: a family that keeps its addresses across a recreation is no // transition, so the reflector's own bring-up never runs. return RejoinGroups(); @@ -411,7 +411,7 @@ bool RawSocket::SendFrame(MacAddress dst_mac, const IpEndpoint& dst, uint16_t sr std::span payload, uint8_t ttl) noexcept { const auto source = interface_->SourceAddressFor(dst.addr); if (!source) { - logger_.Error("Cannot send to {}: interface has no source address for that family", + NFL_LOG_ERROR(logger_, "Cannot send to {}: interface has no source address for that family", dst.addr); return false; } @@ -426,7 +426,7 @@ bool RawSocket::SendFrame(MacAddress dst_mac, const IpEndpoint& dst, uint16_t sr : BuildUdpFrame(dst_mac, interface_->Mac(), IpEndpoint{*source, src_port}, dst, payload, ttl, frame); #endif if (length == 0) { - logger_.Error("Cannot build egress frame for {} ({}-byte payload)", dst.addr, + NFL_LOG_ERROR(logger_, "Cannot build egress frame for {} ({}-byte payload)", dst.addr, payload.size()); return false; } @@ -443,7 +443,7 @@ bool RawSocket::SendFrame(MacAddress dst_mac, const IpEndpoint& dst, uint16_t sr const auto sent = write(fd_.Get(), frame.data(), length); #endif if (sent < 0 || static_cast(sent) != length) { - logger_.Error("Cannot inject datagram to {}: {}", dst.addr, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot inject datagram to {}: {}", dst.addr, Error::FromErrno()); return false; } return true; @@ -453,7 +453,7 @@ LinkSocket::MulticastMembership RawSocket::JoinMulticastGroup(const IpAddress& g // Index 0 is the kernel's "any interface" wildcard, so a parked interface would silently join // on whichever one the routing table picks. if (interface_->Index() == 0) { - logger_.Error("Cannot join multicast group {}: the interface is not resolvable", group); + NFL_LOG_ERROR(logger_, "Cannot join multicast group {}: the interface is not resolvable", group); return {}; } @@ -472,7 +472,7 @@ LinkSocket::MulticastMembership RawSocket::JoinMulticastGroup(const IpAddress& g if (opened_now) { join_fd.Reset(socket(v6 ? AF_INET6 : AF_INET, SOCK_DGRAM, 0)); if (!join_fd.IsValid()) { - logger_.Error("Cannot open multicast-join socket for {}: {}", group, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot open multicast-join socket for {}: {}", group, Error::FromErrno()); return {}; } } @@ -499,7 +499,7 @@ bool RawSocket::JoinInKernel(int join_fd, const IpAddress& group) noexcept { const int level = group.IsV6() ? IPPROTO_IPV6 : IPPROTO_IP; if (setsockopt(join_fd, level, MCAST_JOIN_GROUP, &request, sizeof(request)) == 0) { - logger_.Debug("Joined multicast group {} (interface index {})", group, interface_->Index()); + NFL_LOG_DEBUG(logger_, "Joined multicast group {} (interface index {})", group, interface_->Index()); return true; } @@ -510,10 +510,10 @@ bool RawSocket::JoinInKernel(int join_fd, const IpAddress& group) noexcept { if (error == EADDRNOTAVAIL) { // No address of this group's family yet: the family's teardown drops the membership, or // the repair retry replays the join once one arrives. A wait, not a failure. - logger_.Debug("Join of multicast group {} deferred: {}", group, Error::FromErrno(error)); + NFL_LOG_DEBUG(logger_, "Join of multicast group {} deferred: {}", group, Error::FromErrno(error)); return false; } - logger_.Error("Cannot join multicast group {}: {}", group, Error::FromErrno(error)); + NFL_LOG_ERROR(logger_, "Cannot join multicast group {}: {}", group, Error::FromErrno(error)); return false; } @@ -536,7 +536,7 @@ bool RawSocket::RejoinGroups() noexcept { join_fd.Reset(); join_fd.Reset(socket(family == IpAddress::Family::V6 ? AF_INET6 : AF_INET, SOCK_DGRAM, 0)); if (!join_fd.IsValid()) { - logger_.Error("Cannot reopen the multicast-join socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot reopen the multicast-join socket: {}", Error::FromErrno()); groups_joined_ = false; continue; } @@ -563,7 +563,7 @@ bool RawSocket::Unregister(const IpAddress& group) noexcept { if (!join_fd.IsValid()) { // The family's last group already left, or a rebind closed the socket and could not reopen // it. Closing is what drops the kernel membership, so the group is left either way. - logger_.Debug("Multicast group {} was already left with its join socket", group); + NFL_LOG_DEBUG(logger_, "Multicast group {} was already left with its join socket", group); return true; } @@ -575,9 +575,9 @@ bool RawSocket::Unregister(const IpAddress& group) noexcept { // us, so a later leave fails with the group already gone — the intended end state (not joined) // is reached either way, so this is Debug, not Error. if (setsockopt(join_fd.Get(), level, MCAST_LEAVE_GROUP, &request, sizeof(request)) != 0) { - logger_.Debug("Leave of multicast group {} did not apply: {}", group, Error::FromErrno()); + NFL_LOG_DEBUG(logger_, "Leave of multicast group {} did not apply: {}", group, Error::FromErrno()); } else { - logger_.Debug("Left multicast group {}", group); + NFL_LOG_DEBUG(logger_, "Left multicast group {}", group); } // The family's last group is gone, so free its join fd instead of carrying it for the socket's @@ -601,7 +601,7 @@ void RawSocket::ClearBuffer() noexcept { void RawSocket::Close() noexcept { if (fd_) { - logger_.Debug("Closing socket"); + NFL_LOG_DEBUG(logger_, "Closing socket"); fd_.Reset(); } // Drop the join fds and their membership bookkeeping together, so the "fd open iff the family @@ -632,11 +632,11 @@ std::expected RawSocket::Receive() noexcept { } // Reported for any non-would-block errno rather than a guessed list: this only asks the // owner to re-examine the interface, and Attached() is what decides. - logger_.Error("Cannot receive frame: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot receive frame: {}", Error::FromErrno()); return std::unexpected(ReceiveError::Failed); } if (static_cast(bytes) > receive_buffer_.size()) { - logger_.Warn("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", bytes, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -653,7 +653,7 @@ std::expected RawSocket::Receive() noexcept { if (IsWouldBlockErrno(errno)) { return std::unexpected(ReceiveError::WouldBlock); } - logger_.Error("Cannot receive frame: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot receive frame: {}", Error::FromErrno()); return std::unexpected(ReceiveError::Failed); } if (bytes == 0) { @@ -664,7 +664,7 @@ std::expected RawSocket::Receive() noexcept { } if (receive_buffer_offset_ + sizeof(bpf_hdr) > receive_buffer_filled_) { - logger_.Error("BPF batch truncated: {} bytes remaining, need at least {} for header", + NFL_LOG_ERROR(logger_, "BPF batch truncated: {} bytes remaining, need at least {} for header", receive_buffer_filled_ - receive_buffer_offset_, sizeof(bpf_hdr)); receive_buffer_offset_ = receive_buffer_filled_; return std::unexpected(ReceiveError::Dropped); @@ -675,7 +675,7 @@ std::expected RawSocket::Receive() noexcept { const auto frame_offset = receive_buffer_offset_ + header.bh_hdrlen; const auto frame_end = frame_offset + header.bh_caplen; if (frame_end > receive_buffer_filled_) { - logger_.Error("BPF frame extends past batch end (frame_end {} > filled {})", + NFL_LOG_ERROR(logger_, "BPF frame extends past batch end (frame_end {} > filled {})", frame_end, receive_buffer_filled_); receive_buffer_offset_ = receive_buffer_filled_; return std::unexpected(ReceiveError::Dropped); @@ -685,7 +685,7 @@ std::expected RawSocket::Receive() noexcept { // BPF captured fewer bytes than the frame's real length, so it didn't fit the buffer; drop it // rather than parse a truncated frame. (Offset already advanced to the next record above.) if (header.bh_datalen > header.bh_caplen) { - logger_.Warn("Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", header.bh_datalen, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -694,7 +694,7 @@ std::expected RawSocket::Receive() noexcept { // batch buffer admits frames the MAX_FRAME_SIZE-sized Linux scratch would have refused, so // enforce the same ceiling here at capture. if (header.bh_caplen > MAX_FRAME_SIZE) { - logger_.Warn("Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", + NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", header.bh_caplen, MAX_FRAME_SIZE); return std::unexpected(ReceiveError::Dropped); } @@ -718,7 +718,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no // DLT_NULL: 4-byte address family in host byte order, then the IP packet. No L2, // so MACs stay default-constructed (all zeros) — same shape we see on Linux's lo. if (frame.size() < LOOPBACK_FAMILY_SIZE) { - logger_.Error("Frame too short for DLT_NULL header: {} bytes", frame.size()); + NFL_LOG_ERROR(logger_, "Frame too short for DLT_NULL header: {} bytes", frame.size()); return std::nullopt; } uint32_t family = 0; @@ -728,7 +728,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no } else if (family == AF_INET6) { ethertype = IPV6_ETHERTYPE; } else { - logger_.Error("DLT_NULL frame with unsupported address family {}", family); + NFL_LOG_ERROR(logger_, "DLT_NULL frame with unsupported address family {}", family); return std::nullopt; } l3 = frame.subspan(LOOPBACK_FAMILY_SIZE); @@ -736,7 +736,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no #endif { if (frame.size() < ETHERNET_HEADER_SIZE) { - logger_.Error("Frame too short for Ethernet header: {} bytes", frame.size()); + NFL_LOG_ERROR(logger_, "Frame too short for Ethernet header: {} bytes", frame.size()); return std::nullopt; } ethertype = ReadU16Be(frame.subspan()); @@ -748,29 +748,29 @@ std::optional RawSocket::ParseFrame(std::span frame) no auto parse_l3 = [&]() -> std::optional>> { if (ethertype == IPV4_ETHERTYPE) { if (l3.size() < IPV4_HEADER_SIZE) { - logger_.Error("IPv4 payload too short for header: {} bytes", l3.size()); + NFL_LOG_ERROR(logger_, "IPv4 payload too short for header: {} bytes", l3.size()); return std::nullopt; } const auto version_ihl = std::to_integer(l3[0]); if ((version_ihl >> 4) != 4) { - logger_.Error("IPv4 ethertype with version field {}", version_ihl >> 4); + NFL_LOG_ERROR(logger_, "IPv4 ethertype with version field {}", version_ihl >> 4); return std::nullopt; } const auto ihl_words = version_ihl & 0x0f; const auto header_size = static_cast(ihl_words) * 4; if (header_size < IPV4_HEADER_SIZE || l3.size() < header_size) { - logger_.Error("IPv4 IHL {} words yields header size {} (l3 size {})", + NFL_LOG_ERROR(logger_, "IPv4 IHL {} words yields header size {} (l3 size {})", ihl_words, header_size, l3.size()); return std::nullopt; } const auto flags_fragment = ReadU16Be(l3.subspan<6, 2>()); // MF set or fragment offset non-zero indicates a fragment; reassembly is out of scope. if ((flags_fragment & 0x3fff) != 0) { - logger_.Debug("Dropping IPv4 fragment (flags/offset {:#x})", flags_fragment); + NFL_LOG_DEBUG(logger_, "Dropping IPv4 fragment (flags/offset {:#x})", flags_fragment); return std::nullopt; } if (std::to_integer(l3[9]) != IP_PROTO_UDP) { - logger_.Error("IPv4 protocol {} reached parser; BPF filter should have dropped it", + NFL_LOG_ERROR(logger_, "IPv4 protocol {} reached parser; BPF filter should have dropped it", std::to_integer(l3[9])); return std::nullopt; } @@ -779,7 +779,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no // could pull padding into the payload. const auto total_length = ReadU16Be(l3.subspan<2, 2>()); if (total_length < header_size || total_length > l3.size()) { - logger_.Error("IPv4 total_length {} invalid (header_size {}, l3 size {})", + NFL_LOG_ERROR(logger_, "IPv4 total_length {} invalid (header_size {}, l3 size {})", total_length, header_size, l3.size()); return std::nullopt; } @@ -792,24 +792,24 @@ std::optional RawSocket::ParseFrame(std::span frame) no } if (ethertype == IPV6_ETHERTYPE) { if (l3.size() < IPV6_HEADER_SIZE) { - logger_.Error("IPv6 payload too short for header: {} bytes", l3.size()); + NFL_LOG_ERROR(logger_, "IPv6 payload too short for header: {} bytes", l3.size()); return std::nullopt; } const auto version = std::to_integer(l3[0]) >> 4; if (version != 6) { - logger_.Error("IPv6 ethertype with version field {}", version); + NFL_LOG_ERROR(logger_, "IPv6 ethertype with version field {}", version); return std::nullopt; } const auto next_header = std::to_integer(l3[6]); // Extension headers (Fragment, Hop-by-Hop, Routing, ...) all fail this check. if (next_header != IP_PROTO_UDP) { - logger_.Debug("Dropping IPv6 packet with next-header {} (extension header or non-UDP)", next_header); + NFL_LOG_DEBUG(logger_, "Dropping IPv6 packet with next-header {} (extension header or non-UDP)", next_header); return std::nullopt; } // Trim by payload_length for the same reason as IPv4 total_length above. const auto payload_length = ReadU16Be(l3.subspan<4, 2>()); if (IPV6_HEADER_SIZE + payload_length > l3.size()) { - logger_.Error("IPv6 payload_length {} exceeds captured size (l3 size {})", + NFL_LOG_ERROR(logger_, "IPv6 payload_length {} exceeds captured size (l3 size {})", payload_length, l3.size()); return std::nullopt; } @@ -820,7 +820,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no l3.subspan(IPV6_HEADER_SIZE, payload_length), }; } - logger_.Error("Frame ethertype {:#x} reached parser; BPF filter should have dropped it", ethertype); + NFL_LOG_ERROR(logger_, "Frame ethertype {:#x} reached parser; BPF filter should have dropped it", ethertype); return std::nullopt; }; @@ -831,14 +831,14 @@ std::optional RawSocket::ParseFrame(std::span frame) no const auto& [source_ip, dest_ip, ttl, l4] = *l3_parsed; if (l4.size() < UDP_HEADER_SIZE) { - logger_.Error("L4 payload too short for UDP header: {} bytes", l4.size()); + NFL_LOG_ERROR(logger_, "L4 payload too short for UDP header: {} bytes", l4.size()); return std::nullopt; } const auto source_port = ReadU16Be(l4.subspan<0, 2>()); const auto dest_port = ReadU16Be(l4.subspan<2, 2>()); const auto udp_length = ReadU16Be(l4.subspan<4, 2>()); if (udp_length < UDP_HEADER_SIZE || udp_length > l4.size()) { - logger_.Warn("UDP length {} invalid (header min {}, l4 size {})", + NFL_LOG_WARN(logger_, "UDP length {} invalid (header min {}, l4 size {})", udp_length, UDP_HEADER_SIZE, l4.size()); return std::nullopt; } diff --git a/src/reflector/ssdp_message.cpp b/src/reflector/ssdp_message.cpp index f055a28..5587b9c 100644 --- a/src/reflector/ssdp_message.cpp +++ b/src/reflector/ssdp_message.cpp @@ -156,7 +156,7 @@ std::optional ParseDialLocationAuthority(std::span p if (!found) { // A DIAL message carrying a LOCATION we cannot rewrite (an https URL, a hostname rather than // an IPv4 literal, or a malformed port). The caller forwards it unchanged, so surface why. - GetLogger().Info("DIAL LOCATION \"{}\" is not a rewritable http://ip:port URL", url); + NFL_LOG_INFO(GetLogger(), "DIAL LOCATION \"{}\" is not a rewritable http://ip:port URL", url); return std::nullopt; } // Map the authority's offset within the URL back to an offset within the whole payload. diff --git a/src/reflector/ssdp_reflector.cpp b/src/reflector/ssdp_reflector.cpp index d73e373..34030ba 100644 --- a/src/reflector/ssdp_reflector.cpp +++ b/src/reflector/ssdp_reflector.cpp @@ -46,7 +46,7 @@ SsdpReflector::SsdpReflector(PacketDispatcher& packet_dispatcher, LinkSocket& so bool SsdpReflector::ValidateConfig(const SsdpConfig& config) { if (const auto error = config.Verify()) { - logger_.Error("Cannot create ssdp reflector \"{}\": invalid config: {}", config.name, *error); + NFL_LOG_ERROR(logger_, "Cannot create ssdp reflector \"{}\": invalid config: {}", config.name, *error); return false; } return true; @@ -54,7 +54,7 @@ bool SsdpReflector::ValidateConfig(const SsdpConfig& config) { void SsdpReflector::Initialize(const SsdpConfig& config) { if (config.mac && !target_socket_->LinkCarriesMacs()) { - logger_.Error("Cannot create ssdp reflector \"{}\": mac cannot match on \"{}\" (the link carries no MAC addresses)", + NFL_LOG_ERROR(logger_, "Cannot create ssdp reflector \"{}\": mac cannot match on \"{}\" (the link carries no MAC addresses)", config.name, config.target_if); return; } @@ -62,12 +62,12 @@ void SsdpReflector::Initialize(const SsdpConfig& config) { // tracks the AND): the target re-emits reflected searches, the source re-emits advertisements. // A required family must already be reflectable; an optional one comes up later if it ever is. if (config.RequiresIPv4() && !capability_.CanSend(IpAddress::Family::V4)) { - logger_.Error("Cannot create ssdp reflector \"{}\": IPv4 requires a source address on both \"{}\" and \"{}\"", + NFL_LOG_ERROR(logger_, "Cannot create ssdp reflector \"{}\": IPv4 requires a source address on both \"{}\" and \"{}\"", config.name, config.source_if, config.target_if); return; } if (config.RequiresIPv6() && !capability_.CanSend(IpAddress::Family::V6)) { - logger_.Error("Cannot create ssdp reflector \"{}\": IPv6 requires a source address on both \"{}\" and \"{}\"", + NFL_LOG_ERROR(logger_, "Cannot create ssdp reflector \"{}\": IPv6 requires a source address on both \"{}\" and \"{}\"", config.name, config.source_if, config.target_if); return; } @@ -87,7 +87,7 @@ void SsdpReflector::Initialize(const SsdpConfig& config) { } valid_ = true; - logger_.Info("Created ssdp reflector (IPv4: {}, IPv6: {}, DIAL: {})", + NFL_LOG_INFO(logger_, "Created ssdp reflector (IPv4: {}, IPv6: {}, DIAL: {})", capability_.CanSend(IpAddress::Family::V4) ? "enabled" : "disabled", capability_.CanSend(IpAddress::Family::V6) ? "enabled" : "disabled", config.dial ? "enabled" : "disabled"); @@ -123,7 +123,7 @@ bool SsdpReflector::SetUpGroup(const IpAddress& group, FamilySetup& setup) { auto source_membership = source_socket_->JoinMulticastGroup(group); auto target_membership = target_socket_->JoinMulticastGroup(group); if (!source_membership.IsValid() || !target_membership.IsValid()) { - logger_.Error("Cannot reflect ssdp {}: cannot join the group on both interfaces", group); + NFL_LOG_ERROR(logger_, "Cannot reflect ssdp {}: cannot join the group on both interfaces", group); return false; } @@ -132,7 +132,7 @@ bool SsdpReflector::SetUpGroup(const IpAddress& group, FamilySetup& setup) { PacketFilter{.dest_ip = group, .dest_port = SSDP_PORT}, CreateDelegate<&SsdpReflector::OnSourcePacket>(this)); if (!source_registration.IsValid()) { - logger_.Error("Cannot reflect ssdp {}: registration failed (source)", group); + NFL_LOG_ERROR(logger_, "Cannot reflect ssdp {}: registration failed (source)", group); return false; } @@ -141,7 +141,7 @@ bool SsdpReflector::SetUpGroup(const IpAddress& group, FamilySetup& setup) { PacketFilter{.dest_ip = group, .dest_port = SSDP_PORT, .source_mac = config_mac_}, CreateDelegate<&SsdpReflector::OnTargetPacket>(this)); if (!target_registration.IsValid()) { - logger_.Error("Cannot reflect ssdp {}: registration failed (target)", group); + NFL_LOG_ERROR(logger_, "Cannot reflect ssdp {}: registration failed (target)", group); return false; } @@ -162,7 +162,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { if (!parsed_mx) { // A multicast M-SEARCH must carry MX (UDA 2.0), but this fires on every search including // retransmits — one non-conformant client would flood any louder level. - logger_.Debug("M-SEARCH from {} has no/invalid MX; using the default {}s window", + NFL_LOG_DEBUG(logger_, "M-SEARCH from {} has no/invalid MX; using the default {}s window", packet.header.source, static_cast(mx)); } const auto expiry = std::chrono::steady_clock::now() + std::chrono::seconds{mx} + SESSION_GRACE; @@ -186,10 +186,10 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { : existing_session->reservation.Port(); if (!target_socket_->SendUdpMulticastDatagram(packet.header.dest, port, packet.payload, SSDP_TTL)) { - logger_.Error("Cannot reflect M-SEARCH from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {} to {}", packet.header.source, packet.header.dest); return; // a new session's reservation + response registration RAII-drop here } - logger_.Debug("Reflected M-SEARCH from {} on reserved port {} (MX {}s)", + NFL_LOG_DEBUG(logger_, "Reflected M-SEARCH from {} on reserved port {} (MX {}s)", packet.header.source, port, static_cast(mx)); if (!new_session) { @@ -198,7 +198,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { } sessions_.push_back(std::move(*new_session)); - logger_.Debug("Created session for searcher {} on reserved port {}; {} active", + NFL_LOG_DEBUG(logger_, "Created session for searcher {} on reserved port {}; {} active", packet.header.source, port, sessions_.size()); // Start the eviction sweep on the first in-flight session; EvictExpired stops it once the table // empties, so the reactor isn't woken every interval while there's nothing to sweep. @@ -210,7 +210,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { std::optional SsdpReflector::MakeSession(const Packet& packet, std::chrono::steady_clock::time_point expiry) { if (sessions_.size() >= MAX_SESSIONS) { - logger_.Warn("Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", + NFL_LOG_WARN(logger_, "Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", packet.header.source, sessions_.size()); return std::nullopt; } @@ -219,7 +219,7 @@ std::optional SsdpReflector::MakeSession(const Packet& p // that re-emit — so responders' unicast 200-OKs land on the reserved address. const auto our_address = target_interface.SourceAddressFor(packet.header.dest.addr); if (!our_address) { - logger_.Error("Cannot reflect M-SEARCH from {}: target interface has no source address for {}", + NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {}: target interface has no source address for {}", packet.header.source, packet.header.dest.addr.AddressFamily()); return std::nullopt; } @@ -232,7 +232,7 @@ std::optional SsdpReflector::MakeSession(const Packet& p PacketFilter{.dest_ip = our_address, .dest_port = reservation->Port(), .source_mac = config_mac_}, CreateDelegate<&SsdpReflector::OnUnicastResponse>(this)); if (!registration.IsValid()) { - logger_.Error("Cannot reflect M-SEARCH from {}: response registration failed", + NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {}: response registration failed", packet.header.source); return std::nullopt; // reservation RAII-drops here, freeing the port } @@ -263,10 +263,10 @@ void SsdpReflector::OnTargetPacket(const Packet& packet) noexcept { ? std::as_bytes(std::span{rewrite.payload}) : packet.payload; if (!source_socket_->SendUdpMulticastDatagram(packet.header.dest, SSDP_PORT, payload, SSDP_TTL)) { - logger_.Error("Cannot reflect ssdp packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR(logger_, "Cannot reflect ssdp packet from {} to {}", packet.header.source, packet.header.dest); return; } - logger_.Debug("Reflected ssdp packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_DEBUG(logger_, "Reflected ssdp packet from {} to {}", packet.header.source, packet.header.dest); } void SsdpReflector::OnUnicastResponse(const Packet& packet) noexcept { @@ -296,10 +296,10 @@ void SsdpReflector::OnUnicastResponse(const Packet& packet) noexcept { : packet.payload; if (!source_socket_->SendUdpDatagram(session.searcher_mac, session.searcher, packet.header.source.port, payload, SSDP_TTL)) { - logger_.Error("Cannot reflect SSDP response to searcher {}", session.searcher); + NFL_LOG_ERROR(logger_, "Cannot reflect SSDP response to searcher {}", session.searcher); return; } - logger_.Debug("Reflected SSDP response from {} to searcher {}", packet.header.source, + NFL_LOG_DEBUG(logger_, "Reflected SSDP response from {} to searcher {}", packet.header.source, session.searcher); } @@ -309,7 +309,7 @@ bool SsdpReflector::ShouldReflect(const Packet& packet, SsdpMessageKind kind) no // The group + port 1900 should carry only SSDP requests, so a payload that is neither an // M-SEARCH nor a NOTIFY (e.g. a stray unicast 200 OK, or junk) is anomalous and worth // surfacing. A message of the other kind, by contrast, is normal and dropped silently. - logger_.Info("Ignoring non-SSDP packet on {} from {}: not an M-SEARCH or NOTIFY", + NFL_LOG_INFO(logger_, "Ignoring non-SSDP packet on {} from {}: not an M-SEARCH or NOTIFY", packet.header.dest, packet.header.source); return false; } @@ -328,7 +328,7 @@ SsdpReflector::DialRewrite SsdpReflector::RewriteDialLocation(std::spanEnsureDiscoveryListener(location->endpoint, max_age.transform([](uint32_t seconds) { return std::chrono::seconds{seconds}; })); if (!reflector_authority) { - logger_.Info("DIAL: no listener for device {} (cap/bind); forwarding its LOCATION unchanged", + NFL_LOG_INFO(logger_, "DIAL: no listener for device {} (cap/bind); forwarding its LOCATION unchanged", location->endpoint); return {}; } @@ -344,7 +344,7 @@ SsdpReflector::DialRewrite SsdpReflector::RewriteDialLocation(std::span(payload.data()), payload.size()}; const size_t rewritten_size = original.size() - location->length + authority.size(); if (rewritten_size > MAX_UDP_PAYLOAD_SIZE) { - logger_.Error("DIAL: rewritten LOCATION for {} overflows the {}-byte payload ceiling; dropping the datagram", + NFL_LOG_ERROR(logger_, "DIAL: rewritten LOCATION for {} overflows the {}-byte payload ceiling; dropping the datagram", location->endpoint, MAX_UDP_PAYLOAD_SIZE); return {.action = DialRewrite::Action::Drop}; } @@ -356,7 +356,7 @@ SsdpReflector::DialRewrite SsdpReflector::RewriteDialLocation(std::spanoffset + location->length); - logger_.Debug("DIAL: rewrote device {} LOCATION to reflector listener {}", + NFL_LOG_DEBUG(logger_, "DIAL: rewrote device {} LOCATION to reflector listener {}", location->endpoint, *reflector_authority); return {.action = DialRewrite::Action::ForwardRewritten, .payload = rewrite_scratch_}; } @@ -379,7 +379,7 @@ void SsdpReflector::EvictStaleSessions() noexcept { if (removed == 0) { return; } - logger_.Info("Dropped {} search session(s) whose reserved address on the target is gone", removed); + NFL_LOG_INFO(logger_, "Dropped {} search session(s) whose reserved address on the target is gone", removed); if (sessions_.empty()) { eviction_timer_.Stop(); // nothing left to sweep } @@ -389,13 +389,13 @@ void SsdpReflector::EvictExpired(std::chrono::steady_clock::time_point now) noex const auto removed = std::erase_if(sessions_, [this, now](const Session& session) { const bool expired = session.expiry <= now; if (expired) { - logger_.Debug("Removing session for searcher {} on reserved port {}", + NFL_LOG_DEBUG(logger_, "Removing session for searcher {} on reserved port {}", session.searcher, session.reservation.Port()); } return expired; }); if (removed > 0) { - logger_.Debug("Evicted {} session(s); {} still active", removed, sessions_.size()); + NFL_LOG_DEBUG(logger_, "Evicted {} session(s); {} still active", removed, sessions_.size()); } if (sessions_.empty()) { // Nothing left to sweep: stop. Safe self-unregister — the dispatcher defers a mid-fire diff --git a/src/reflector/tcp_socket.cpp b/src/reflector/tcp_socket.cpp index f623db4..79df026 100644 --- a/src/reflector/tcp_socket.cpp +++ b/src/reflector/tcp_socket.cpp @@ -32,13 +32,13 @@ Logger& GetLogger() noexcept { // is set once here instead. [[nodiscard]] bool ConfigureFd(int fd) noexcept { if (!SetNonBlocking(fd)) { - GetLogger().Error("Cannot set socket non-blocking: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set socket non-blocking: {}", Error::FromErrno()); return false; } #if !defined(__linux__) const int on = 1; if (::setsockopt(fd, SOL_SOCKET, SO_NOSIGPIPE, &on, sizeof(on)) != 0) { - GetLogger().Error("Cannot set SO_NOSIGPIPE: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set SO_NOSIGPIPE: {}", Error::FromErrno()); return false; } #endif @@ -50,7 +50,7 @@ Logger& GetLogger() noexcept { [[nodiscard]] bool SetNoDelay(int fd) noexcept { const int on = 1; if (::setsockopt(fd, IPPROTO_TCP, TCP_NODELAY, &on, sizeof(on)) != 0) { - GetLogger().Error("Cannot set TCP_NODELAY: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set TCP_NODELAY: {}", Error::FromErrno()); return false; } return true; @@ -64,7 +64,7 @@ Logger& GetLogger() noexcept { #if defined(__linux__) const auto name = egress_if.Name(); if (::setsockopt(fd, SOL_SOCKET, SO_BINDTODEVICE, name.data(), narrow_cast(name.size())) != 0) { - GetLogger().Error("Cannot pin egress to interface \"{}\": {}", name, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot pin egress to interface \"{}\": {}", name, Error::FromErrno()); return false; } #elif defined(__APPLE__) @@ -72,7 +72,7 @@ Logger& GetLogger() noexcept { const int level = family == AF_INET6 ? IPPROTO_IPV6 : IPPROTO_IP; const int optname = family == AF_INET6 ? IPV6_BOUND_IF : IP_BOUND_IF; if (::setsockopt(fd, level, optname, &ifindex, sizeof(ifindex)) != 0) { - GetLogger().Error("Cannot pin egress to interface index {}: {}", ifindex, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot pin egress to interface index {}: {}", ifindex, Error::FromErrno()); return false; } #else @@ -80,7 +80,7 @@ Logger& GetLogger() noexcept { // the source-address bind the caller performs before connect() (and, for link-local IPv6, the scope // id in the destination sockaddr). Correct when the peer is on a directly-connected subnet of // egress_if — the route to it then leaves via egress_if anyway; otherwise the routing table decides. - GetLogger().Debug("No egress-pin primitive; relying on source-address bind to reach via \"{}\"", + NFL_LOG_DEBUG(GetLogger(), "No egress-pin primitive; relying on source-address bind to reach via \"{}\"", egress_if.Name()); #endif return true; @@ -92,7 +92,7 @@ Logger& GetLogger() noexcept { sockaddr_storage addr{}; socklen_t len = sizeof(addr); if (::getsockname(fd, reinterpret_cast(&addr), &len) != 0) { - GetLogger().Error("Cannot read local endpoint for fd {}: {}", fd, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot read local endpoint for fd {}: {}", fd, Error::FromErrno()); return std::nullopt; } // getsockname filled the bytes; begin a sockaddr's lifetime over them for FromSockaddr's @@ -143,7 +143,7 @@ void TcpSocket::Shutdown() noexcept { void TcpSocket::Close() noexcept { if (fd_) { - logger_.Debug("Closing socket"); + NFL_LOG_DEBUG(logger_, "Closing socket"); fd_.Reset(); } } @@ -152,7 +152,7 @@ std::optional TcpSocket::Listen(const Interface& iface, IpAddress::Fa uint16_t port) { const auto address = iface.SourceAddress(family); if (!address) { - GetLogger().Error("Cannot listen on \"{}\": the interface has no {} source address", + NFL_LOG_ERROR(GetLogger(), "Cannot listen on \"{}\": the interface has no {} source address", iface.Name(), family); return std::nullopt; } @@ -160,7 +160,7 @@ std::optional TcpSocket::Listen(const Interface& iface, IpAddress::Fa const int af = bind.addr.IsV6() ? AF_INET6 : AF_INET; const int fd = ::socket(af, SOCK_STREAM, 0); if (fd < 0) { - GetLogger().Error("Cannot create listening socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot create listening socket: {}", Error::FromErrno()); return std::nullopt; } const int on = 1; @@ -169,7 +169,7 @@ std::optional TcpSocket::Listen(const Interface& iface, IpAddress::Fa return std::nullopt; } if (::setsockopt(fd, SOL_SOCKET, SO_REUSEADDR, &on, sizeof(on)) != 0) { - GetLogger().Error("Cannot set SO_REUSEADDR: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot set SO_REUSEADDR: {}", Error::FromErrno()); ::close(fd); return std::nullopt; } @@ -177,7 +177,7 @@ std::optional TcpSocket::Listen(const Interface& iface, IpAddress::Fa const socklen_t len = bind.ToSockaddr(addr, iface.Index()); if (::bind(fd, reinterpret_cast(&addr), len) != 0 || ::listen(fd, SOMAXCONN) != 0) { - GetLogger().Error("Cannot bind/listen on {}: {}", bind, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot bind/listen on {}: {}", bind, Error::FromErrno()); ::close(fd); return std::nullopt; } @@ -197,7 +197,7 @@ std::optional TcpSocket::Connect(const IpEndpoint& dst, const Interfa const auto family = dst.addr.AddressFamily(); const auto source = egress_if->SourceAddress(family); if (!source) { - GetLogger().Error("Cannot connect to {}: interface \"{}\" has no {} source address", + NFL_LOG_ERROR(GetLogger(), "Cannot connect to {}: interface \"{}\" has no {} source address", dst, egress_if->Name(), family); return std::nullopt; } @@ -206,7 +206,7 @@ std::optional TcpSocket::Connect(const IpEndpoint& dst, const Interfa const int af = dst.addr.IsV6() ? AF_INET6 : AF_INET; const int fd = ::socket(af, SOCK_STREAM, 0); if (fd < 0) { - GetLogger().Error("Cannot create connect socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot create connect socket: {}", Error::FromErrno()); return std::nullopt; } const unsigned scope_id = egress_if != nullptr ? egress_if->Index() : 0; @@ -218,7 +218,7 @@ std::optional TcpSocket::Connect(const IpEndpoint& dst, const Interfa sockaddr_storage src{}; const socklen_t src_len = bind->ToSockaddr(src, scope_id); if (::bind(fd, reinterpret_cast(&src), src_len) != 0) { - GetLogger().Error("Cannot bind connect source to {}: {}", *bind, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot bind connect source to {}: {}", *bind, Error::FromErrno()); ::close(fd); return std::nullopt; } @@ -226,7 +226,7 @@ std::optional TcpSocket::Connect(const IpEndpoint& dst, const Interfa sockaddr_storage dest{}; const socklen_t dest_len = dst.ToSockaddr(dest, scope_id); if (::connect(fd, reinterpret_cast(&dest), dest_len) != 0 && errno != EINPROGRESS) { - GetLogger().Error("Cannot connect to {}: {}", dst, Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot connect to {}: {}", dst, Error::FromErrno()); ::close(fd); return std::nullopt; } @@ -251,7 +251,7 @@ std::optional TcpSocket::Accept() noexcept { #endif if (client < 0) { if (!IsWouldBlockErrno(errno)) { - GetLogger().Error("Cannot accept connection: {}", Error::FromErrno()); + NFL_LOG_ERROR(GetLogger(), "Cannot accept connection: {}", Error::FromErrno()); } return std::nullopt; } @@ -282,11 +282,11 @@ bool TcpSocket::FinishConnect() noexcept { int so_error = 0; socklen_t len = sizeof(so_error); if (::getsockopt(fd_.Get(), SOL_SOCKET, SO_ERROR, &so_error, &len) != 0) { - logger_.Error("Cannot read SO_ERROR: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot read SO_ERROR: {}", Error::FromErrno()); return false; } if (so_error != 0) { - logger_.Error("Connect failed: {}", Error::FromErrno(so_error)); + NFL_LOG_ERROR(logger_, "Connect failed: {}", Error::FromErrno(so_error)); return false; } connecting_ = false; @@ -310,7 +310,7 @@ IoResult TcpSocket::Read(std::span out) noexcept { if (IsWouldBlockErrno(errno)) { return {IoStatus::WouldBlock, 0}; } - logger_.Error("Receive failed: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Receive failed: {}", Error::FromErrno()); return {IoStatus::Error, 0}; } @@ -338,7 +338,7 @@ IoResult TcpSocket::WriteSome(std::span data) noexcept { return {IoStatus::WouldBlock, 0}; } #endif - logger_.Error("Send failed: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Send failed: {}", Error::FromErrno()); return {IoStatus::Error, 0}; } @@ -380,7 +380,7 @@ IoResult TcpSocket::WriteSomeV(std::span> chunk return {IoStatus::WouldBlock, 0}; } #endif - logger_.Error("Send failed: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Send failed: {}", Error::FromErrno()); return {IoStatus::Error, 0}; } @@ -399,12 +399,12 @@ SendStatus TcpSocket::Send(std::span data) noexcept { } } if (!send_buffer_.Append(data)) { - logger_.Error("Send buffer overflow: {} queued + {}-byte tail exceeds the {}-byte cap", + NFL_LOG_ERROR(logger_, "Send buffer overflow: {} queued + {}-byte tail exceeds the {}-byte cap", send_buffer_.Size(), data.size(), MAX_SEND_BUFFER); return SendStatus::Overflow; // tail would exceed the cap — owner aborts the connection (drop-and-close) } if (!was_buffering) { - logger_.Debug("Started buffering, {} bytes queued", send_buffer_.Size()); + NFL_LOG_DEBUG(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); } return SendStatus::Ok; } @@ -414,7 +414,7 @@ SendStatus TcpSocket::Send(std::span> chunks) n // buffers and flushes on later writable edges — but a caller only ever passes a header + body (2 chunks), // so a scatter this large is unexpected: warn and carry on. if (chunks.size() > MAX_SEND_CHUNKS) { - logger_.Warn("Scatter-send of {} chunks exceeds the {}-chunk sendmsg cap; the overflow " + NFL_LOG_WARN(logger_, "Scatter-send of {} chunks exceeds the {}-chunk sendmsg cap; the overflow " "buffers and flushes on later writable edges", chunks.size(), MAX_SEND_CHUNKS); } // Write through only when nothing is already queued; otherwise the chunks follow the backlog in order @@ -434,12 +434,12 @@ SendStatus TcpSocket::Send(std::span> chunks) n for (const std::span chunk : chunks) { total += chunk.size(); } - logger_.Error("Send buffer overflow: {} queued + {}-byte tail exceeds the {}-byte cap", + NFL_LOG_ERROR(logger_, "Send buffer overflow: {} queued + {}-byte tail exceeds the {}-byte cap", backlog, total - already_sent, MAX_SEND_BUFFER); return SendStatus::Overflow; // tail would exceed the cap — owner aborts the connection (drop-and-close) } if (!was_buffering && !send_buffer_.Empty()) { - logger_.Debug("Started buffering, {} bytes queued", send_buffer_.Size()); + NFL_LOG_DEBUG(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); } return SendStatus::Ok; } @@ -474,7 +474,7 @@ bool TcpSocket::Flush() noexcept { send_buffer_.Consume(wrote.bytes); } if (was_buffering && send_buffer_.Empty()) { - logger_.Debug("Send buffer drained, resumed direct writes"); + NFL_LOG_DEBUG(logger_, "Send buffer drained, resumed direct writes"); } return true; } diff --git a/src/reflector/wol_reflector.cpp b/src/reflector/wol_reflector.cpp index 4a8541c..504d3ca 100644 --- a/src/reflector/wol_reflector.cpp +++ b/src/reflector/wol_reflector.cpp @@ -34,7 +34,7 @@ WolReflector::WolReflector(PacketDispatcher& packet_dispatcher, LinkSocket& sour bool WolReflector::ValidateConfig(const WolConfig& config) { if (const auto error = config.Verify()) { - logger_.Error("Cannot create wol reflector \"{}\": invalid config: {}", config.name, *error); + NFL_LOG_ERROR(logger_, "Cannot create wol reflector \"{}\": invalid config: {}", config.name, *error); return false; } return true; @@ -43,12 +43,12 @@ bool WolReflector::ValidateConfig(const WolConfig& config) { void WolReflector::Initialize(PacketDispatcher& packet_dispatcher, LinkSocket& source_socket, const WolConfig& config) { const auto& target_interface = target_socket_->GetInterface(); if (config.RequiresIPv4() && !target_interface.CanSend(IpAddress::Family::V4)) { - logger_.Error("Cannot create wol reflector \"{}\": target_if \"{}\" cannot send IPv4", + NFL_LOG_ERROR(logger_, "Cannot create wol reflector \"{}\": target_if \"{}\" cannot send IPv4", config.name, config.target_if); return; } if (config.RequiresIPv6() && !target_interface.CanSend(IpAddress::Family::V6)) { - logger_.Error("Cannot create wol reflector \"{}\": target_if \"{}\" cannot send IPv6", + NFL_LOG_ERROR(logger_, "Cannot create wol reflector \"{}\": target_if \"{}\" cannot send IPv6", config.name, config.target_if); return; } @@ -65,7 +65,7 @@ void WolReflector::Initialize(PacketDispatcher& packet_dispatcher, LinkSocket& s auto registration = packet_dispatcher.Register(source_socket, PacketFilter{.dest_port = port}, CreateDelegate<&WolReflector::OnPacket>(this)); if (!registration.IsValid()) { - logger_.Error("Cannot create wol reflector \"{}\": registration failed for port {}", + NFL_LOG_ERROR(logger_, "Cannot create wol reflector \"{}\": registration failed for port {}", config.name, port); registrations_.clear(); return; @@ -74,7 +74,7 @@ void WolReflector::Initialize(PacketDispatcher& packet_dispatcher, LinkSocket& s } valid_ = true; - logger_.Info("Created wol reflector (IPv4: {}, IPv6: {})", + NFL_LOG_INFO(logger_, "Created wol reflector (IPv4: {}, IPv6: {})", target_capability_.CanSend(IpAddress::Family::V4) ? "enabled" : "disabled", target_capability_.CanSend(IpAddress::Family::V6) ? "enabled" : "disabled"); } @@ -86,25 +86,25 @@ void WolReflector::Initialize(PacketDispatcher& packet_dispatcher, LinkSocket& s // single memcmp and narrows what this reflector will re-broadcast onto target_if. bool WolReflector::IsMagicPacket(std::span payload) noexcept { if (payload.size() < MAGIC_PACKET_SIZE) { - logger_.Debug("Ignoring wol packet: payload is too short: {} bytes", payload.size()); + NFL_LOG_DEBUG(logger_, "Ignoring wol packet: payload is too short: {} bytes", payload.size()); return false; } if (target_mac_) { if (std::memcmp(payload.data(), expected_magic_packet_.data(), expected_magic_packet_.size()) != 0) { - logger_.Debug("Ignoring wol packet: magic packet does not match expected MAC"); + NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet does not match expected MAC"); return false; } return true; } if (!HasMagicPacketPrefix(payload)) { - logger_.Debug("Ignoring wol packet: magic packet prefix is invalid"); + NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet prefix is invalid"); return false; } if (!HasRepeatedMac(payload)) { - logger_.Debug("Ignoring wol packet: magic packet MAC repetitions are inconsistent"); + NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet MAC repetitions are inconsistent"); return false; } @@ -146,7 +146,7 @@ void WolReflector::OnPacket(const Packet& packet) noexcept { const auto family = packet.header.source.addr.AddressFamily(); if (!target_capability_.CanSend(family)) { - logger_.Debug("Ignoring wol packet from {}: {} not handled", + NFL_LOG_DEBUG(logger_, "Ignoring wol packet from {}: {} not handled", packet.header.source, family); return; } @@ -163,7 +163,7 @@ void WolReflector::OnPacket(const Packet& packet) noexcept { : target_socket_->SendUdpMulticastDatagram( {destination, port}, packet.header.source.port, packet.payload, packet.header.ttl); if (!sent) { - logger_.Error("Cannot reflect wol packet from {} to {}:{}", + NFL_LOG_ERROR(logger_, "Cannot reflect wol packet from {} to {}:{}", packet.header.source, destination, port); return; } @@ -171,7 +171,7 @@ void WolReflector::OnPacket(const Packet& packet) noexcept { // The MAC comes from the payload, not the frame's L2 header: it names the device that // will wake, and IsMagicPacket has already validated the payload is long enough. const auto target = MacAddress::FromBytes(packet.payload.subspan()); - logger_.Info("Reflected WoL packet for {} from {} to {}:{}", + NFL_LOG_INFO(logger_, "Reflected WoL packet for {} from {} to {}:{}", target, packet.header.source, destination, port); } diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index adc7ed6..95ab973 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -34,10 +34,10 @@ TEST(LoggerTest, MinLevelSuppressesLowerSeverityMessages) { Logger logger{"LoggerTest"}; const std::string output = CaptureStdout([&] { - logger.Debug("hidden debug message"); - logger.Info("hidden info message"); - logger.Warn("visible warning message"); - logger.Error("visible error message"); + NFL_LOG_DEBUG(logger, "hidden debug message"); + NFL_LOG_INFO(logger, "hidden info message"); + NFL_LOG_WARN(logger, "visible warning message"); + NFL_LOG_ERROR(logger, "visible error message"); }); EXPECT_EQ(output.find("hidden debug message"), std::string::npos) << output; @@ -51,7 +51,7 @@ TEST(LoggerTest, NameAppearsInOutput) { Logger logger{"NamedLogger"}; const std::string output = CaptureStdout([&] { - logger.Info("message from a named logger"); + NFL_LOG_INFO(logger, "message from a named logger"); }); EXPECT_NE(output.find("[NamedLogger]"), std::string::npos) << output; @@ -67,8 +67,8 @@ TEST(LoggerTest, NameSurvivesMoveConstructionAndAssignment) { move_assigned_target = std::move(assigned_from); const std::string output = CaptureStdout([&] { - move_constructed.Info("message from the move constructed logger"); - move_assigned_target.Info("message from the move assigned logger"); + NFL_LOG_INFO(move_constructed, "message from the move constructed logger"); + NFL_LOG_INFO(move_assigned_target, "message from the move assigned logger"); }); EXPECT_NE(output.find("[MoveConstructedLogger]"), std::string::npos) << output; @@ -86,8 +86,8 @@ TEST(LoggerTest, DynamicNameSurvivesMoveConstructionAndAssignment) { move_assigned_target = std::move(assigned_from); const std::string output = CaptureStdout([&] { - move_constructed.Info("message from move constructed dynamic logger"); - move_assigned_target.Info("message from move assigned dynamic logger"); + NFL_LOG_INFO(move_constructed, "message from move constructed dynamic logger"); + NFL_LOG_INFO(move_assigned_target, "message from move assigned dynamic logger"); }); EXPECT_NE(output.find("[MoveConstructedDynamicLoggerName]"), std::string::npos) << output; @@ -108,7 +108,7 @@ TEST(LoggerTest, LogLineIncludesSourceLocation) { Logger logger{"LoggerTest"}; const std::string output = CaptureStdout([&] { - logger.Info("a message"); + NFL_LOG_INFO(logger, "a message"); }); // The line carries the call site as basename:line; parse the number to prove a line follows. @@ -130,7 +130,7 @@ TEST(LoggerTest, MarksAnOverlongMessageAndKeepsWhatFollowsIt) { // Longer than any record buffer, so the message is cut wherever that boundary sits. const std::string argument(8192, 'x'); const std::string output = CaptureStdout([&] { - logger.Info("{}", argument); + NFL_LOG_INFO(logger, "{}", argument); }); // The marker and the source location both land past the cut message, so the tail is what @@ -156,9 +156,9 @@ TEST(LoggerTest, EmittingARecordDoesNotAllocate) { size_t allocated = 0; const std::string output = CaptureStdout([&] { - logger.Info("warm-up: the redirected stream buffers itself on its first write"); + NFL_LOG_INFO(logger, "warm-up: the redirected stream buffers itself on its first write"); const ScopedAllocationCounter counter; - logger.Info("group {} via {} port {}", address, mac, 1900); + NFL_LOG_INFO(logger, "group {} via {} port {}", address, mac, 1900); allocated = counter.Count(); }); @@ -173,12 +173,28 @@ TEST(LoggerTest, EndsTheLineWhenEvenTheRecordIsTruncated) { Logger logger{std::string(8192, 'n')}; // the name alone overruns the record buffer const std::string output = CaptureStdout([&] { - logger.Info("a message"); + NFL_LOG_INFO(logger, "a message"); }); // Exactly one newline, at the very end: the reserved slot held, and the record is a single line. ASSERT_FALSE(output.empty()); EXPECT_EQ(output.find('\n'), output.size() - 1); } +// The macro gates on the level before the arguments are formed, so a filtered record costs nothing +// past the comparison. Calling Logger::Debug directly still builds every argument first. +TEST(LoggerTest, AFilteredRecordDoesNotEvaluateItsArguments) { + const ScopedMinLogLevel level{LogLevel::Info}; + Logger logger{"GateLogger"}; + int evaluated = 0; + const auto counted = [&evaluated] { return ++evaluated; }; + + NFL_LOG_DEBUG(logger, "suppressed {}", counted()); + EXPECT_EQ(evaluated, 0); + + const std::string output = CaptureStdout([&] { NFL_LOG_INFO(logger, "emitted {}", counted()); }); + + EXPECT_EQ(evaluated, 1); + EXPECT_NE(output.find("emitted 1"), std::string::npos) << output; +} } // namespace reflector diff --git a/tests/util/udp_socket.cpp b/tests/util/udp_socket.cpp index 3839294..987fbd0 100644 --- a/tests/util/udp_socket.cpp +++ b/tests/util/udp_socket.cpp @@ -13,13 +13,13 @@ namespace reflector { UdpSocket::UdpSocket(IpAddress::Family family) : family_{family} { - logger_.Debug("Creating socket"); + NFL_LOG_DEBUG(logger_, "Creating socket"); fd_.Reset(socket(family == IpAddress::Family::V6 ? AF_INET6 : AF_INET, SOCK_DGRAM, IPPROTO_UDP)); if (!fd_) { if (errno == EAFNOSUPPORT || errno == EPROTONOSUPPORT) { - logger_.Warn("Cannot create socket: address family not supported: {}", Error::FromErrno()); + NFL_LOG_WARN(logger_, "Cannot create socket: address family not supported: {}", Error::FromErrno()); } else { - logger_.Error("Cannot create socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot create socket: {}", Error::FromErrno()); } return; } @@ -27,7 +27,7 @@ UdpSocket::UdpSocket(IpAddress::Family family) : family_{family} { logger_.SetName(std::format("UdpSocket:{}", fd_.Get())); if (!SetNonBlocking(fd_.Get())) { - logger_.Error("Cannot set socket non-blocking: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set socket non-blocking: {}", Error::FromErrno()); Close(); } } @@ -38,14 +38,14 @@ UdpSocket::~UdpSocket() noexcept { void UdpSocket::Close() noexcept { if (fd_) { - logger_.Debug("Closing socket"); + NFL_LOG_DEBUG(logger_, "Closing socket"); fd_.Reset(); } } bool UdpSocket::IsInterfaceConsistent(const std::string& interface, unsigned int index) noexcept { if (interface_index_ != 0 && interface_index_ != index) { - logger_.Error("Cannot use interface \"{}\": socket is already bound to a different interface (index {})", + NFL_LOG_ERROR(logger_, "Cannot use interface \"{}\": socket is already bound to a different interface (index {})", interface, interface_index_); return false; } @@ -54,15 +54,15 @@ bool UdpSocket::IsInterfaceConsistent(const std::string& interface, unsigned int bool UdpSocket::SetInterface(const std::string& interface) { if (!IsValid()) { - logger_.Error("Cannot set interface to \"{}\": socket is invalid", interface); + NFL_LOG_ERROR(logger_, "Cannot set interface to \"{}\": socket is invalid", interface); return false; } - logger_.Info("Setting interface to \"{}\"", interface); + NFL_LOG_INFO(logger_, "Setting interface to \"{}\"", interface); const unsigned int idx = if_nametoindex(interface.c_str()); if (idx == 0) { - logger_.Error("Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); return false; } if (!IsInterfaceConsistent(interface, idx)) { @@ -72,18 +72,18 @@ bool UdpSocket::SetInterface(const std::string& interface) { #if defined(__linux__) const auto interface_size = interface.size() + 1; if (interface_size > IF_NAMESIZE) { - logger_.Error("Cannot set SO_BINDTODEVICE to \"{}\": interface name is too long", interface); + NFL_LOG_ERROR(logger_, "Cannot set SO_BINDTODEVICE to \"{}\": interface name is too long", interface); return false; } if (setsockopt(fd_.Get(), SOL_SOCKET, SO_BINDTODEVICE, interface.c_str(), static_cast(interface_size)) != 0) { - logger_.Error("Cannot set SO_BINDTODEVICE to \"{}\": {}", interface, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set SO_BINDTODEVICE to \"{}\": {}", interface, Error::FromErrno()); return false; } #elif defined(__APPLE__) const int level = family_ == IpAddress::Family::V6 ? IPPROTO_IPV6 : IPPROTO_IP; const int option = family_ == IpAddress::Family::V6 ? IPV6_BOUND_IF : IP_BOUND_IF; if (setsockopt(fd_.Get(), level, option, &idx, sizeof(idx)) != 0) { - logger_.Error("Cannot bind socket to interface \"{}\" (index {}): {}", + NFL_LOG_ERROR(logger_, "Cannot bind socket to interface \"{}\" (index {}): {}", interface, idx, Error::FromErrno()); return false; } @@ -98,13 +98,13 @@ bool UdpSocket::SetInterface(const std::string& interface) { bool UdpSocket::SetBroadcast(bool enabled) noexcept { if (!IsValid()) { - logger_.Error("Cannot set SO_BROADCAST to {}: socket is invalid", enabled); + NFL_LOG_ERROR(logger_, "Cannot set SO_BROADCAST to {}: socket is invalid", enabled); return false; } int value = enabled ? 1 : 0; if (setsockopt(fd_.Get(), SOL_SOCKET, SO_BROADCAST, &value, sizeof(value)) != 0) { - logger_.Error("Cannot set SO_BROADCAST to {}: {}", enabled, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set SO_BROADCAST to {}: {}", enabled, Error::FromErrno()); return false; } @@ -113,13 +113,13 @@ bool UdpSocket::SetBroadcast(bool enabled) noexcept { bool UdpSocket::SetReuseAddr(bool enabled) noexcept { if (!IsValid()) { - logger_.Error("Cannot set SO_REUSEADDR to {}: socket is invalid", enabled); + NFL_LOG_ERROR(logger_, "Cannot set SO_REUSEADDR to {}: socket is invalid", enabled); return false; } int value = enabled ? 1 : 0; if (setsockopt(fd_.Get(), SOL_SOCKET, SO_REUSEADDR, &value, sizeof(value)) != 0) { - logger_.Error("Cannot set SO_REUSEADDR to {}: {}", enabled, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set SO_REUSEADDR to {}: {}", enabled, Error::FromErrno()); return false; } @@ -128,17 +128,17 @@ bool UdpSocket::SetReuseAddr(bool enabled) noexcept { bool UdpSocket::SetV6Only(bool enabled) noexcept { if (!IsValid()) { - logger_.Error("Cannot set IPV6_V6ONLY to {}: socket is invalid", enabled); + NFL_LOG_ERROR(logger_, "Cannot set IPV6_V6ONLY to {}: socket is invalid", enabled); return false; } if (family_ != IpAddress::Family::V6) { - logger_.Error("Cannot set IPV6_V6ONLY to {}: socket is not IPv6", enabled); + NFL_LOG_ERROR(logger_, "Cannot set IPV6_V6ONLY to {}: socket is not IPv6", enabled); return false; } int value = enabled ? 1 : 0; if (setsockopt(fd_.Get(), IPPROTO_IPV6, IPV6_V6ONLY, &value, sizeof(value)) != 0) { - logger_.Error("Cannot set IPV6_V6ONLY to {}: {}", enabled, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot set IPV6_V6ONLY to {}: {}", enabled, Error::FromErrno()); return false; } @@ -147,17 +147,17 @@ bool UdpSocket::SetV6Only(bool enabled) noexcept { bool UdpSocket::SetMulticastInterface(const std::string& interface) { if (!IsValid()) { - logger_.Error("Cannot set multicast interface to \"{}\": socket is invalid", interface); + NFL_LOG_ERROR(logger_, "Cannot set multicast interface to \"{}\": socket is invalid", interface); return false; } if (family_ != IpAddress::Family::V6) { - logger_.Error("Cannot set multicast interface to \"{}\": socket is not IPv6", interface); + NFL_LOG_ERROR(logger_, "Cannot set multicast interface to \"{}\": socket is not IPv6", interface); return false; } const unsigned int idx = if_nametoindex(interface.c_str()); if (idx == 0) { - logger_.Error("Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); return false; } if (!IsInterfaceConsistent(interface, idx)) { @@ -165,7 +165,7 @@ bool UdpSocket::SetMulticastInterface(const std::string& interface) { } if (setsockopt(fd_.Get(), IPPROTO_IPV6, IPV6_MULTICAST_IF, &idx, sizeof(idx)) != 0) { - logger_.Error("Cannot set IPV6_MULTICAST_IF to \"{}\" (index {}): {}", + NFL_LOG_ERROR(logger_, "Cannot set IPV6_MULTICAST_IF to \"{}\" (index {}): {}", interface, idx, Error::FromErrno()); return false; } @@ -176,18 +176,18 @@ bool UdpSocket::SetMulticastInterface(const std::string& interface) { bool UdpSocket::JoinMulticastGroup(const IpAddress& group, const std::string& interface) { if (!IsValid()) { - logger_.Error("Cannot join multicast group {}: socket is invalid", group); + NFL_LOG_ERROR(logger_, "Cannot join multicast group {}: socket is invalid", group); return false; } if (group.AddressFamily() != family_) { - logger_.Error("Cannot join multicast group {}: address family does not match the socket", + NFL_LOG_ERROR(logger_, "Cannot join multicast group {}: address family does not match the socket", group); return false; } const unsigned int idx = if_nametoindex(interface.c_str()); if (idx == 0) { - logger_.Error("Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot resolve interface \"{}\": {}", interface, Error::FromErrno()); return false; } @@ -199,7 +199,7 @@ bool UdpSocket::JoinMulticastGroup(const IpAddress& group, const std::string& in group.ToSockaddr(request.gr_group, /*port=*/0); const int level = family_ == IpAddress::Family::V6 ? IPPROTO_IPV6 : IPPROTO_IP; if (setsockopt(fd_.Get(), level, MCAST_JOIN_GROUP, &request, sizeof(request)) != 0) { - logger_.Error("Cannot join multicast group {} on \"{}\": {}", group, interface, + NFL_LOG_ERROR(logger_, "Cannot join multicast group {} on \"{}\": {}", group, interface, Error::FromErrno()); return false; } @@ -213,34 +213,34 @@ bool UdpSocket::Bind(uint16_t port) { bool UdpSocket::Bind(const IpEndpoint& endpoint) { if (!IsValid()) { - logger_.Error("Cannot bind to {}: socket is invalid", endpoint); + NFL_LOG_ERROR(logger_, "Cannot bind to {}: socket is invalid", endpoint); return false; } if (endpoint.addr.AddressFamily() != family_) { - logger_.Error("Cannot bind to {}: address family does not match the socket's", endpoint); + NFL_LOG_ERROR(logger_, "Cannot bind to {}: address family does not match the socket's", endpoint); return false; } - logger_.Info("Binding socket to {}", endpoint); + NFL_LOG_INFO(logger_, "Binding socket to {}", endpoint); sockaddr_storage storage{}; const socklen_t length = endpoint.ToSockaddr(storage); if (bind(fd_.Get(), reinterpret_cast(&storage), length) != 0) { - logger_.Error("Cannot bind UDP socket: {}", Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot bind UDP socket: {}", Error::FromErrno()); return false; } - logger_.Debug("Bound UDP socket to {}", endpoint); + NFL_LOG_DEBUG(logger_, "Bound UDP socket to {}", endpoint); return true; } bool UdpSocket::SendTo(std::span payload, const IpEndpoint& endpoint) noexcept { if (!IsValid()) { - logger_.Error("Cannot send to {}: socket is invalid", endpoint); + NFL_LOG_ERROR(logger_, "Cannot send to {}: socket is invalid", endpoint); return false; } if (endpoint.addr.AddressFamily() != family_) { - logger_.Error("Cannot send to {}: address family does not match the socket's", endpoint); + NFL_LOG_ERROR(logger_, "Cannot send to {}: address family does not match the socket's", endpoint); return false; } @@ -257,11 +257,11 @@ bool UdpSocket::SendTo(std::span payload, const IpEndpoint& end length); } while (bytes_sent < 0 && errno == EINTR); if (bytes_sent < 0) { - logger_.Error("Cannot send UDP packet to {}: {}", endpoint, Error::FromErrno()); + NFL_LOG_ERROR(logger_, "Cannot send UDP packet to {}: {}", endpoint, Error::FromErrno()); return false; } - logger_.Debug("Sent {} bytes to {}", bytes_sent, endpoint); + NFL_LOG_DEBUG(logger_, "Sent {} bytes to {}", bytes_sent, endpoint); return true; } From d832a46c61bfa19c0703cf7add88779bd7dbfd91 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 15:20:57 +0200 Subject: [PATCH 04/10] docs: record the breaking-change commit convention --- CLAUDE.md | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/CLAUDE.md b/CLAUDE.md index e355eac..c72ca18 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -15,6 +15,10 @@ - Mixed signed/unsigned comparison: `static_cast` when non-negativity is evident at the call site (a length, a count); `std::cmp_*` only when a side can actually be negative (an error-signalling `-1`, a difference). - Log level by failure, not blame: failure of an intended operation → `Error`, even if externally caused; deliberate skips (traffic not handled by design) → `Debug`. If Error volume becomes a problem, rate-limit — don't downgrade. +## Commits + +- Breaking changes get `!` in the type (`feat!:`, `refactor!:`): anything that makes an existing config file, command line, or deployment stop working as it did. + ## Build ```sh From 95bac779fd501c1bf169580b63f5ee1e1d71ee23 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 15:49:57 +0200 Subject: [PATCH 05/10] refactor: build log records in a translation unit of their own Emit was a template, so the entire record builder was instantiated once per combination of argument types: localtime_r, strftime, both format calls and the fwrite, copied 86 times across the tree. Type-erasing the arguments through make_format_args leaves each call site with just the argument array to build, and the builder compiles once. Release text drops from 425,984 to 376,832 bytes, around 10% of the stripped binary, measured on an arm64 LTO build. std::format has no vformat_to_n, so bounding the message buffer needs an output iterator of our own to keep truncation working. --- src/reflector/CMakeLists.txt | 1 + src/reflector/logger.cpp | 100 +++++++++++++++++++++++++++++++++++ src/reflector/logger.h | 55 +++---------------- 3 files changed, 107 insertions(+), 49 deletions(-) create mode 100644 src/reflector/logger.cpp diff --git a/src/reflector/CMakeLists.txt b/src/reflector/CMakeLists.txt index b085ab9..4cbe224 100644 --- a/src/reflector/CMakeLists.txt +++ b/src/reflector/CMakeLists.txt @@ -12,6 +12,7 @@ add_library(reflector STATIC ${CMAKE_CURRENT_SOURCE_DIR}/interface.cpp ${CMAKE_CURRENT_SOURCE_DIR}/interface_address.cpp ${CMAKE_CURRENT_SOURCE_DIR}/ip_address.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/logger.cpp ${CMAKE_CURRENT_SOURCE_DIR}/mac_address.cpp ${CMAKE_CURRENT_SOURCE_DIR}/mdns_message.cpp ${CMAKE_CURRENT_SOURCE_DIR}/memory_report.cpp diff --git a/src/reflector/logger.cpp b/src/reflector/logger.cpp new file mode 100644 index 0000000..a767499 --- /dev/null +++ b/src/reflector/logger.cpp @@ -0,0 +1,100 @@ +#include "reflector/logger.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace { + +using namespace reflector; + +constexpr size_t MAX_MESSAGE_SIZE = 1024; +// Plus the timestamp, level, logger name and source location wrapped around it. +constexpr size_t MAX_RECORD_SIZE = MAX_MESSAGE_SIZE + 512; + +constexpr const char* Basename(const char* path) noexcept { + const char* base = path; + for (const char* p = path; *p != '\0'; ++p) { + if (*p == '/') { + base = p + 1; + } + } + return base; +} + +struct SinkState { + char* out; + size_t capacity; + size_t written = 0; +}; + +// Writes while the buffer has room and keeps counting past it, so an over-long message stays +// measurable. format_to_n does this for a typed call, but type-erased arguments go through +// vformat_to, which has no bounded form. +// +// Shaped like std::back_insert_iterator: the assignment writes and advances, ++ is a no-op. The +// position cannot advance in operator++ instead, because std::format writes through `*it++ = c` +// against a shared position, which would read a slot its own increment had already moved past. +class BoundedSink { +public: + using difference_type = ptrdiff_t; + + explicit BoundedSink(SinkState& state) noexcept : state_{&state} {} + + BoundedSink& operator=(char c) noexcept { + if (state_->written < state_->capacity) { + state_->out[state_->written] = c; + } + ++state_->written; + return *this; + } + + BoundedSink& operator*() noexcept { return *this; } + BoundedSink& operator++() noexcept { return *this; } + BoundedSink operator++(int) noexcept { return *this; } + +private: + SinkState* state_; +}; + +} // namespace + +namespace reflector { + +void Logger::EmitRecord(LogLevel level, std::string_view fmt, std::format_args args, + const std::source_location& loc) noexcept { + try { + // Clang 17 does not support std::chrono::current_zone(). Maybe next time. + const auto time = std::time({}); + std::tm tm_buf{}; + localtime_r(&time, &tm_buf); + char time_str[sizeof("yyyy-mm-dd hh:mm:ss")]; + std::strftime(time_str, sizeof(time_str), "%Y-%m-%d %H:%M:%S", &tm_buf); + + // Two buffers, so an over-long message loses its own tail rather than the source location + // after it. std::format plus std::println would allocate twice per record. + std::array message_buffer; + SinkState state{message_buffer.data(), message_buffer.size()}; + std::vformat_to(BoundedSink{state}, fmt, args); + const std::string_view message{message_buffer.data(), std::min(state.written, state.capacity)}; + const std::string_view elision = state.written > state.capacity ? "[...]" : ""; + + // One slot is held back for the newline, so it lands even on a truncated record and the + // whole line still goes out in a single write. + std::array record; + const auto emitted = std::format_to_n(record.data(), record.size() - 1, "{} {} [{}] {}{} ({}:{})", + time_str, level, name_, message, elision, Basename(loc.file_name()), loc.line()); + const auto length = static_cast(emitted.out - record.data()); + record[length] = '\n'; + std::fwrite(record.data(), 1, length + 1, stdout); + } catch (...) { + std::fputs("logger: failed to emit message\n", stderr); + } +} + +} // namespace reflector diff --git a/src/reflector/logger.h b/src/reflector/logger.h index 2892b4e..1c3999a 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -2,11 +2,7 @@ #include "reflector/util/no_copy.h" -#include -#include #include -#include -#include #include #include #include @@ -25,16 +21,6 @@ enum class LogLevel : uint8_t { namespace detail { -constexpr const char* Basename(const char* path) noexcept { - const char* base = path; - for (const char* p = path; *p != '\0'; ++p) { - if (*p == '/') { - base = p + 1; - } - } - return base; -} - template struct LogFmt { std::format_string fmt; @@ -59,46 +45,17 @@ class Logger : NoCopy { static void SetMinLevel(LogLevel level) noexcept { min_level_ = level; } [[nodiscard]] static LogLevel MinLevel() noexcept { return min_level_; } - // Ungated: the NFL_LOG macros check the level before they reach here. + // Ungated: the NFL_LOG macros check the level before they reach here. Type-erasing the + // arguments keeps the record builder to one instantiation rather than one per combination of + // argument types across every call site. template void Emit(LogLevel level, detail::LogFmt...> fmt, Args&& ...args) noexcept { - try { - // Clang 17 does not support std::chrono::current_zone(). Maybe next time. - const auto time = std::time({}); - std::tm tm_buf{}; - localtime_r(&time, &tm_buf); - char time_str[sizeof("yyyy-mm-dd hh:mm:ss")]; - std::strftime(time_str, sizeof(time_str), "%Y-%m-%d %H:%M:%S", &tm_buf); - - // Two buffers, so an over-long message loses its own tail rather than the source - // location after it. std::format plus std::println would allocate twice per record. - std::array message_buffer; - const auto formatted = std::format_to_n(message_buffer.data(), message_buffer.size(), - std::move(fmt.fmt), std::forward(args)...); - const std::string_view message{message_buffer.data(), - static_cast(formatted.out - message_buffer.data())}; - // formatted.size is the length the message needed, not what fit, so this catches a cut. - const std::string_view elision = - static_cast(formatted.size) > message_buffer.size() ? "[...]" : ""; - - // One slot is held back for the newline, so it lands even on a truncated record and the - // whole line still goes out in a single write. - std::array record; - const auto emitted = std::format_to_n(record.data(), record.size() - 1, "{} {} [{}] {}{} ({}:{})", - time_str, level, name_, message, elision, - detail::Basename(fmt.loc.file_name()), fmt.loc.line()); - const auto length = static_cast(emitted.out - record.data()); - record[length] = '\n'; - std::fwrite(record.data(), 1, length + 1, stdout); - } catch (...) { - std::fputs("logger: failed to emit message\n", stderr); - } + EmitRecord(level, fmt.fmt.get(), std::make_format_args(args...), fmt.loc); } private: - static constexpr size_t MAX_MESSAGE_SIZE = 1024; - // Plus the timestamp, level, logger name and source location wrapped around it. - static constexpr size_t MAX_RECORD_SIZE = MAX_MESSAGE_SIZE + 512; + void EmitRecord(LogLevel level, std::string_view fmt, std::format_args args, + const std::source_location& loc) noexcept; inline static LogLevel min_level_ = LogLevel::Info; From 93e65bd78c8861c7c6c45954afae19fa60665488 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 17:44:28 +0200 Subject: [PATCH 06/10] feat: rate-limited log macros A failure that recurs per packet or per peer floods the log and buries everything else. NFL_LOG_WARN_RATE and NFL_LOG_ERROR_RATE emit at most once per window per call site, count what they swallow, and disclose the count on the next line that gets through. The window is a consteval constructor argument, so a site cannot pass one that varies between calls, and the gate is constant-initialized rather than carrying a thread-safe init guard, and its atomic load, into every call. MonotonicSecs is one-based, which leaves 0 to mean "nothing emitted yet" even for a daemon that logs during its first second of uptime, and makes the window arithmetic underflow-free without a guard. The disclosure is interpolated into the record rather than appended to the message, so a message long enough to be truncated cannot take it down with it, and an ordinary log never tests for one. --- src/reflector/logger.cpp | 29 ++++++++++++-- src/reflector/logger.h | 72 ++++++++++++++++++++++++++++++++++- tests/logger_test.cpp | 81 +++++++++++++++++++++++++++++++++++++++- 3 files changed, 175 insertions(+), 7 deletions(-) diff --git a/src/reflector/logger.cpp b/src/reflector/logger.cpp index a767499..29ae704 100644 --- a/src/reflector/logger.cpp +++ b/src/reflector/logger.cpp @@ -2,7 +2,9 @@ #include #include +#include #include +#include #include #include #include @@ -66,7 +68,25 @@ class BoundedSink { namespace reflector { -void Logger::EmitRecord(LogLevel level, std::string_view fmt, std::format_args args, +uint32_t detail::MonotonicSecs() noexcept { + const auto now = std::chrono::steady_clock::now().time_since_epoch(); + return detail::MonotonicSecsFrom(std::chrono::duration_cast(now).count()); +} + +void Logger::EmitRatedRecord(LogLevel level, uint32_t suppressed, std::string_view fmt, + std::format_args args, const std::source_location& loc) noexcept { + // The first emission in a window has swallowed nothing, which is the common case. + if (suppressed == 0) { + EmitRecord(level, {}, fmt, args, loc); + return; + } + std::array note; + const auto end = std::format_to_n(note.data(), note.size(), " ({} suppressed)", suppressed); + EmitRecord(level, std::string_view{note.data(), static_cast(end.out - note.data())}, fmt, + args, loc); +} + +void Logger::EmitRecord(LogLevel level, std::string_view note, std::string_view fmt, std::format_args args, const std::source_location& loc) noexcept { try { // Clang 17 does not support std::chrono::current_zone(). Maybe next time. @@ -85,10 +105,11 @@ void Logger::EmitRecord(LogLevel level, std::string_view fmt, std::format_args a const std::string_view elision = state.written > state.capacity ? "[...]" : ""; // One slot is held back for the newline, so it lands even on a truncated record and the - // whole line still goes out in a single write. + // whole line still goes out in a single write. note sits outside the message buffer, so a + // message long enough to be cut cannot swallow the disclosure with it. std::array record; - const auto emitted = std::format_to_n(record.data(), record.size() - 1, "{} {} [{}] {}{} ({}:{})", - time_str, level, name_, message, elision, Basename(loc.file_name()), loc.line()); + const auto emitted = std::format_to_n(record.data(), record.size() - 1, "{} {} [{}] {}{}{} ({}:{})", + time_str, level, name_, message, elision, note, Basename(loc.file_name()), loc.line()); const auto length = static_cast(emitted.out - record.data()); record[length] = '\n'; std::fwrite(record.data(), 1, length + 1, stdout); diff --git a/src/reflector/logger.h b/src/reflector/logger.h index 1c3999a..99d1103 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -4,6 +4,7 @@ #include #include +#include #include #include #include @@ -31,6 +32,43 @@ struct LogFmt { : fmt{s}, loc{l} {} }; +// One-based, so a reading is never 0 and RateGate can spend 0 on "never emitted". Whole seconds, so +// a window under a second lets every call through. +constexpr uint32_t MonotonicSecsFrom(int64_t nanos) noexcept { + return 1 + static_cast(nanos / 1'000'000'000); +} + +// MonotonicSecsFrom applied to the steady clock, which counts from boot. +uint32_t MonotonicSecs() noexcept; + +// The emit-or-count decision for one call site. The NFL_LOG_*_RATE macros keep one of these in a +// static, so a window covers a statement rather than an interface or a peer. The caller passes the +// time in, which is what makes the arithmetic testable without waiting on a clock. Plain integers +// rather than atomics: the loop is single-threaded and no log runs from a signal handler. +class RateGate { +public: + // consteval, so a site cannot hand over a window that varies between calls, and the gate is + // constant-initialized rather than carrying a thread-safe init guard into every call. + consteval explicit RateGate(uint32_t window_secs) noexcept : window_secs_{window_secs} {} + + // How many records were suppressed since the last emission, or nullopt to suppress this one. + // Takes readings from MonotonicSecs, which never decrease and are never 0, so the subtraction + // cannot underflow and last_emit_ of 0 can only mean nothing has been emitted yet. + constexpr std::optional Admit(uint32_t now_secs) noexcept { + if (last_emit_ == 0 || now_secs - last_emit_ >= window_secs_) { + last_emit_ = now_secs; + return std::exchange(suppressed_, 0); + } + ++suppressed_; + return std::nullopt; + } + +private: + uint32_t window_secs_; + uint32_t last_emit_ = 0; + uint32_t suppressed_ = 0; +}; + } // namespace detail class Logger : NoCopy { @@ -50,12 +88,23 @@ class Logger : NoCopy { // argument types across every call site. template void Emit(LogLevel level, detail::LogFmt...> fmt, Args&& ...args) noexcept { - EmitRecord(level, fmt.fmt.get(), std::make_format_args(args...), fmt.loc); + EmitRecord(level, {}, fmt.fmt.get(), std::make_format_args(args...), fmt.loc); + } + + // For the NFL_LOG_*_RATE macros, which have a count of what the window swallowed to disclose. + template + void EmitRated(LogLevel level, uint32_t suppressed, + detail::LogFmt...> fmt, Args&& ...args) noexcept { + EmitRatedRecord(level, suppressed, fmt.fmt.get(), std::make_format_args(args...), fmt.loc); } private: - void EmitRecord(LogLevel level, std::string_view fmt, std::format_args args, + // note is interpolated as it stands, so the rate-limited path owns the decision of whether + // there is anything to disclose and the ordinary path never tests for it. + void EmitRecord(LogLevel level, std::string_view note, std::string_view fmt, std::format_args args, const std::source_location& loc) noexcept; + void EmitRatedRecord(LogLevel level, uint32_t suppressed, std::string_view fmt, + std::format_args args, const std::source_location& loc) noexcept; inline static LogLevel min_level_ = LogLevel::Info; @@ -105,3 +154,22 @@ struct std::formatter #define NFL_LOG_INFO(logger, ...) NFL_LOG(logger, Info, __VA_ARGS__) #define NFL_LOG_WARN(logger, ...) NFL_LOG(logger, Warn, __VA_ARGS__) #define NFL_LOG_ERROR(logger, ...) NFL_LOG(logger, Error, __VA_ARGS__) + +// Emits at most once per window per call site. A call landing inside a closed window is counted +// instead, and the next line that does emit discloses the count. +#define NFL_LOG_RATE(logger, level, window_secs, ...) \ + do { \ + if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ + static ::reflector::detail::RateGate nfl_rate_gate{(window_secs)}; \ + const auto nfl_suppressed = \ + nfl_rate_gate.Admit(::reflector::detail::MonotonicSecs()); \ + if (nfl_suppressed) { \ + (logger).EmitRated(::reflector::LogLevel::level, *nfl_suppressed, __VA_ARGS__); \ + } \ + } \ + } while (false) + +#define NFL_LOG_WARN_RATE(logger, window_secs, ...) \ + NFL_LOG_RATE(logger, Warn, window_secs, __VA_ARGS__) +#define NFL_LOG_ERROR_RATE(logger, window_secs, ...) \ + NFL_LOG_RATE(logger, Error, window_secs, __VA_ARGS__) diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index 95ab973..339d833 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -180,8 +180,87 @@ TEST(LoggerTest, EndsTheLineWhenEvenTheRecordIsTruncated) { ASSERT_FALSE(output.empty()); EXPECT_EQ(output.find('\n'), output.size() - 1); } +// Times are MonotonicSecs readings, which are one-based: 1 is the first second of uptime. +TEST(RateGateTest, EmitsFirstThenSuppressesWithinTheWindow) { + detail::RateGate gate{60}; + + EXPECT_EQ(gate.Admit(1), 0U); + EXPECT_EQ(gate.Admit(2), std::nullopt); + EXPECT_EQ(gate.Admit(60), std::nullopt); + // A full 60 seconds after the emission at 1, disclosing the two it swallowed. + EXPECT_EQ(gate.Admit(61), 2U); + EXPECT_EQ(gate.Admit(200), 0U); +} + +TEST(RateGateTest, RepeatedCallsInTheFirstSecondEmitOnlyOnce) { + detail::RateGate gate{60}; + + EXPECT_EQ(gate.Admit(1), 0U); + EXPECT_EQ(gate.Admit(1), std::nullopt); + EXPECT_EQ(gate.Admit(1), std::nullopt); +} + +TEST(RateGateTest, AZeroWindowAdmitsEveryCall) { + detail::RateGate gate{0}; + + EXPECT_EQ(gate.Admit(1), 0U); + EXPECT_EQ(gate.Admit(1), 0U); + EXPECT_EQ(gate.Admit(2), 0U); +} + +// RateGate spends 0 on "never emitted", which only works because a reading can never be 0. The +// first second of uptime is the case that would otherwise collide with it. +TEST(RateGateTest, TheClockIsOneBased) { + EXPECT_EQ(detail::MonotonicSecsFrom(0), 1U); + EXPECT_EQ(detail::MonotonicSecsFrom(999'999'999), 1U); + EXPECT_EQ(detail::MonotonicSecsFrom(1'000'000'000), 2U); +} + +TEST(LoggerTest, ASuppressedCountRidesOnTheNextRecord) { + const ScopedMinLogLevel level{LogLevel::Info}; + Logger logger{"RateLogger"}; + + const std::string output = CaptureStdout([&] { + logger.EmitRated(LogLevel::Warn, 5, "a message"); + }); + + EXPECT_NE(output.find("(5 suppressed)"), std::string::npos) << output; +} + +TEST(LoggerTest, ADisclosureOutlivesAnOverlongMessage) { + const ScopedMinLogLevel level{LogLevel::Info}; + Logger logger{"RateLogger"}; + + const std::string argument(8192, 'x'); + const std::string output = CaptureStdout([&] { + logger.EmitRated(LogLevel::Warn, 7, "{}", argument); + }); + + ASSERT_GT(output.size(), 100u); + const std::string tail = output.substr(output.size() - 100); + EXPECT_NE(output.find("[...]"), std::string::npos) << tail; + EXPECT_NE(output.find("(7 suppressed)"), std::string::npos) << tail; +} + +TEST(LoggerTest, ARateLimitedCallSiteEmitsOncePerWindow) { + const ScopedMinLogLevel level{LogLevel::Info}; + Logger logger{"RateLogger"}; + + const std::string output = CaptureStdout([&] { + for (int i = 0; i < 3; ++i) { + NFL_LOG_WARN_RATE(logger, 60, "flooding {}", i); + } + }); + + EXPECT_NE(output.find("flooding 0"), std::string::npos) << output; + EXPECT_EQ(output.find("flooding 1"), std::string::npos) << output; + EXPECT_EQ(output.find("flooding 2"), std::string::npos) << output; + // Nothing was suppressed before the one that emitted, so it carries no disclosure. + EXPECT_EQ(output.find("suppressed"), std::string::npos) << output; +} + // The macro gates on the level before the arguments are formed, so a filtered record costs nothing -// past the comparison. Calling Logger::Debug directly still builds every argument first. +// past the comparison. Calling Logger::Emit directly still builds every argument first. TEST(LoggerTest, AFilteredRecordDoesNotEvaluateItsArguments) { const ScopedMinLogLevel level{LogLevel::Info}; Logger logger{"GateLogger"}; From 079229d164fab4262a4a2d0528afeaee81c86f3a Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 19:08:53 +0200 Subject: [PATCH 07/10] feat: rate-limit the per-packet reflect failures One inbound packet produces one of these lines, so a peer sets the rate: the oversized-frame drops in both capture backends, the reflect failures in each reflector, and the session, connection and reservation caps. One window for all of them, so what survives is a coherent sample rather than a scatter of sites whose windows opened at different times. Nothing else is gated. A socket that will not open or a group that will not join reports at the rate we chose to retry it, which is a rate worth seeing. Ten tests asserted a gated line reached stdout beside an assertion of the behaviour that produced it. A gate outlives the test that trips it, so those passed only in the order they happened to run; the log assertions go. --- src/reflector/dial_proxy.cpp | 2 +- src/reflector/mdns_reflector.cpp | 3 ++- src/reflector/raw_socket.cpp | 6 +++--- src/reflector/ssdp_reflector.cpp | 15 +++++++++------ src/reflector/wol_reflector.cpp | 2 +- tests/logger_test.cpp | 2 ++ tests/mdns_reflector_test.cpp | 5 ++--- tests/raw_socket_test.cpp | 6 ++---- tests/ssdp_reflector_test.cpp | 24 +++++++++--------------- tests/wol_reflector_test.cpp | 5 ++--- 10 files changed, 33 insertions(+), 37 deletions(-) diff --git a/src/reflector/dial_proxy.cpp b/src/reflector/dial_proxy.cpp index ef8b3fb..b54f9b8 100644 --- a/src/reflector/dial_proxy.cpp +++ b/src/reflector/dial_proxy.cpp @@ -326,7 +326,7 @@ void DialProxy::OnAccept(int listener_fd) noexcept { } if (connections_.size() >= MAX_CONNECTIONS) { - NFL_LOG_WARN(logger_, "Dropping accept for {}: connection cap reached", ep->device); + NFL_LOG_WARN_RATE(logger_, 60, "Dropping accept for {}: connection cap reached", ep->device); return; // the accepted client TcpSocket drops here -> RAII close } diff --git a/src/reflector/mdns_reflector.cpp b/src/reflector/mdns_reflector.cpp index 6f5f616..3fc8fbf 100644 --- a/src/reflector/mdns_reflector.cpp +++ b/src/reflector/mdns_reflector.cpp @@ -141,7 +141,8 @@ void MdnsReflector::Relay(LinkSocket& egress, const Packet& packet) noexcept { // Re-emit to the same group it was sent to (the filter guarantees dest_ip is that group), from // the mDNS port, with the conventional 255 hop limit. if (!egress.SendUdpMulticastDatagram(packet.header.dest, MDNS_PORT, packet.payload, MDNS_TTL)) { - NFL_LOG_ERROR(logger_, "Cannot reflect mdns packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR_RATE(logger_, 60, + "Cannot reflect mdns packet from {} to {}", packet.header.source, packet.header.dest); return; } NFL_LOG_DEBUG(logger_, "Reflected mdns packet from {} to {}", packet.header.source, packet.header.dest); diff --git a/src/reflector/raw_socket.cpp b/src/reflector/raw_socket.cpp index f5d3feb..e2e3be8 100644 --- a/src/reflector/raw_socket.cpp +++ b/src/reflector/raw_socket.cpp @@ -636,7 +636,7 @@ std::expected RawSocket::Receive() noexcept { return std::unexpected(ReceiveError::Failed); } if (static_cast(bytes) > receive_buffer_.size()) { - NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + NFL_LOG_WARN_RATE(logger_, 60, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", bytes, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -685,7 +685,7 @@ std::expected RawSocket::Receive() noexcept { // BPF captured fewer bytes than the frame's real length, so it didn't fit the buffer; drop it // rather than parse a truncated frame. (Offset already advanced to the next record above.) if (header.bh_datalen > header.bh_caplen) { - NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", + NFL_LOG_WARN_RATE(logger_, 60, "Dropping oversized frame: {} bytes exceeds {}-byte receive buffer", header.bh_datalen, receive_buffer_.size()); return std::unexpected(ReceiveError::Dropped); } @@ -694,7 +694,7 @@ std::expected RawSocket::Receive() noexcept { // batch buffer admits frames the MAX_FRAME_SIZE-sized Linux scratch would have refused, so // enforce the same ceiling here at capture. if (header.bh_caplen > MAX_FRAME_SIZE) { - NFL_LOG_WARN(logger_, "Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", + NFL_LOG_WARN_RATE(logger_, 60, "Dropping oversized frame: {} bytes exceeds the {}-byte frame ceiling", header.bh_caplen, MAX_FRAME_SIZE); return std::unexpected(ReceiveError::Dropped); } diff --git a/src/reflector/ssdp_reflector.cpp b/src/reflector/ssdp_reflector.cpp index 34030ba..204999b 100644 --- a/src/reflector/ssdp_reflector.cpp +++ b/src/reflector/ssdp_reflector.cpp @@ -186,7 +186,8 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { : existing_session->reservation.Port(); if (!target_socket_->SendUdpMulticastDatagram(packet.header.dest, port, packet.payload, SSDP_TTL)) { - NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR_RATE(logger_, 60, + "Cannot reflect M-SEARCH from {} to {}", packet.header.source, packet.header.dest); return; // a new session's reservation + response registration RAII-drop here } NFL_LOG_DEBUG(logger_, "Reflected M-SEARCH from {} on reserved port {} (MX {}s)", @@ -210,7 +211,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { std::optional SsdpReflector::MakeSession(const Packet& packet, std::chrono::steady_clock::time_point expiry) { if (sessions_.size() >= MAX_SESSIONS) { - NFL_LOG_WARN(logger_, "Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", + NFL_LOG_WARN_RATE(logger_, 60, "Dropping M-SEARCH from {}: {} sessions in flight (cap reached)", packet.header.source, sessions_.size()); return std::nullopt; } @@ -219,7 +220,8 @@ std::optional SsdpReflector::MakeSession(const Packet& p // that re-emit — so responders' unicast 200-OKs land on the reserved address. const auto our_address = target_interface.SourceAddressFor(packet.header.dest.addr); if (!our_address) { - NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {}: target interface has no source address for {}", + NFL_LOG_ERROR_RATE(logger_, 60, + "Cannot reflect M-SEARCH from {}: target interface has no source address for {}", packet.header.source, packet.header.dest.addr.AddressFamily()); return std::nullopt; } @@ -232,7 +234,7 @@ std::optional SsdpReflector::MakeSession(const Packet& p PacketFilter{.dest_ip = our_address, .dest_port = reservation->Port(), .source_mac = config_mac_}, CreateDelegate<&SsdpReflector::OnUnicastResponse>(this)); if (!registration.IsValid()) { - NFL_LOG_ERROR(logger_, "Cannot reflect M-SEARCH from {}: response registration failed", + NFL_LOG_ERROR_RATE(logger_, 60, "Cannot reflect M-SEARCH from {}: response registration failed", packet.header.source); return std::nullopt; // reservation RAII-drops here, freeing the port } @@ -263,7 +265,8 @@ void SsdpReflector::OnTargetPacket(const Packet& packet) noexcept { ? std::as_bytes(std::span{rewrite.payload}) : packet.payload; if (!source_socket_->SendUdpMulticastDatagram(packet.header.dest, SSDP_PORT, payload, SSDP_TTL)) { - NFL_LOG_ERROR(logger_, "Cannot reflect ssdp packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_ERROR_RATE(logger_, 60, + "Cannot reflect ssdp packet from {} to {}", packet.header.source, packet.header.dest); return; } NFL_LOG_DEBUG(logger_, "Reflected ssdp packet from {} to {}", packet.header.source, packet.header.dest); @@ -296,7 +299,7 @@ void SsdpReflector::OnUnicastResponse(const Packet& packet) noexcept { : packet.payload; if (!source_socket_->SendUdpDatagram(session.searcher_mac, session.searcher, packet.header.source.port, payload, SSDP_TTL)) { - NFL_LOG_ERROR(logger_, "Cannot reflect SSDP response to searcher {}", session.searcher); + NFL_LOG_ERROR_RATE(logger_, 60, "Cannot reflect SSDP response to searcher {}", session.searcher); return; } NFL_LOG_DEBUG(logger_, "Reflected SSDP response from {} to searcher {}", packet.header.source, diff --git a/src/reflector/wol_reflector.cpp b/src/reflector/wol_reflector.cpp index 504d3ca..34262d5 100644 --- a/src/reflector/wol_reflector.cpp +++ b/src/reflector/wol_reflector.cpp @@ -163,7 +163,7 @@ void WolReflector::OnPacket(const Packet& packet) noexcept { : target_socket_->SendUdpMulticastDatagram( {destination, port}, packet.header.source.port, packet.payload, packet.header.ttl); if (!sent) { - NFL_LOG_ERROR(logger_, "Cannot reflect wol packet from {} to {}:{}", + NFL_LOG_ERROR_RATE(logger_, 60, "Cannot reflect wol packet from {} to {}:{}", packet.header.source, destination, port); return; } diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index 339d833..0329c87 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -242,6 +242,8 @@ TEST(LoggerTest, ADisclosureOutlivesAnOverlongMessage) { EXPECT_NE(output.find("(7 suppressed)"), std::string::npos) << tail; } +// Wants a gate that has never emitted, so it does not survive --gtest_repeat: the static below holds +// its window across iterations. Every lane runs each test once. TEST(LoggerTest, ARateLimitedCallSiteEmitsOncePerWindow) { const ScopedMinLogLevel level{LogLevel::Info}; Logger logger{"RateLogger"}; diff --git a/tests/mdns_reflector_test.cpp b/tests/mdns_reflector_test.cpp index f5a17f5..86238e6 100644 --- a/tests/mdns_reflector_test.cpp +++ b/tests/mdns_reflector_test.cpp @@ -488,17 +488,16 @@ TEST_F(MdnsReflectorTest, DropsWrongDirectionSilently) { EXPECT_EQ(output.find("non-mDNS"), std::string::npos) << output; } -TEST_F(MdnsReflectorTest, LogsErrorWhenSendFails) { +TEST_F(MdnsReflectorTest, DoesNotReflectWhenSendFails) { const MdnsReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; ASSERT_TRUE(reflector.IsValid()); target.fail_send = true; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(source, MakePacket(MakeQuery(), IpAddress::Family::V4)); }); EXPECT_TRUE(target.sent.empty()); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(MdnsReflectorTest, JoinFailureMakesInvalid) { diff --git a/tests/raw_socket_test.cpp b/tests/raw_socket_test.cpp index 3a1ad5a..a31e43c 100644 --- a/tests/raw_socket_test.cpp +++ b/tests/raw_socket_test.cpp @@ -818,12 +818,11 @@ TEST(RawSocketBatchTest, ReceiveDropsBpfTruncatedFrame) { // The frame's real length was far larger than what BPF captured. ASSERT_TRUE(capture.WriteTruncatedFrame(f.bytes, 70000)); - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const auto dropped = capture.socket.Receive(); ASSERT_FALSE(dropped.has_value()); EXPECT_EQ(dropped.error(), LinkSocket::ReceiveError::Dropped); }); - EXPECT_NE(output.find("oversized frame"), std::string::npos) << output; } // A frame can be fully captured (datalen == caplen) yet exceed MAX_FRAME_SIZE when the batch @@ -834,12 +833,11 @@ TEST(RawSocketReceiveTest, DropsFullyCapturedFrameLargerThanTheFrameCeiling) { const std::vector frame(MAX_FRAME_SIZE + 1, std::byte{0xff}); ASSERT_TRUE(capture.WriteFrame(frame)); - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const auto dropped = capture.socket.Receive(); ASSERT_FALSE(dropped.has_value()); EXPECT_EQ(dropped.error(), LinkSocket::ReceiveError::Dropped); }); - EXPECT_NE(output.find("oversized frame"), std::string::npos) << output; } #endif // !defined(__linux__) diff --git a/tests/ssdp_reflector_test.cpp b/tests/ssdp_reflector_test.cpp index 78fdb04..146a537 100644 --- a/tests/ssdp_reflector_test.cpp +++ b/tests/ssdp_reflector_test.cpp @@ -586,19 +586,18 @@ TEST_F(SsdpReflectorTest, DropsWrongDirectionSilently) { EXPECT_EQ(output.find("non-SSDP"), std::string::npos) << output; } -TEST_F(SsdpReflectorTest, LogsErrorWhenSendFails) { +TEST_F(SsdpReflectorTest, DoesNotReflectWhenSendFails) { SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; ASSERT_TRUE(reflector.IsValid()); const size_t base = RegistrationCount(); target.fail_send = true; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(source, MakePacket(MakeSearch(), IpAddress::SsdpGroupV4())); }); EXPECT_TRUE(target.sent.empty()); EXPECT_EQ(RegistrationCount(), base); // the response registration is rolled back on the failed reflect - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, JoinFailureMakesInvalid) { @@ -720,13 +719,12 @@ TEST_F(SsdpReflectorTest, DoesNotReflectMSearchWhenTargetHasNoSourceAddress) { const size_t base = RegistrationCount(); target.iface.SetV4(std::nullopt); // e.g. the interface's v4 address vanished after construction - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(source, MakePacket(MakeSearch(), IpAddress::SsdpGroupV4())); }); EXPECT_TRUE(target.sent.empty()); EXPECT_EQ(RegistrationCount(), base); // no session / capture created - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, DoesNotReflectMSearchWhenResponseRegistrationFails) { @@ -735,13 +733,12 @@ TEST_F(SsdpReflectorTest, DoesNotReflectMSearchWhenResponseRegistrationFails) { const size_t base = RegistrationCount(); // the two multicast registrations packet_dispatcher.fail_register_on_call = base + 1; // fail the session's response registration - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(source, MakePacket(MakeSearch(), IpAddress::SsdpGroupV4())); }); EXPECT_TRUE(target.sent.empty()); // capture failed before the reflect, so nothing is sent EXPECT_EQ(RegistrationCount(), base); // no session; the reservation was rolled back - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, ReflectsUnicastResponseBackToSearcher) { @@ -778,7 +775,7 @@ TEST_F(SsdpReflectorTest, ReflectsUnicastResponseBackToSearcher) { EXPECT_EQ(out.ttl, 2); } -TEST_F(SsdpReflectorTest, LogsErrorWhenReflectingResponseFails) { +TEST_F(SsdpReflectorTest, DoesNotReflectAResponseWhenSendFails) { SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; ASSERT_TRUE(reflector.IsValid()); @@ -796,12 +793,11 @@ TEST_F(SsdpReflectorTest, LogsErrorWhenReflectingResponseFails) { }, .payload = response, }; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(target, reply); }); EXPECT_TRUE(source.sent.empty()); // nothing reflected to the searcher - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, IgnoresUnicastResponseWithNoMatchingSession) { @@ -901,10 +897,9 @@ TEST_F(SsdpReflectorTest, SessionCapIsGlobalAcrossGroups) { // The overflow searcher targets v6 site-local, which so far holds only about a third of the table. Packet overflow = MakePacket(search_payload, IpAddress::SsdpGroupV6SiteLocal()); overflow.header.source.port = static_cast(20000 + SsdpReflector::MAX_SESSIONS); - const std::string output = CaptureStdout([&] { packet_dispatcher.Deliver(source, overflow); }); + CaptureStdout([&] { packet_dispatcher.Deliver(source, overflow); }); EXPECT_EQ(target.sent.size(), SsdpReflector::MAX_SESSIONS); // not reflected: MakeSession returned nullopt before the reflect - EXPECT_NE(output.find("cap reached"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, RetransmittedMSearchReusesOneSessionAndReflectsEach) { @@ -1331,17 +1326,16 @@ TEST_F(SsdpReflectorTest, DialForwardsResponseLocationUnchangedWhenListenerMintF EXPECT_NE(output.find("no listener"), std::string::npos) << output; // surfaced at INFO } -TEST_F(SsdpReflectorTest, LogsErrorWhenReflectingAdvertisementFails) { +TEST_F(SsdpReflectorTest, DoesNotReflectAnAdvertisementWhenSendFails) { SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; ASSERT_TRUE(reflector.IsValid()); source.fail_send = true; // re-emitting the advertisement to source will fail - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(target, MakePacket(MakeAdvertisement(), IpAddress::SsdpGroupV4())); }); EXPECT_TRUE(source.sent.empty()); // nothing reflected - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, DoesNotRewriteDialContentInAnMSearch) { diff --git a/tests/wol_reflector_test.cpp b/tests/wol_reflector_test.cpp index 9c58705..f8fa1ca 100644 --- a/tests/wol_reflector_test.cpp +++ b/tests/wol_reflector_test.cpp @@ -286,18 +286,17 @@ TEST_F(WolReflectorTest, DualModeInvalidWhenAFamilyIsUnavailable) { EXPECT_FALSE(reflector.IsValid()); } -TEST_F(WolReflectorTest, LogsErrorWhenSendFails) { +TEST_F(WolReflectorTest, DoesNotReflectWhenSendFails) { auto reflector = BuildV4Reflector(MakeConfig(IpAddress::Family::V4)); ASSERT_TRUE(reflector.IsValid()); target.fail_send = true; const auto payload = MakeMagicPacket(*MakeConfig(IpAddress::Family::V4).mac); - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(MakePacket(payload, IpAddress::FromV4Bytes(192, 0, 2, 1), 9)); }); EXPECT_TRUE(target.sent.empty()); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(WolReflectorTest, ReflectedLogShowsMacAndInterfaces) { From ed5e0751bae5a92279587f7344cd772ef1701868 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Tue, 11 Aug 2026 20:41:56 +0200 Subject: [PATCH 08/10] feat: add trace and off log levels Trace is for the detail that only matters when reconstructing what the daemon did, so a release build drops those statements rather than testing a level for them: NDEBUG lowers a compile-time floor the macros check before anything else. The arguments still compile, so a Trace line cannot rot in the configuration that leaves it out. Off completes the set the config file accepts. Both levels parse from the file and from REFLECTOR_LOG_LEVEL, which share a parser. No site logs at Trace yet. --- README.md | 2 +- config.toml | 2 +- src/reflector/config/config.cpp | 5 +++- src/reflector/logger.h | 51 +++++++++++++++++++++++---------- tests/config_test.cpp | 12 ++++++++ tests/logger_test.cpp | 35 ++++++++++++++++++++++ 6 files changed, 89 insertions(+), 18 deletions(-) diff --git a/README.md b/README.md index 07ffd22..8a37388 100644 --- a/README.md +++ b/README.md @@ -202,7 +202,7 @@ On RouterOS, setting the container's environment variables is usually easier tha `config.toml` contains optional top-level settings plus at least one reflector entry. Entries are tables under `reflectors`, keyed by name (`[reflectors.]`) — the name is the label used in logs — each describing one `source_if` → `target_if` bridge that enables any combination of the protocols. The top-level settings are `log_level` and `debug_memory`: ```toml -log_level = "info" # optional; one of debug | info | warn | error (default: info) +log_level = "info" # optional; one of trace | debug | info | warn | error | off (default: info) debug_memory = false # optional; periodically log RSS + heap arena stats for footprint debugging (default false) [reflectors.tv] diff --git a/config.toml b/config.toml index 83f9190..60e3707 100644 --- a/config.toml +++ b/config.toml @@ -1,4 +1,4 @@ -# log_level = "info" # debug | info | warn | error +# log_level = "info" # trace | debug | info | warn | error | off # debug_memory = false # periodically log RSS + heap arena stats for footprint debugging # A single device: bridge its Wake-on-LAN, mDNS, and SSDP. The one mac is the device's NIC MAC — diff --git a/src/reflector/config/config.cpp b/src/reflector/config/config.cpp index 5c5e5c5..213c9a7 100644 --- a/src/reflector/config/config.cpp +++ b/src/reflector/config/config.cpp @@ -29,11 +29,14 @@ std::string_view ToStringView(const toml::key& key) { std::expected LogLevelFromString(std::string_view s) { const auto lower = AsciiToLower(s); + if (lower == "trace") return LogLevel::Trace; if (lower == "debug") return LogLevel::Debug; if (lower == "info") return LogLevel::Info; if (lower == "warn") return LogLevel::Warn; if (lower == "error") return LogLevel::Error; - return std::unexpected(Error{"log_level must be one of: debug, info, warn, error; got \"{}\"", s}); + if (lower == "off") return LogLevel::Off; + return std::unexpected( + Error{"log_level must be one of: trace, debug, info, warn, error, off; got \"{}\"", s}); } std::expected AddressFamilyFromString(std::string_view section, std::string_view s) { diff --git a/src/reflector/logger.h b/src/reflector/logger.h index 99d1103..b1ae741 100644 --- a/src/reflector/logger.h +++ b/src/reflector/logger.h @@ -13,13 +13,26 @@ namespace reflector { +// Ordered by severity, so filtering is a plain comparison. Off is above Error and no record carries +// it, so selecting it admits nothing. enum class LogLevel : uint8_t { + Trace, Debug, Info, Warn, Error, + Off, }; +// Trace costs nothing in a release build: the macros discard the statement rather than testing a +// level for it. The arguments are still compiled and type-checked, so a Trace line cannot rot +// unnoticed in the configuration that omits it. +#if defined(NDEBUG) +inline constexpr LogLevel STATIC_MIN_LOG_LEVEL = LogLevel::Debug; +#else +inline constexpr LogLevel STATIC_MIN_LOG_LEVEL = LogLevel::Trace; +#endif + namespace detail { template @@ -130,10 +143,13 @@ struct std::formatter FmtContext::iterator format(const reflector::LogLevel& l, FmtContext& ctx) const { switch (l) { using enum reflector::LogLevel; + case Trace: return std::format_to(ctx.out(), "TRACE"); case Debug: return std::format_to(ctx.out(), "DEBUG"); case Info: return std::format_to(ctx.out(), "INFO"); case Warn: return std::format_to(ctx.out(), "WARN"); case Error: return std::format_to(ctx.out(), "ERROR"); + // Never reaches a record, but it is a level a config can name. + case Off: return std::format_to(ctx.out(), "OFF"); } std::unreachable(); @@ -143,13 +159,16 @@ struct std::formatter // The only level gate. A filtered record never reaches Emit, so it never evaluates its arguments: // a suppressed Debug line would otherwise still build every Error::FromErrno() and ToString() it // passes. NFL_ rather than a bare LOG_, which syslog.h already defines. -#define NFL_LOG(logger, level, ...) \ - do { \ - if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ - (logger).Emit(::reflector::LogLevel::level, __VA_ARGS__); \ - } \ +#define NFL_LOG(logger, level, ...) \ + do { \ + if constexpr (::reflector::LogLevel::level >= ::reflector::STATIC_MIN_LOG_LEVEL) { \ + if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ + (logger).Emit(::reflector::LogLevel::level, __VA_ARGS__); \ + } \ + } \ } while (false) +#define NFL_LOG_TRACE(logger, ...) NFL_LOG(logger, Trace, __VA_ARGS__) #define NFL_LOG_DEBUG(logger, ...) NFL_LOG(logger, Debug, __VA_ARGS__) #define NFL_LOG_INFO(logger, ...) NFL_LOG(logger, Info, __VA_ARGS__) #define NFL_LOG_WARN(logger, ...) NFL_LOG(logger, Warn, __VA_ARGS__) @@ -157,16 +176,18 @@ struct std::formatter // Emits at most once per window per call site. A call landing inside a closed window is counted // instead, and the next line that does emit discloses the count. -#define NFL_LOG_RATE(logger, level, window_secs, ...) \ - do { \ - if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ - static ::reflector::detail::RateGate nfl_rate_gate{(window_secs)}; \ - const auto nfl_suppressed = \ - nfl_rate_gate.Admit(::reflector::detail::MonotonicSecs()); \ - if (nfl_suppressed) { \ - (logger).EmitRated(::reflector::LogLevel::level, *nfl_suppressed, __VA_ARGS__); \ - } \ - } \ +#define NFL_LOG_RATE(logger, level, window_secs, ...) \ + do { \ + if constexpr (::reflector::LogLevel::level >= ::reflector::STATIC_MIN_LOG_LEVEL) { \ + if (::reflector::LogLevel::level >= ::reflector::Logger::MinLevel()) { \ + static ::reflector::detail::RateGate nfl_rate_gate{(window_secs)}; \ + const auto nfl_suppressed = \ + nfl_rate_gate.Admit(::reflector::detail::MonotonicSecs()); \ + if (nfl_suppressed) { \ + (logger).EmitRated(::reflector::LogLevel::level, *nfl_suppressed, __VA_ARGS__); \ + } \ + } \ + } \ } while (false) #define NFL_LOG_WARN_RATE(logger, window_secs, ...) \ diff --git a/tests/config_test.cpp b/tests/config_test.cpp index 56add9a..ffd87b1 100644 --- a/tests/config_test.cpp +++ b/tests/config_test.cpp @@ -345,6 +345,18 @@ wol = true EXPECT_EQ(config->MinLogLevel(), LogLevel::Info); } +TEST(ConfigTest, ParsesLogLevelTrace) { + const auto config = Config::FromString(TomlWithLogLevel("trace")); + ASSERT_TRUE(config.has_value()) << config.error().Message(); + EXPECT_EQ(config->MinLogLevel(), LogLevel::Trace); +} + +TEST(ConfigTest, ParsesLogLevelOff) { + const auto config = Config::FromString(TomlWithLogLevel("off")); + ASSERT_TRUE(config.has_value()) << config.error().Message(); + EXPECT_EQ(config->MinLogLevel(), LogLevel::Off); +} + TEST(ConfigTest, ParsesLogLevelDebug) { const auto config = Config::FromString(TomlWithLogLevel("debug")); ASSERT_TRUE(config.has_value()) << config.error().Message(); diff --git a/tests/logger_test.cpp b/tests/logger_test.cpp index 0329c87..62f9595 100644 --- a/tests/logger_test.cpp +++ b/tests/logger_test.cpp @@ -97,10 +97,45 @@ TEST(LoggerTest, DynamicNameSurvivesMoveConstructionAndAssignment) { } TEST(LoggerTest, FormatsLogLevelNames) { + EXPECT_EQ(std::format("{}", LogLevel::Trace), "TRACE"); EXPECT_EQ(std::format("{}", LogLevel::Debug), "DEBUG"); EXPECT_EQ(std::format("{}", LogLevel::Info), "INFO"); EXPECT_EQ(std::format("{}", LogLevel::Warn), "WARN"); EXPECT_EQ(std::format("{}", LogLevel::Error), "ERROR"); + EXPECT_EQ(std::format("{}", LogLevel::Off), "OFF"); +} + +// The contract differs by build, so the test does too: a release build has no Trace statement left +// to run, and every other build emits one when the level allows it. +TEST(LoggerTest, ReleaseBuildsCarryNoTraceStatement) { + const ScopedMinLogLevel level{LogLevel::Trace}; + Logger logger{"TraceLogger"}; + + const std::string output = CaptureStdout([&] { + NFL_LOG_TRACE(logger, "a trace message"); + }); + +#if defined(NDEBUG) + EXPECT_EQ(output.find("a trace message"), std::string::npos) << output; +#else + EXPECT_NE(output.find("a trace message"), std::string::npos) << output; + EXPECT_NE(output.find("TRACE"), std::string::npos) << output; +#endif +} + +TEST(LoggerTest, OffSuppressesEveryLevel) { + const ScopedMinLogLevel level{LogLevel::Off}; + Logger logger{"OffLogger"}; + + const std::string output = CaptureStdout([&] { + NFL_LOG_TRACE(logger, "trace record"); + NFL_LOG_DEBUG(logger, "debug record"); + NFL_LOG_INFO(logger, "info record"); + NFL_LOG_WARN(logger, "warn record"); + NFL_LOG_ERROR(logger, "error record"); + }); + + EXPECT_TRUE(output.empty()) << output; } TEST(LoggerTest, LogLineIncludesSourceLocation) { From 8b0e9fc71ab6c3e08e29f585b73743db042e1296 Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Wed, 12 Aug 2026 00:38:21 +0200 Subject: [PATCH 09/10] feat: log the per-event detail at trace Debug now means one line per lifecycle event: an interface resolved, a group joined, a capture re-bound. Everything that fires per packet, per fd operation or per address examined moved to trace, which a release build does not carry. The new lines are mostly address selection: which v4 won, which v6 took the source or routable slot and at what rank, and what the flags filtered out. That reasoning was invisible before, and it decides what the daemon can send from. --- src/reflector/default_address_monitor.cpp | 2 +- src/reflector/default_packet_dispatcher.cpp | 17 ++++++++++++---- src/reflector/event_loop_dispatcher.cpp | 18 +++++++++-------- src/reflector/http_message.cpp | 2 +- src/reflector/interface_address.cpp | 22 +++++++++++++++++---- src/reflector/mdns_reflector.cpp | 2 +- src/reflector/raw_socket.cpp | 7 ++++--- src/reflector/ssdp_reflector.cpp | 14 ++++++------- src/reflector/tcp_socket.cpp | 11 ++++++----- src/reflector/wol_reflector.cpp | 10 +++++----- tests/ssdp_reflector_test.cpp | 6 ++++-- 11 files changed, 70 insertions(+), 41 deletions(-) diff --git a/src/reflector/default_address_monitor.cpp b/src/reflector/default_address_monitor.cpp index 69dc08b..e4dc073 100644 --- a/src/reflector/default_address_monitor.cpp +++ b/src/reflector/default_address_monitor.cpp @@ -201,7 +201,7 @@ void DefaultAddressMonitor::OnReadable(int /*fd*/) noexcept { // A local process can unicast a netlink datagram to this socket (user-to-user needs no // privilege), spoofing an address change; drop anything whose source isn't the kernel. if (verify_sender_ && !detail::NetlinkSenderIsKernel(src, addrlen)) { - NFL_LOG_DEBUG(GetLogger(), "Dropping an address notification from a non-kernel sender"); + NFL_LOG_TRACE(GetLogger(), "Dropping an address notification from a non-kernel sender"); continue; } // Once overflowed we'll emit a single refresh-all, so keep draining the socket but stop diff --git a/src/reflector/default_packet_dispatcher.cpp b/src/reflector/default_packet_dispatcher.cpp index b866cd1..8ea9ccd 100644 --- a/src/reflector/default_packet_dispatcher.cpp +++ b/src/reflector/default_packet_dispatcher.cpp @@ -53,7 +53,7 @@ PacketDispatcher::Registration DefaultPacketDispatcher::Register( // capture source's count. const auto id = static_cast(next_registration_id_++); registrations_.emplace_back(id, &source->second, callback, filter); - NFL_LOG_DEBUG(GetLogger(), "Registered packet callback {} for fd {}", std::to_underlying(id), fd); + NFL_LOG_TRACE(GetLogger(), "Registered packet callback {} for fd {}", std::to_underlying(id), fd); return MakeRegistration(id); } @@ -65,7 +65,7 @@ bool DefaultPacketDispatcher::Unregister(RegistrationId id) noexcept { NFL_LOG_WARN(GetLogger(), "Cannot unregister packet callback {}: not found", std::to_underlying(id)); return false; } - NFL_LOG_DEBUG(GetLogger(), "Unregistered packet callback {}", std::to_underlying(id)); + NFL_LOG_TRACE(GetLogger(), "Unregistered packet callback {}", std::to_underlying(id)); if (dispatching_) { it->enabled = false; // DrainReadableFd is walking; defer the erase + teardown to its sweep return true; @@ -101,10 +101,11 @@ bool DefaultPacketDispatcher::DrainReadableFd(LinkSocket& socket) noexcept { dispatching_ = true; bool failed = false; + size_t packet_count = 0; #if defined(__linux__) - for (size_t packet_count = 0; packet_count < MAX_PACKETS_PER_READ_EVENT; ++packet_count) { + for (; packet_count < MAX_PACKETS_PER_READ_EVENT; ++packet_count) { #else - for (size_t packet_count = 0; packet_count < MAX_PACKETS_PER_READ_EVENT || socket.HasBufferedData(); ++packet_count) { + for (; packet_count < MAX_PACKETS_PER_READ_EVENT || socket.HasBufferedData(); ++packet_count) { #endif const auto packet = socket.Receive(); if (!packet) { @@ -126,6 +127,8 @@ bool DefaultPacketDispatcher::DrainReadableFd(LinkSocket& socket) noexcept { DispatchPacket(socket, *packet); } + NFL_LOG_TRACE(GetLogger(), "Drained {} frame(s)", packet_count); + dispatching_ = false; Sweep(); return !failed; @@ -137,12 +140,18 @@ void DefaultPacketDispatcher::DispatchPacket(const LinkSocket& socket, const Pac // so index by position and re-fetch each iteration, never holding an iterator across the callback. // Removal is deferred to the sweep, so the walk never shifts and needs no restart. A callback that // Registers appends a higher entry this loop still reaches, dispatching it for the current packet. + size_t matched = 0; for (size_t idx = 0; idx < registrations_.size(); ++idx) { const auto& entry = registrations_[idx]; if (entry.enabled && entry.capture_source->socket == &socket && entry.filter.Matches(packet)) { + ++matched; entry.callback(packet); } } + if (matched == 0) { + NFL_LOG_TRACE(GetLogger(), "No registration matched {} -> {}", packet.header.source, + packet.header.dest); + } } void DefaultPacketDispatcher::Sweep() noexcept { diff --git a/src/reflector/event_loop_dispatcher.cpp b/src/reflector/event_loop_dispatcher.cpp index 6bbb336..53121d0 100644 --- a/src/reflector/event_loop_dispatcher.cpp +++ b/src/reflector/event_loop_dispatcher.cpp @@ -48,7 +48,7 @@ EventLoopDispatcher::EventLoopDispatcher() { if (!event_fd_) { NFL_LOG_ERROR(GetLogger(), "Cannot create dispatcher event queue: {}", Error::FromErrno()); } else { - NFL_LOG_DEBUG(GetLogger(), "Created dispatcher event queue fd {}", event_fd_.Get()); + NFL_LOG_TRACE(GetLogger(), "Created dispatcher event queue fd {}", event_fd_.Get()); } } @@ -61,7 +61,7 @@ EventLoopDispatcher::~EventLoopDispatcher() noexcept { } if (event_fd_) { - NFL_LOG_DEBUG(GetLogger(), "Closing dispatcher event queue fd {}", event_fd_.Get()); + NFL_LOG_TRACE(GetLogger(), "Closing dispatcher event queue fd {}", event_fd_.Get()); event_fd_.Reset(); } } @@ -90,7 +90,7 @@ Dispatcher::Registration EventLoopDispatcher::Register(int fd, FdCallbacks callb return {}; } - NFL_LOG_DEBUG(GetLogger(), "Registered fd callback for fd {}", fd); + NFL_LOG_TRACE(GetLogger(), "Registered fd callback for fd {}", fd); return MakeRegistration(fd); } @@ -122,7 +122,7 @@ bool EventLoopDispatcher::Unregister(int fd) noexcept { NFL_LOG_ERROR(GetLogger(), "Cannot remove events for fd {} after unregistering its callback", fd); } - NFL_LOG_DEBUG(GetLogger(), "Unregistered fd callback for fd {}", fd); + NFL_LOG_TRACE(GetLogger(), "Unregistered fd callback for fd {}", fd); return true; } @@ -155,6 +155,7 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { if (event_count < 0) { if (errno == EINTR) { // Expected when a signal interrupts polling; callers decide whether to retry or shut down. + NFL_LOG_TRACE(GetLogger(), "Poll interrupted by a signal"); return false; } NFL_LOG_ERROR(GetLogger(), "Cannot poll dispatcher read events: {}", Error::FromErrno()); @@ -172,6 +173,7 @@ bool EventLoopDispatcher::PollOnce(std::chrono::milliseconds timeout) { if (event_count < 0) { if (errno == EINTR) { // Expected when a signal interrupts polling; callers decide whether to retry or shut down. + NFL_LOG_TRACE(GetLogger(), "Poll interrupted by a signal"); return false; } NFL_LOG_ERROR(GetLogger(), "Cannot poll dispatcher read events: {}", Error::FromErrno()); @@ -261,7 +263,7 @@ bool EventLoopDispatcher::RegisterTimer( } else { timers_.push_back(registration); } - NFL_LOG_DEBUG(GetLogger(), "Registered timer {} (interval {}ms); {} active", static_cast(id), + NFL_LOG_TRACE(GetLogger(), "Registered timer {} (interval {}ms); {} active", static_cast(id), interval.count(), std::ranges::count_if(timers_, [](const TimerEntry& entry) { return entry.enabled; })); return true; } @@ -278,7 +280,7 @@ void EventLoopDispatcher::UnregisterTimer(TimerId id) noexcept { } else { timers_.erase(it); // no walk in progress; erase in place } - NFL_LOG_DEBUG(GetLogger(), "Unregistered timer {}; {} active", static_cast(id), + NFL_LOG_TRACE(GetLogger(), "Unregistered timer {}; {} active", static_cast(id), std::ranges::count_if(timers_, [](const TimerEntry& t) { return t.enabled; })); } @@ -361,7 +363,7 @@ bool EventLoopDispatcher::SetEvents(int fd, bool enable_write) noexcept { } #endif - NFL_LOG_DEBUG(GetLogger(), "Set events for fd {}: write {}", fd, enable_write); + NFL_LOG_TRACE(GetLogger(), "Set events for fd {}: write {}", fd, enable_write); return true; } @@ -396,7 +398,7 @@ bool EventLoopDispatcher::RemoveEvents(int fd) noexcept { } #endif - NFL_LOG_DEBUG(GetLogger(), "Removed events for fd {}", fd); + NFL_LOG_TRACE(GetLogger(), "Removed events for fd {}", fd); return true; } diff --git a/src/reflector/http_message.cpp b/src/reflector/http_message.cpp index da628ad..3754553 100644 --- a/src/reflector/http_message.cpp +++ b/src/reflector/http_message.cpp @@ -147,7 +147,7 @@ bool HttpFraming::ScanAndRewriteHeader() { if (const auto found = ParseAuthority(value, /*bare=*/is_host)) { if (const auto repl = rewrite_(found->endpoint)) { // Log before the splice: `line` views into header_, which the replace may reallocate. - NFL_LOG_DEBUG(GetLogger(), "rewrote {} authority {} -> {}", line.substr(0, colon), + NFL_LOG_TRACE(GetLogger(), "rewrote {} authority {} -> {}", line.substr(0, colon), found->endpoint, *repl); const std::string repl_text = std::format("{}", *repl); const size_t auth_off = diff --git a/src/reflector/interface_address.cpp b/src/reflector/interface_address.cpp index 6b55e45..4346072 100644 --- a/src/reflector/interface_address.cpp +++ b/src/reflector/interface_address.cpp @@ -67,17 +67,27 @@ void Consider(InterfaceAddresses& result, const IpAddress& address) noexcept { if (address.IsV4()) { if (!result.v4) { result.v4 = address; + NFL_LOG_TRACE(GetLogger(), "v4 {}", address); + } else { + NFL_LOG_TRACE(GetLogger(), "v4 {} ignored; already have {}", address, *result.v4); } return; } - if (!result.v6 || Ipv6Rank(address) < Ipv6Rank(*result.v6)) { + const bool took_v6 = !result.v6 || Ipv6Rank(address) < Ipv6Rank(*result.v6); + if (took_v6) { result.v6 = address; } - if (!address.IsLinkLocal() - && (!result.v6_routable || Ipv6Rank(address) < Ipv6Rank(*result.v6_routable))) { + const bool took_routable = !address.IsLinkLocal() + && (!result.v6_routable || Ipv6Rank(address) < Ipv6Rank(*result.v6_routable)); + if (took_routable) { result.v6_routable = address; } + NFL_LOG_TRACE(GetLogger(), "v6 {} rank {} -> {}", address, Ipv6Rank(address), + took_v6 && took_routable ? "source and routable" + : took_v6 ? "source" + : took_routable ? "routable" + : "not selected"); } #if defined(__linux__) @@ -152,7 +162,7 @@ template // Only the kernel (nl_pid 0) may answer the dump; a local process could unicast a spoofed // reply to inject a bogus address. Discard anything else and read the next datagram. if (addrlen < sizeof(src) || src.nl_pid != 0) { - NFL_LOG_DEBUG(GetLogger(), "Ignoring a netlink dump reply from a non-kernel sender (pid {})", src.nl_pid); + NFL_LOG_TRACE(GetLogger(), "Ignoring a netlink dump reply from a non-kernel sender (pid {})", src.nl_pid); continue; } @@ -197,6 +207,7 @@ bool ResolveViaNetlink(unsigned index, InterfaceAddresses& result) noexcept { if (attr->rta_type == IFLA_ADDRESS && RTA_PAYLOAD(attr) == MAC_SIZE) { const auto* mac = static_cast(RTA_DATA(attr)); result.mac = MacAddress::FromBytes(std::span{mac, MAC_SIZE}); + NFL_LOG_TRACE(GetLogger(), "mac {}", result.mac); break; // exactly one IFLA_ADDRESS per link message } } @@ -233,6 +244,7 @@ bool ResolveViaNetlink(unsigned index, InterfaceAddresses& result) noexcept { } } if (!IsUsable(flags)) { + NFL_LOG_TRACE(GetLogger(), "address filtered: ifa_flags {:#06x}", flags); return; } @@ -312,6 +324,7 @@ bool ResolveViaGetifaddrs(std::string_view interface, InterfaceAddresses& result sockaddr_in6 sin6{}; std::memcpy(&sin6, ifa->ifa_addr, sizeof(sin6)); if (!IsUsableIpv6(inet6_fd, ifa->ifa_name, sin6)) { + NFL_LOG_TRACE(GetLogger(), "v6 address on \"{}\" filtered by its flags", ifa->ifa_name); break; } if (auto address = IpAddress::FromSockaddr(ifa->ifa_addr); address) { @@ -324,6 +337,7 @@ bool ResolveViaGetifaddrs(std::string_view interface, InterfaceAddresses& result } case AF_LINK: result.mac = detail::MacFromLinkSockaddr(*ifa->ifa_addr); + NFL_LOG_TRACE(GetLogger(), "mac {}", result.mac); break; default: break; diff --git a/src/reflector/mdns_reflector.cpp b/src/reflector/mdns_reflector.cpp index 3fc8fbf..82e267e 100644 --- a/src/reflector/mdns_reflector.cpp +++ b/src/reflector/mdns_reflector.cpp @@ -145,7 +145,7 @@ void MdnsReflector::Relay(LinkSocket& egress, const Packet& packet) noexcept { "Cannot reflect mdns packet from {} to {}", packet.header.source, packet.header.dest); return; } - NFL_LOG_DEBUG(logger_, "Reflected mdns packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_TRACE(logger_, "Reflected mdns packet from {} to {}", packet.header.source, packet.header.dest); } } // namespace reflector diff --git a/src/reflector/raw_socket.cpp b/src/reflector/raw_socket.cpp index e2e3be8..83e7da1 100644 --- a/src/reflector/raw_socket.cpp +++ b/src/reflector/raw_socket.cpp @@ -601,7 +601,7 @@ void RawSocket::ClearBuffer() noexcept { void RawSocket::Close() noexcept { if (fd_) { - NFL_LOG_DEBUG(logger_, "Closing socket"); + NFL_LOG_TRACE(logger_, "Closing socket"); fd_.Reset(); } // Drop the join fds and their membership bookkeeping together, so the "fd open iff the family @@ -766,7 +766,7 @@ std::optional RawSocket::ParseFrame(std::span frame) no const auto flags_fragment = ReadU16Be(l3.subspan<6, 2>()); // MF set or fragment offset non-zero indicates a fragment; reassembly is out of scope. if ((flags_fragment & 0x3fff) != 0) { - NFL_LOG_DEBUG(logger_, "Dropping IPv4 fragment (flags/offset {:#x})", flags_fragment); + NFL_LOG_TRACE(logger_, "Dropping IPv4 fragment (flags/offset {:#x})", flags_fragment); return std::nullopt; } if (std::to_integer(l3[9]) != IP_PROTO_UDP) { @@ -803,7 +803,8 @@ std::optional RawSocket::ParseFrame(std::span frame) no const auto next_header = std::to_integer(l3[6]); // Extension headers (Fragment, Hop-by-Hop, Routing, ...) all fail this check. if (next_header != IP_PROTO_UDP) { - NFL_LOG_DEBUG(logger_, "Dropping IPv6 packet with next-header {} (extension header or non-UDP)", next_header); + NFL_LOG_TRACE(logger_, + "Dropping IPv6 packet with next-header {} (extension header or non-UDP)", next_header); return std::nullopt; } // Trim by payload_length for the same reason as IPv4 total_length above. diff --git a/src/reflector/ssdp_reflector.cpp b/src/reflector/ssdp_reflector.cpp index 204999b..6df26c3 100644 --- a/src/reflector/ssdp_reflector.cpp +++ b/src/reflector/ssdp_reflector.cpp @@ -162,7 +162,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { if (!parsed_mx) { // A multicast M-SEARCH must carry MX (UDA 2.0), but this fires on every search including // retransmits — one non-conformant client would flood any louder level. - NFL_LOG_DEBUG(logger_, "M-SEARCH from {} has no/invalid MX; using the default {}s window", + NFL_LOG_TRACE(logger_, "M-SEARCH from {} has no/invalid MX; using the default {}s window", packet.header.source, static_cast(mx)); } const auto expiry = std::chrono::steady_clock::now() + std::chrono::seconds{mx} + SESSION_GRACE; @@ -190,7 +190,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { "Cannot reflect M-SEARCH from {} to {}", packet.header.source, packet.header.dest); return; // a new session's reservation + response registration RAII-drop here } - NFL_LOG_DEBUG(logger_, "Reflected M-SEARCH from {} on reserved port {} (MX {}s)", + NFL_LOG_TRACE(logger_, "Reflected M-SEARCH from {} on reserved port {} (MX {}s)", packet.header.source, port, static_cast(mx)); if (!new_session) { @@ -199,7 +199,7 @@ void SsdpReflector::OnSourcePacket(const Packet& packet) noexcept { } sessions_.push_back(std::move(*new_session)); - NFL_LOG_DEBUG(logger_, "Created session for searcher {} on reserved port {}; {} active", + NFL_LOG_TRACE(logger_, "Created session for searcher {} on reserved port {}; {} active", packet.header.source, port, sessions_.size()); // Start the eviction sweep on the first in-flight session; EvictExpired stops it once the table // empties, so the reactor isn't woken every interval while there's nothing to sweep. @@ -269,7 +269,7 @@ void SsdpReflector::OnTargetPacket(const Packet& packet) noexcept { "Cannot reflect ssdp packet from {} to {}", packet.header.source, packet.header.dest); return; } - NFL_LOG_DEBUG(logger_, "Reflected ssdp packet from {} to {}", packet.header.source, packet.header.dest); + NFL_LOG_TRACE(logger_, "Reflected ssdp packet from {} to {}", packet.header.source, packet.header.dest); } void SsdpReflector::OnUnicastResponse(const Packet& packet) noexcept { @@ -302,7 +302,7 @@ void SsdpReflector::OnUnicastResponse(const Packet& packet) noexcept { NFL_LOG_ERROR_RATE(logger_, 60, "Cannot reflect SSDP response to searcher {}", session.searcher); return; } - NFL_LOG_DEBUG(logger_, "Reflected SSDP response from {} to searcher {}", packet.header.source, + NFL_LOG_TRACE(logger_, "Reflected SSDP response from {} to searcher {}", packet.header.source, session.searcher); } @@ -359,7 +359,7 @@ SsdpReflector::DialRewrite SsdpReflector::RewriteDialLocation(std::spanoffset + location->length); - NFL_LOG_DEBUG(logger_, "DIAL: rewrote device {} LOCATION to reflector listener {}", + NFL_LOG_TRACE(logger_, "DIAL: rewrote device {} LOCATION to reflector listener {}", location->endpoint, *reflector_authority); return {.action = DialRewrite::Action::ForwardRewritten, .payload = rewrite_scratch_}; } @@ -392,7 +392,7 @@ void SsdpReflector::EvictExpired(std::chrono::steady_clock::time_point now) noex const auto removed = std::erase_if(sessions_, [this, now](const Session& session) { const bool expired = session.expiry <= now; if (expired) { - NFL_LOG_DEBUG(logger_, "Removing session for searcher {} on reserved port {}", + NFL_LOG_TRACE(logger_, "Removing session for searcher {} on reserved port {}", session.searcher, session.reservation.Port()); } return expired; diff --git a/src/reflector/tcp_socket.cpp b/src/reflector/tcp_socket.cpp index 79df026..210e379 100644 --- a/src/reflector/tcp_socket.cpp +++ b/src/reflector/tcp_socket.cpp @@ -80,9 +80,10 @@ Logger& GetLogger() noexcept { // the source-address bind the caller performs before connect() (and, for link-local IPv6, the scope // id in the destination sockaddr). Correct when the peer is on a directly-connected subnet of // egress_if — the route to it then leaves via egress_if anyway; otherwise the routing table decides. - NFL_LOG_DEBUG(GetLogger(), "No egress-pin primitive; relying on source-address bind to reach via \"{}\"", + NFL_LOG_TRACE(GetLogger(), "No egress-pin primitive; relying on source-address bind to reach via \"{}\"", egress_if.Name()); #endif + NFL_LOG_TRACE(GetLogger(), "Egress pinned to \"{}\"", egress_if.Name()); return true; } @@ -143,7 +144,7 @@ void TcpSocket::Shutdown() noexcept { void TcpSocket::Close() noexcept { if (fd_) { - NFL_LOG_DEBUG(logger_, "Closing socket"); + NFL_LOG_TRACE(logger_, "Closing socket"); fd_.Reset(); } } @@ -404,7 +405,7 @@ SendStatus TcpSocket::Send(std::span data) noexcept { return SendStatus::Overflow; // tail would exceed the cap — owner aborts the connection (drop-and-close) } if (!was_buffering) { - NFL_LOG_DEBUG(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); + NFL_LOG_TRACE(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); } return SendStatus::Ok; } @@ -439,7 +440,7 @@ SendStatus TcpSocket::Send(std::span> chunks) n return SendStatus::Overflow; // tail would exceed the cap — owner aborts the connection (drop-and-close) } if (!was_buffering && !send_buffer_.Empty()) { - NFL_LOG_DEBUG(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); + NFL_LOG_TRACE(logger_, "Started buffering, {} bytes queued", send_buffer_.Size()); } return SendStatus::Ok; } @@ -474,7 +475,7 @@ bool TcpSocket::Flush() noexcept { send_buffer_.Consume(wrote.bytes); } if (was_buffering && send_buffer_.Empty()) { - NFL_LOG_DEBUG(logger_, "Send buffer drained, resumed direct writes"); + NFL_LOG_TRACE(logger_, "Send buffer drained, resumed direct writes"); } return true; } diff --git a/src/reflector/wol_reflector.cpp b/src/reflector/wol_reflector.cpp index 34262d5..31315be 100644 --- a/src/reflector/wol_reflector.cpp +++ b/src/reflector/wol_reflector.cpp @@ -86,25 +86,25 @@ void WolReflector::Initialize(PacketDispatcher& packet_dispatcher, LinkSocket& s // single memcmp and narrows what this reflector will re-broadcast onto target_if. bool WolReflector::IsMagicPacket(std::span payload) noexcept { if (payload.size() < MAGIC_PACKET_SIZE) { - NFL_LOG_DEBUG(logger_, "Ignoring wol packet: payload is too short: {} bytes", payload.size()); + NFL_LOG_TRACE(logger_, "Ignoring wol packet: payload is too short: {} bytes", payload.size()); return false; } if (target_mac_) { if (std::memcmp(payload.data(), expected_magic_packet_.data(), expected_magic_packet_.size()) != 0) { - NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet does not match expected MAC"); + NFL_LOG_TRACE(logger_, "Ignoring wol packet: magic packet does not match expected MAC"); return false; } return true; } if (!HasMagicPacketPrefix(payload)) { - NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet prefix is invalid"); + NFL_LOG_TRACE(logger_, "Ignoring wol packet: magic packet prefix is invalid"); return false; } if (!HasRepeatedMac(payload)) { - NFL_LOG_DEBUG(logger_, "Ignoring wol packet: magic packet MAC repetitions are inconsistent"); + NFL_LOG_TRACE(logger_, "Ignoring wol packet: magic packet MAC repetitions are inconsistent"); return false; } @@ -146,7 +146,7 @@ void WolReflector::OnPacket(const Packet& packet) noexcept { const auto family = packet.header.source.addr.AddressFamily(); if (!target_capability_.CanSend(family)) { - NFL_LOG_DEBUG(logger_, "Ignoring wol packet from {}: {} not handled", + NFL_LOG_TRACE(logger_, "Ignoring wol packet from {}: {} not handled", packet.header.source, family); return; } diff --git a/tests/ssdp_reflector_test.cpp b/tests/ssdp_reflector_test.cpp index 146a537..f1938df 100644 --- a/tests/ssdp_reflector_test.cpp +++ b/tests/ssdp_reflector_test.cpp @@ -976,7 +976,7 @@ TEST_F(SsdpReflectorTest, SameSearcherAndGroupReusesOneSession) { EXPECT_EQ(RegistrationCount(), base + 1); // but one shared session } -TEST_F(SsdpReflectorTest, LogsDefaultedMxAtDebugOnly) { +TEST_F(SsdpReflectorTest, LogsDefaultedMxAtTraceOnly) { SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; ASSERT_TRUE(reflector.IsValid()); @@ -992,12 +992,14 @@ TEST_F(SsdpReflectorTest, LogsDefaultedMxAtDebugOnly) { EXPECT_EQ(output.find("no/invalid MX"), std::string::npos) << output; } { - const ScopedMinLogLevel level{LogLevel::Debug}; + const ScopedMinLogLevel level{LogLevel::Trace}; const std::string output = CaptureStdout([&] { packet_dispatcher.Deliver(source, MakePacket(search_no_mx, IpAddress::SsdpGroupV4())); }); EXPECT_EQ(target.sent.size(), 2u); +#if !defined(NDEBUG) EXPECT_NE(output.find("no/invalid MX"), std::string::npos) << output; +#endif } } From 9abcff422e7d7f44777f92552fea12716cc9a18e Mon Sep 17 00:00:00 2001 From: Sergii Bogomolov Date: Wed, 12 Aug 2026 00:55:29 +0200 Subject: [PATCH 10/10] test: drop log assertions that duplicate a behavioural one Sixteen tests asserted a line reached stdout beside an assertion that already pinned the behaviour producing it: a reflector left invalid, a registration count unchanged, a payload forwarded byte for byte. Log text is not a contract and the assertions break on ordering once a site is rate limited, so the behavioural assertion is the one to keep. The rest stay. A logger test asserting its own output has nothing else to look at, and a name in the record does not prove the message after it survived. --- tests/mdns_reflector_test.cpp | 13 ++++--------- tests/ssdp_reflector_test.cpp | 25 ++++++++----------------- tests/wol_reflector_test.cpp | 6 ++---- 3 files changed, 14 insertions(+), 30 deletions(-) diff --git a/tests/mdns_reflector_test.cpp b/tests/mdns_reflector_test.cpp index 86238e6..a297f58 100644 --- a/tests/mdns_reflector_test.cpp +++ b/tests/mdns_reflector_test.cpp @@ -216,7 +216,6 @@ TEST_P(MdnsReflectorPerFamilyTest, RequiredFamilyUnavailableOnSourceMakesInvalid EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find(std::format("{}", family)), std::string::npos) << output; } TEST_P(MdnsReflectorPerFamilyTest, RequiredFamilyUnavailableOnTargetMakesInvalid) { @@ -246,12 +245,11 @@ TEST_F(MdnsReflectorTest, RejectsInvalidConfig) { auto config = MakeConfig(); config.target_if = config.source_if; // source_if == target_if fails Verify - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const MdnsReflector reflector{packet_dispatcher, source, target, config}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(MdnsReflectorTest, CreatedLogUsesConfigName) { @@ -401,7 +399,7 @@ TEST_F(MdnsReflectorTest, TransientBringUpFailureLeavesFamilyDownThenRetries) { TEST_F(MdnsReflectorTest, FailureBringingUpSecondFamilyRollsBackTheFirst) { packet_dispatcher.fail_register_on_call = 3; // v4 (calls 1-2) succeeds; v6's first registration (3) fails - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const MdnsReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::Dual)}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); // the already-up v4 family was torn down too @@ -420,7 +418,6 @@ TEST_F(MdnsReflectorTest, RejectsAMacFilterOnATargetLinkWithoutMacs) { EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; // Same link without the filter is fine — only the source_mac match is impossible. const MdnsReflector unfiltered{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; @@ -503,24 +500,22 @@ TEST_F(MdnsReflectorTest, DoesNotReflectWhenSendFails) { TEST_F(MdnsReflectorTest, JoinFailureMakesInvalid) { source.fail_join = true; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const MdnsReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(MdnsReflectorTest, RegistrationFailureRollsBackAndInvalidates) { packet_dispatcher.fail_register_on_call = 2; // the second registration fails - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const MdnsReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; EXPECT_FALSE(reflector.IsValid()); }); EXPECT_EQ(RegistrationCount(), 0); // the first registration was rolled back - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(MdnsReflectorTest, DestructorUnregisters) { diff --git a/tests/ssdp_reflector_test.cpp b/tests/ssdp_reflector_test.cpp index f1938df..a655d47 100644 --- a/tests/ssdp_reflector_test.cpp +++ b/tests/ssdp_reflector_test.cpp @@ -280,7 +280,6 @@ TEST_P(SsdpReflectorPerFamilyTest, RequiredFamilyUnavailableOnSourceMakesInvalid EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find(std::format("{}", family)), std::string::npos) << output; } TEST_P(SsdpReflectorPerFamilyTest, RequiredFamilyUnavailableOnTargetMakesInvalid) { @@ -310,12 +309,11 @@ TEST_F(SsdpReflectorTest, RejectsInvalidConfig) { auto config = MakeConfig(); config.target_if = config.source_if; // source_if == target_if fails Verify - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const SsdpReflector reflector{packet_dispatcher, source, target, config}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, CreatedLogUsesConfigName) { @@ -455,11 +453,10 @@ TEST_F(SsdpReflectorTest, TransientBringUpFailureOnALaterGroupLeavesFamilyDownTh // group (link-local) has already taken its memberships/registrations. target.iface.SetHasSource(IpAddress::Family::V6, true); packet_dispatcher.fail_register_on_call = RegistrationCount() + 3; - const std::string output = CaptureStdout([&] { reflector.OnInterfaceChanged(); }); + CaptureStdout([&] { reflector.OnInterfaceChanged(); }); EXPECT_EQ(RegistrationCount(), 2); // bring-up failed -> v6 stays fully down, nothing half-set-up EXPECT_TRUE(reflector.IsValid()); // still valid - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; // the registration failure was logged // the first group's membership, already taken before the second group's failure, was rolled back too EXPECT_NE(std::ranges::find(source.left_groups, IpAddress::SsdpGroupV6LinkLocal()), source.left_groups.end()); @@ -475,7 +472,7 @@ TEST_F(SsdpReflectorTest, TransientBringUpFailureOnALaterGroupLeavesFamilyDownTh TEST_F(SsdpReflectorTest, FailureOnALaterGroupRollsBackTheWholeFamily) { packet_dispatcher.fail_register_on_call = 3; // group 1 (calls 1-2) succeeds; group 2's first reg (3) fails - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv6)}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); // the first group's captures were rolled back too @@ -515,7 +512,6 @@ TEST_F(SsdpReflectorTest, RejectsAMacFilterOnATargetLinkWithoutMacs) { EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; // Same link without the filter is fine — only the source_mac match is impossible. const SsdpReflector unfiltered{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; @@ -603,24 +599,22 @@ TEST_F(SsdpReflectorTest, DoesNotReflectWhenSendFails) { TEST_F(SsdpReflectorTest, JoinFailureMakesInvalid) { source.fail_join = true; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(RegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, RegistrationFailureRollsBackAndInvalidates) { packet_dispatcher.fail_register_on_call = 2; // the second registration fails - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const SsdpReflector reflector{packet_dispatcher, source, target, MakeConfig(AddressFamily::IPv4)}; EXPECT_FALSE(reflector.IsValid()); }); EXPECT_EQ(RegistrationCount(), 0); // the first registration was rolled back - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(SsdpReflectorTest, DestructorUnregisters) { @@ -1090,12 +1084,11 @@ TEST_F(SsdpReflectorTest, DialDropsAnAdvertisementWhoseRewriteOverflowsThePayloa // Already at the ceiling, so any growth overflows. const auto advertisement = MakeGrowingDialAdvertisement(MAX_UDP_PAYLOAD_SIZE); - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(target, MakePacket(advertisement, IpAddress::SsdpGroupV4())); }); EXPECT_TRUE(source.sent.empty()); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; // Room for the growth: the same message is rewritten and forwarded. packet_dispatcher.Deliver(target, @@ -1284,13 +1277,12 @@ TEST_F(SsdpReflectorTest, DialForwardsLocationUnchangedWhenListenerMintFails) { source.iface.SetV4(std::nullopt); // no source_if V4 address -> EnsureDiscoveryListener cannot bind a listener const auto advertisement = MakeDialAdvertisement(); - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(target, MakePacket(advertisement, IpAddress::SsdpGroupV4())); }); ASSERT_EQ(source.sent.size(), 1u); EXPECT_EQ(source.sent.back().payload, advertisement); // forwarded unchanged (benign fallback) - EXPECT_NE(output.find("no listener"), std::string::npos) << output; // surfaced at INFO } // Same mint-failure fallback as DialForwardsLocationUnchangedWhenListenerMintFails, but on the unicast @@ -1319,13 +1311,12 @@ TEST_F(SsdpReflectorTest, DialForwardsResponseLocationUnchangedWhenListenerMintF }, .payload = response, }; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { packet_dispatcher.Deliver(target, reply); }); ASSERT_EQ(source.sent.size(), 1u); EXPECT_EQ(source.sent.back().payload, response); // forwarded unchanged (benign fallback) - EXPECT_NE(output.find("no listener"), std::string::npos) << output; // surfaced at INFO } TEST_F(SsdpReflectorTest, DoesNotReflectAnAdvertisementWhenSendFails) { diff --git a/tests/wol_reflector_test.cpp b/tests/wol_reflector_test.cpp index f8fa1ca..2f1c14e 100644 --- a/tests/wol_reflector_test.cpp +++ b/tests/wol_reflector_test.cpp @@ -210,13 +210,12 @@ TEST_F(WolReflectorTest, RejectsConfigWithEmptyPorts) { auto config = MakeConfig(IpAddress::Family::V4); config.ports = {}; - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const auto reflector = BuildV4Reflector(config); EXPECT_FALSE(reflector.IsValid()); EXPECT_EQ(DispatcherRegistrationCount(), 0); }); - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(WolReflectorTest, RegistersACallbackPerConfiguredPort) { @@ -242,13 +241,12 @@ TEST_F(WolReflectorTest, RegistrationFailureRollsBackAndInvalidates) { config.ports = {7, 9}; packet_dispatcher.fail_register_on_call = 2; // second port's registration fails - const std::string output = CaptureStdout([&] { + CaptureStdout([&] { const auto reflector = BuildV4Reflector(config); EXPECT_FALSE(reflector.IsValid()); }); EXPECT_EQ(DispatcherRegistrationCount(), 0); // the first port's registration was rolled back - EXPECT_NE(output.find("ERROR"), std::string::npos) << output; } TEST_F(WolReflectorTest, IgnoresPacketOnUnconfiguredPort) {