From: Piotrek Zadroga Date: Wed, 7 Jun 2023 15:38:24 +0000 (+0200) Subject: [#2865] Tweaking some pkt DROP prints X-Git-Tag: Kea-2.4.0~204 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=bff27696eca45d07668e5251840dcec1bae3be82;p=thirdparty%2Fkea.git [#2865] Tweaking some pkt DROP prints --- diff --git a/src/bin/dhcp4/client_handler.cc b/src/bin/dhcp4/client_handler.cc index 38384f3919..8fa4a55b2b 100644 --- a/src/bin/dhcp4/client_handler.cc +++ b/src/bin/dhcp4/client_handler.cc @@ -238,8 +238,10 @@ ClientHandler::tryLock(Pkt4Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0011) + .arg(next_query_id->getHWAddrLabel()) .arg(next_query_id->toText()) .arg(this_thread::get_id()) + .arg(holder_id->query_->getHWAddrLabel()) .arg(holder_id->query_->toText()) .arg(holder_id->thread_); stats::StatsMgr::instance().addValue("pkt4-receive-drop", @@ -249,8 +251,10 @@ ClientHandler::tryLock(Pkt4Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0011) + .arg(query->getHWAddrLabel()) .arg(query->toText()) .arg(this_thread::get_id()) + .arg(holder_id->query_->getHWAddrLabel()) .arg(holder_id->query_->toText()) .arg(holder_id->thread_); stats::StatsMgr::instance().addValue("pkt4-receive-drop", @@ -263,8 +267,10 @@ ClientHandler::tryLock(Pkt4Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0012) + .arg(next_query_hw->getHWAddrLabel()) .arg(next_query_hw->toText()) .arg(this_thread::get_id()) + .arg(holder_hw->query_->getHWAddrLabel()) .arg(holder_hw->query_->toText()) .arg(holder_hw->thread_); stats::StatsMgr::instance().addValue("pkt4-receive-drop", @@ -274,8 +280,10 @@ ClientHandler::tryLock(Pkt4Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0012) + .arg(query->getHWAddrLabel()) .arg(query->toText()) .arg(this_thread::get_id()) + .arg(holder_hw->query_->getHWAddrLabel()) .arg(holder_hw->query_->toText()) .arg(holder_hw->thread_); stats::StatsMgr::instance().addValue("pkt4-receive-drop", diff --git a/src/bin/dhcp4/dhcp4_messages.cc b/src/bin/dhcp4/dhcp4_messages.cc index 4b6d285b0a..8bb9b02a4d 100644 --- a/src/bin/dhcp4/dhcp4_messages.cc +++ b/src/bin/dhcp4/dhcp4_messages.cc @@ -275,7 +275,7 @@ const char* values[] = { "DHCP4_OPEN_SOCKETS_FAILED", "maximum number of open service sockets attempts: %1, has been exhausted without success", "DHCP4_OPEN_SOCKETS_NO_RECONNECT_CTL", "unexpected error in bind service sockets.", "DHCP4_OPEN_SOCKET_FAIL", "failed to open socket: %1", - "DHCP4_PACKET_DROP_0001", "failed to parse packet from %1 to %2, received over interface %3, reason: %4", + "DHCP4_PACKET_DROP_0001", "failed to parse packet from %1 to %2, received over interface %3, reason: %4, %5", "DHCP4_PACKET_DROP_0002", "%1, from interface %2: no suitable subnet configured for a direct client", "DHCP4_PACKET_DROP_0003", "%1, from interface %2: it contains a foreign server identifier", "DHCP4_PACKET_DROP_0004", "%1, from interface %2: missing msg-type option", @@ -284,11 +284,11 @@ const char* values[] = { "DHCP4_PACKET_DROP_0007", "%1: failed to process packet: %2", "DHCP4_PACKET_DROP_0008", "%1: DHCP service is globally disabled", "DHCP4_PACKET_DROP_0009", "%1: Option 53 missing (no DHCP message type), is this a BOOTP packet?", - "DHCP4_PACKET_DROP_0010", "dropped as member of the special class 'DROP': hwaddr=%1, %2", - "DHCP4_PACKET_DROP_0011", "dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4", - "DHCP4_PACKET_DROP_0012", "dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4", - "DHCP4_PACKET_DROP_0013", "dropped as member of the special class 'DROP' after host reservation lookup: hwaddr=%1, %2", - "DHCP4_PACKET_DROP_0014", "dropped as member of the special class 'DROP' after early global host reservations lookup: hwaddr=%1, %2", + "DHCP4_PACKET_DROP_0010", "dropped as member of the special class 'DROP': %1, %2", + "DHCP4_PACKET_DROP_0011", "dropped as sent by the same client than a packet being processed by another thread: dropped %1, %2 by thread %3 as duplicate of %4, %5 processed by %6", + "DHCP4_PACKET_DROP_0012", "dropped as sent by the same client than a packet being processed by another thread: dropped %1, %2 by thread %3 as duplicate of %4, %5 processed by %6", + "DHCP4_PACKET_DROP_0013", "dropped as member of the special class 'DROP' after host reservation lookup: %1, %2", + "DHCP4_PACKET_DROP_0014", "dropped as member of the special class 'DROP' after early global host reservations lookup: %1, %2", "DHCP4_PACKET_NAK_0001", "%1: failed to select a subnet for incoming packet, src %2, type %3", "DHCP4_PACKET_NAK_0002", "%1: invalid address %2 requested by INIT-REBOOT", "DHCP4_PACKET_NAK_0003", "%1: failed to advertise a lease, client sent ciaddr %2, requested-ip-address %3", diff --git a/src/bin/dhcp4/dhcp4_messages.mes b/src/bin/dhcp4/dhcp4_messages.mes index 88a4444065..5e37eb8a2a 100644 --- a/src/bin/dhcp4/dhcp4_messages.mes +++ b/src/bin/dhcp4/dhcp4_messages.mes @@ -580,7 +580,7 @@ are unavailable, and the server exits. This error should be reported. A warning message issued when IfaceMgr fails to open and bind a socket. The reason for the failure is appended as an argument of the log message. -% DHCP4_PACKET_DROP_0001 failed to parse packet from %1 to %2, received over interface %3, reason: %4 +% DHCP4_PACKET_DROP_0001 failed to parse packet from %1 to %2, received over interface %3, reason: %4, %5 The DHCPv4 server has received a packet that it is unable to interpret. The reason why the packet is invalid is included in the message. @@ -637,30 +637,30 @@ This debug message is issued when a packet is dropped because it did contain option 53 and thus has no DHCP message type. The most likely explanation is that it was BOOTP packet. -% DHCP4_PACKET_DROP_0010 dropped as member of the special class 'DROP': hwaddr=%1, %2 +% DHCP4_PACKET_DROP_0010 dropped as member of the special class 'DROP': %1, %2 This debug message is emitted when an incoming packet was classified into the special class 'DROP' and dropped. The packet details are displayed. -% DHCP4_PACKET_DROP_0011 dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4 +% DHCP4_PACKET_DROP_0011 dropped as sent by the same client than a packet being processed by another thread: dropped %1, %2 by thread %3 as duplicate of %4, %5 processed by %6 Currently multi-threading processing avoids races between packets sent by a client using the same client id option by dropping new packets until processing is finished. Packet details and thread identifiers are included for both packets in this warning message. -% DHCP4_PACKET_DROP_0012 dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4 +% DHCP4_PACKET_DROP_0012 dropped as sent by the same client than a packet being processed by another thread: dropped %1, %2 by thread %3 as duplicate of %4, %5 processed by %6 Currently multi-threading processing avoids races between packets sent by a client using the same hardware address by dropping new packets until processing is finished. Packet details and thread identifiers are included for both packets in this warning message. -% DHCP4_PACKET_DROP_0013 dropped as member of the special class 'DROP' after host reservation lookup: hwaddr=%1, %2 +% DHCP4_PACKET_DROP_0013 dropped as member of the special class 'DROP' after host reservation lookup: %1, %2 This debug message is emitted when an incoming packet was classified after host reservation lookup into the special class 'DROP' and dropped. The packet details are displayed. -% DHCP4_PACKET_DROP_0014 dropped as member of the special class 'DROP' after early global host reservations lookup: hwaddr=%1, %2 +% DHCP4_PACKET_DROP_0014 dropped as member of the special class 'DROP' after early global host reservations lookup: %1, %2 This debug message is emitted when an incoming packet was classified after early global host reservations lookup into the special class 'DROP' and dropped. The packet details are displayed. diff --git a/src/bin/dhcp4/dhcp4_srv.cc b/src/bin/dhcp4/dhcp4_srv.cc index ff3a937368..ec1f56f475 100644 --- a/src/bin/dhcp4/dhcp4_srv.cc +++ b/src/bin/dhcp4/dhcp4_srv.cc @@ -262,7 +262,7 @@ Dhcpv4Exchange::Dhcpv4Exchange(const AllocEnginePtr& alloc_engine, // Check the DROP special class. if (query_->inClass("DROP")) { LOG_DEBUG(packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0013) - .arg(query_->getHWAddr() ? query_->getHWAddr()->toText(false) : "(undefined)") + .arg(query_->getHWAddrLabel()) .arg(query_->toText()); isc::stats::StatsMgr::instance().addValue("pkt4-receive-drop", static_cast(1)); @@ -984,7 +984,7 @@ Dhcpv4Srv::earlyGHRLookup(const Pkt4Ptr& query, if (query->inClass("DROP")) { LOG_DEBUG(packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0014) - .arg(query->getHWAddr() ? query->getHWAddr()->toText(false) : "(undefined)") + .arg(query->getHWAddrLabel()) .arg(query->toText()); isc::stats::StatsMgr::instance().addValue("pkt4-receive-drop", static_cast(1)); @@ -1219,7 +1219,8 @@ Dhcpv4Srv::processPacket(Pkt4Ptr& query, Pkt4Ptr& rsp, bool allow_packet_park) { .arg(query->getRemoteAddr().toText()) .arg(query->getLocalAddr().toText()) .arg(query->getIface()) - .arg(e.what()); + .arg(e.what()) + .arg(query->getHWAddrLabel()); // Increase the statistics of parse failures and dropped packets. isc::stats::StatsMgr::instance().addValue("pkt4-parse-failed", @@ -1301,7 +1302,7 @@ Dhcpv4Srv::processPacket(Pkt4Ptr& query, Pkt4Ptr& rsp, bool allow_packet_park) { // Check the DROP special class. if (query->inClass("DROP")) { LOG_DEBUG(packet4_logger, DBGLVL_PKT_HANDLING, DHCP4_PACKET_DROP_0010) - .arg(query->getHWAddr() ? query->getHWAddr()->toText(false) : "(undefined)") + .arg(query->getHWAddrLabel()) .arg(query->toText()); isc::stats::StatsMgr::instance().addValue("pkt4-receive-drop", static_cast(1)); diff --git a/src/bin/dhcp6/client_handler.cc b/src/bin/dhcp6/client_handler.cc index c70643b6b4..8349047c0b 100644 --- a/src/bin/dhcp6/client_handler.cc +++ b/src/bin/dhcp6/client_handler.cc @@ -128,8 +128,10 @@ ClientHandler::tryLock(Pkt6Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet6_logger, DBGLVL_PKT_HANDLING, DHCP6_PACKET_DROP_DUPLICATE) + .arg(next_query->makeLabel(next_query->getClientId(), nullptr)) .arg(next_query->toText()) .arg(this_thread::get_id()) + .arg(holder->query_->makeLabel(holder->query_->getClientId(), nullptr)) .arg(holder->query_->toText()) .arg(holder->thread_); stats::StatsMgr::instance().addValue("pkt6-receive-drop", @@ -139,8 +141,10 @@ ClientHandler::tryLock(Pkt6Ptr query, ContinuationPtr cont) { // Logging a warning as it is supposed to be a rare event // with well behaving clients... LOG_DEBUG(bad_packet6_logger, DBGLVL_PKT_HANDLING, DHCP6_PACKET_DROP_DUPLICATE) + .arg(query->makeLabel(query->getClientId(), nullptr)) .arg(query->toText()) .arg(this_thread::get_id()) + .arg(holder->query_->makeLabel(holder->query_->getClientId(), nullptr)) .arg(holder->query_->toText()) .arg(holder->thread_); stats::StatsMgr::instance().addValue("pkt6-receive-drop", diff --git a/src/bin/dhcp6/dhcp6_messages.cc b/src/bin/dhcp6/dhcp6_messages.cc index 2445b44c7d..613d343d93 100644 --- a/src/bin/dhcp6/dhcp6_messages.cc +++ b/src/bin/dhcp6/dhcp6_messages.cc @@ -272,8 +272,8 @@ const char* values[] = { "DHCP6_PACKET_DROP_DROP_CLASS", "dropped as member of the special class 'DROP': %1 %2", "DHCP6_PACKET_DROP_DROP_CLASS2", "dropped as member of the special class 'DROP' after host reservation lookup: %1 %2", "DHCP6_PACKET_DROP_DROP_CLASS_EARLY", "dropped as member of the special class 'DROP' after early global host reservations lookup: %1 %2", - "DHCP6_PACKET_DROP_DUPLICATE", "dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4", - "DHCP6_PACKET_DROP_PARSE_FAIL", "failed to parse packet from %1 to %2, received over interface %3, reason: %4", + "DHCP6_PACKET_DROP_DUPLICATE", "dropped as sent by the same client than a packet being processed by another thread: dropped %1 %2 by thread %3 as duplicate of %4 %5 processed by %6", + "DHCP6_PACKET_DROP_PARSE_FAIL", "failed to parse packet from %1 to %2, received over interface %3, reason: %4, %5", "DHCP6_PACKET_DROP_SERVERID_MISMATCH", "%1: dropping packet with server identifier: %2, server is using: %3", "DHCP6_PACKET_DROP_UNICAST", "%1: dropping unicast %2 packet as this packet should be sent to multicast", "DHCP6_PACKET_OPTIONS_SKIPPED", "An error unpacking an option, caused subsequent options to be skipped: %1", diff --git a/src/bin/dhcp6/dhcp6_messages.mes b/src/bin/dhcp6/dhcp6_messages.mes index ace9aeecc4..042be281b7 100644 --- a/src/bin/dhcp6/dhcp6_messages.mes +++ b/src/bin/dhcp6/dhcp6_messages.mes @@ -593,13 +593,13 @@ This debug message is emitted when an incoming packet was classified after early global host reservations lookup into the special class 'DROP' and dropped. The packet details are displayed. -% DHCP6_PACKET_DROP_DUPLICATE dropped as sent by the same client than a packet being processed by another thread: dropped %1 by thread %2 as duplicate of %3 processed by %4 +% DHCP6_PACKET_DROP_DUPLICATE dropped as sent by the same client than a packet being processed by another thread: dropped %1 %2 by thread %3 as duplicate of %4 %5 processed by %6 Currently multi-threading processing avoids races between packets sent by the same client by dropping new packets until processing is finished. Packet details and thread identifiers are included for both packets in this warning message. -% DHCP6_PACKET_DROP_PARSE_FAIL failed to parse packet from %1 to %2, received over interface %3, reason: %4 +% DHCP6_PACKET_DROP_PARSE_FAIL failed to parse packet from %1 to %2, received over interface %3, reason: %4, %5 The DHCPv6 server has received a packet that it is unable to interpret. The reason why the packet is invalid is included in the message. diff --git a/src/bin/dhcp6/dhcp6_srv.cc b/src/bin/dhcp6/dhcp6_srv.cc index 8eaa5c9e92..d334b12aa0 100644 --- a/src/bin/dhcp6/dhcp6_srv.cc +++ b/src/bin/dhcp6/dhcp6_srv.cc @@ -806,7 +806,8 @@ Dhcpv6Srv::processPacket(Pkt6Ptr& query, Pkt6Ptr& rsp) { .arg(query->getRemoteAddr().toText()) .arg(query->getLocalAddr().toText()) .arg(query->getIface()) - .arg(e.what()); + .arg(e.what()) + .arg(query->makeLabel(query->getClientId(), nullptr)); // Increase the statistics of parse failures and dropped packets. StatsMgr::instance().addValue("pkt6-parse-failed", diff --git a/src/lib/dhcp/pkt4.cc b/src/lib/dhcp/pkt4.cc index f6947da40d..00bd99ad79 100644 --- a/src/lib/dhcp/pkt4.cc +++ b/src/lib/dhcp/pkt4.cc @@ -602,5 +602,13 @@ Pkt4::isRelayed() const { return (!giaddr_.isV4Zero() && !giaddr_.isV4Bcast()); } +std::string +Pkt4::getHWAddrLabel() const { + std::ostringstream label; + label << "hwaddr="; + hwaddr_ ? label << hwaddr_->toText(false) : label << "(undefined)"; + return (label.str()); +} + } // end of namespace isc::dhcp } // end of namespace isc diff --git a/src/lib/dhcp/pkt4.h b/src/lib/dhcp/pkt4.h index dd36168033..83282155ad 100644 --- a/src/lib/dhcp/pkt4.h +++ b/src/lib/dhcp/pkt4.h @@ -323,6 +323,14 @@ public: /// @return hardware address structure HWAddrPtr getHWAddr() const { return (hwaddr_); } + /// @brief Returns text representation of the hardware address + /// + /// Returns text representation of the hardware address (e.g. hwaddr=00:01:02:03:04:05). + /// If there is no defined hardware address, it returns @c hwaddr=(undefined). + /// + /// @return string with text representation + std::string getHWAddrLabel() const; + /// @brief Add an option. /// /// @note: to avoid throwing when adding multiple options diff --git a/src/lib/dhcp/tests/pkt4_unittest.cc b/src/lib/dhcp/tests/pkt4_unittest.cc index 7df927c641..70bc624d6b 100644 --- a/src/lib/dhcp/tests/pkt4_unittest.cc +++ b/src/lib/dhcp/tests/pkt4_unittest.cc @@ -1506,4 +1506,24 @@ TEST_F(Pkt4Test, testSkipThisOptionError) { EXPECT_EQ("def", opstr->getValue()); } +// Tests that getHWAddrLabel method produces the expected strings based on +// packet content. +TEST_F(Pkt4Test, getHWAddrLabel) { + Pkt4 pkt(DHCPOFFER, 1234); + + // Verify getHWAddrLabel() handles empty values + EXPECT_EQ ("hwaddr=", pkt.getHWAddrLabel()); + + // Testing undefined hwaddr case is not possible + EXPECT_THROW(pkt.setHWAddr(nullptr), BadValue); + + // Set that packet hardware address, then verify getLabel + const uint8_t hw[] = { 2, 4, 6, 8, 10, 12 }; // MAC + const uint8_t hw_type = 123; // hardware type + HWAddrPtr dummy_hwaddr(new HWAddr(hw, sizeof(hw), hw_type)); + pkt.setHWAddr(dummy_hwaddr); + + EXPECT_EQ ("hwaddr=02:04:06:08:0a:0c", pkt.getHWAddrLabel()); +} + } // end of anonymous namespace