From: Razvan Becheriu Date: Tue, 31 Oct 2023 13:21:57 +0000 (+0200) Subject: [#3109] consistent pkt info logging in v4 and v6 X-Git-Tag: Kea-2.5.4~3 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=f65c0fb9f6332add36f60796feecb2a702aa885f;p=thirdparty%2Fkea.git [#3109] consistent pkt info logging in v4 and v6 --- diff --git a/src/bin/dhcp6/dhcp6_messages.cc b/src/bin/dhcp6/dhcp6_messages.cc index 091a822628..ac59966033 100644 --- a/src/bin/dhcp6/dhcp6_messages.cc +++ b/src/bin/dhcp6/dhcp6_messages.cc @@ -61,6 +61,7 @@ extern const isc::log::MessageID DHCP6_DEVELOPMENT_VERSION = "DHCP6_DEVELOPMENT_ extern const isc::log::MessageID DHCP6_DHCP4O6_PACKET_RECEIVED = "DHCP6_DHCP4O6_PACKET_RECEIVED"; extern const isc::log::MessageID DHCP6_DHCP4O6_RECEIVE_FAIL = "DHCP6_DHCP4O6_RECEIVE_FAIL"; extern const isc::log::MessageID DHCP6_DHCP4O6_RECEIVING = "DHCP6_DHCP4O6_RECEIVING"; +extern const isc::log::MessageID DHCP6_DHCP4O6_RESPONSE_DATA = "DHCP6_DHCP4O6_RESPONSE_DATA"; extern const isc::log::MessageID DHCP6_DHCP4O6_SEND_FAIL = "DHCP6_DHCP4O6_SEND_FAIL"; extern const isc::log::MessageID DHCP6_DYNAMIC_RECONFIGURATION = "DHCP6_DYNAMIC_RECONFIGURATION"; extern const isc::log::MessageID DHCP6_DYNAMIC_RECONFIGURATION_FAIL = "DHCP6_DYNAMIC_RECONFIGURATION_FAIL"; @@ -234,6 +235,7 @@ const char* values[] = { "DHCP6_DHCP4O6_PACKET_RECEIVED", "received DHCPv4o6 packet from DHCPv4 server (type %1) for %2 port %3 on interface %4", "DHCP6_DHCP4O6_RECEIVE_FAIL", "failed to receive DHCPv4o6: %1", "DHCP6_DHCP4O6_RECEIVING", "receiving DHCPv4o6 packet from DHCPv4 server", + "DHCP6_DHCP4O6_RESPONSE_DATA", "%1: responding with packet %2 (type %3), packet details: %4", "DHCP6_DHCP4O6_SEND_FAIL", "failed to send DHCPv4o6 packet: %1", "DHCP6_DYNAMIC_RECONFIGURATION", "initiate server reconfiguration using file: %1, after receiving SIGHUP signal or config-reload command", "DHCP6_DYNAMIC_RECONFIGURATION_FAIL", "dynamic server reconfiguration failed with file: %1", @@ -328,7 +330,7 @@ const char* values[] = { "DHCP6_RELEASE_PD_FAIL_WRONG_IAID", "%1: client tried to release prefix %2/%3, but it used wrong IAID (expected %4, but got %5)", "DHCP6_REQUIRED_OPTIONS_CHECK_FAIL", "%1 message received from %2 failed the following check: %3", "DHCP6_RESERVATIONS_LOOKUP_FIRST_ENABLED", "Multi-threading is enabled and host reservations lookup is always performed first.", - "DHCP6_RESPONSE_DATA", "responding with packet type %1 data is %2", + "DHCP6_RESPONSE_DATA", "%1: responding with packet %2 (type %3), packet details: %4", "DHCP6_SERVER_FAILED", "server failed: %1", "DHCP6_SHUTDOWN", "server shutdown", "DHCP6_SHUTDOWN_REQUEST", "shutdown of server requested", diff --git a/src/bin/dhcp6/dhcp6_messages.h b/src/bin/dhcp6/dhcp6_messages.h index 88e86e7c9a..d087bb317a 100644 --- a/src/bin/dhcp6/dhcp6_messages.h +++ b/src/bin/dhcp6/dhcp6_messages.h @@ -62,6 +62,7 @@ extern const isc::log::MessageID DHCP6_DEVELOPMENT_VERSION; extern const isc::log::MessageID DHCP6_DHCP4O6_PACKET_RECEIVED; extern const isc::log::MessageID DHCP6_DHCP4O6_RECEIVE_FAIL; extern const isc::log::MessageID DHCP6_DHCP4O6_RECEIVING; +extern const isc::log::MessageID DHCP6_DHCP4O6_RESPONSE_DATA; extern const isc::log::MessageID DHCP6_DHCP4O6_SEND_FAIL; extern const isc::log::MessageID DHCP6_DYNAMIC_RECONFIGURATION; extern const isc::log::MessageID DHCP6_DYNAMIC_RECONFIGURATION_FAIL; diff --git a/src/bin/dhcp6/dhcp6_messages.mes b/src/bin/dhcp6/dhcp6_messages.mes index 4ddbd27da5..fa5df89661 100644 --- a/src/bin/dhcp6/dhcp6_messages.mes +++ b/src/bin/dhcp6/dhcp6_messages.mes @@ -936,8 +936,19 @@ etc. The exact reason for rejecting the packet is included in the message. This is a message informing that host reservations lookup is performed before lease lookup when multi-threading is enabled overwriting configured value. -% DHCP6_RESPONSE_DATA responding with packet type %1 data is %2 -A debug message listing the data returned to the client. +% DHCP6_RESPONSE_DATA %1: responding with packet %2 (type %3), packet details: %4 +A debug message including the detailed data about the packet being sent +to the client. The first argument contains the client and the transaction +identification information. The second and third argument contains the +packet name and type respectively. The fourth argument contains detailed +packet information. + +% DHCP6_DHCP4O6_RESPONSE_DATA %1: responding with packet %2 (type %3), packet details: %4 +A debug message including the detailed data about the packet being sent +to the client. The first argument contains the client and the transaction +identification information. The second and third argument contains the +packet name and type respectively. The fourth argument contains detailed +packet information. % DHCP6_SERVER_FAILED server failed: %1 The IPv6 DHCP server has encountered a fatal error and is terminating. diff --git a/src/bin/dhcp6/dhcp6_srv.cc b/src/bin/dhcp6/dhcp6_srv.cc index 8bf504541a..7be8d06ca3 100644 --- a/src/bin/dhcp6/dhcp6_srv.cc +++ b/src/bin/dhcp6/dhcp6_srv.cc @@ -1355,8 +1355,10 @@ Dhcpv6Srv::processPacketBufferSend(CalloutHandlePtr& callout_handle, .arg(rsp->getIface()); LOG_DEBUG(packet6_logger, DBG_DHCP6_DETAIL_DATA, DHCP6_RESPONSE_DATA) - .arg(static_cast(rsp->getType())).arg(rsp->toText()); - + .arg(rsp->getLabel()) + .arg(rsp->getName()) + .arg(static_cast(rsp->getType())) + .arg(rsp->toText()); sendPacket(rsp); // Update statistics accordingly for sent packet. diff --git a/src/bin/dhcp6/dhcp6to4_ipc.cc b/src/bin/dhcp6/dhcp6to4_ipc.cc index 0bb73f27cb..504f63f693 100644 --- a/src/bin/dhcp6/dhcp6to4_ipc.cc +++ b/src/bin/dhcp6/dhcp6to4_ipc.cc @@ -145,8 +145,11 @@ void Dhcp6to4Ipc::handler(int /* fd */) { callout_handle->getArgument("response6", pkt); } - LOG_DEBUG(packet6_logger, DBG_DHCP6_DETAIL_DATA, DHCP6_RESPONSE_DATA) - .arg(static_cast(pkt->getType())).arg(pkt->toText()); + LOG_DEBUG(packet6_logger, DBG_DHCP6_DETAIL_DATA, DHCP6_DHCP4O6_RESPONSE_DATA) + .arg(pkt->getLabel()) + .arg(pkt->getName()) + .arg(static_cast(pkt->getType())) + .arg(pkt->toText()); // Forward packet to the client. IfaceMgr::instance().send(pkt); diff --git a/src/lib/dhcp/pkt4.cc b/src/lib/dhcp/pkt4.cc index 595adfb6e8..bb5276639c 100644 --- a/src/lib/dhcp/pkt4.cc +++ b/src/lib/dhcp/pkt4.cc @@ -98,7 +98,6 @@ Pkt4::pack() { buffer_out_.writeUint32(siaddr_.toUint32()); buffer_out_.writeUint32(giaddr_.toUint32()); - if ((hw_len > 0) && (hw_len <= MAX_CHADDR_LEN)) { // write up to 16 bytes of the hardware address (CHADDR field is 16 // bytes long in DHCPv4 message). @@ -398,6 +397,7 @@ Pkt4::getLabel() const { } label << suffix; + return (label.str()); } @@ -411,7 +411,7 @@ Pkt4::makeLabel(const HWAddrPtr& hwaddr, const ClientIdPtr& client_id, // Append transaction id. label << ", tid=0x" << hex << transid << dec; - return label.str(); + return (label.str()); } std::string @@ -421,42 +421,45 @@ Pkt4::makeLabel(const HWAddrPtr& hwaddr, const ClientIdPtr& client_id) { << "], cid=[" << (client_id ? client_id->toText() : "no info") << "]"; - return label.str(); + return (label.str()); } std::string Pkt4::toText() const { - stringstream output; - output << "local_address=" << local_addr_ << ":" << local_port_ - << ", remote_address=" << remote_addr_ - << ":" << remote_port_ << ", msg_type="; + stringstream tmp; + + // First print the basics + tmp << "local_address=" << local_addr_ << ":" << local_port_ + << ", remote_address=" << remote_addr_ << ":" << remote_port_ << "," << endl; + + tmp << "msg_type="; // Try to obtain message type. uint8_t msg_type = getType(); if (msg_type != DHCP_NOTYPE) { - output << getName(msg_type) << " (" << static_cast(msg_type) << ")"; + tmp << getName(msg_type) << " (" << static_cast(msg_type) << ")"; } else { // Message Type option is missing. - output << "(missing)"; + tmp << "(missing)"; } - output << ", transid=0x" << hex << transid_ << dec; + tmp << ", trans_id=0x" << hex << transid_ << dec; if (!options_.empty()) { - output << "," << std::endl << "options:"; + tmp << "," << endl << "options:"; for (const auto& opt : options_) { try { - output << std::endl << opt.second->toText(2); + tmp << endl << opt.second->toText(2); } catch (...) { - output << "(unknown)" << std::endl; + tmp << "(unknown)" << endl; } } } else { - output << ", message contains no options"; + tmp << "," << endl << "message contains no options"; } - return (output.str()); + return (tmp.str()); } void diff --git a/src/lib/dhcp/pkt6.cc b/src/lib/dhcp/pkt6.cc index b02bf39e11..b32d47c1a7 100644 --- a/src/lib/dhcp/pkt6.cc +++ b/src/lib/dhcp/pkt6.cc @@ -375,7 +375,6 @@ uint16_t Pkt6::directLen() const { return (length); } - void Pkt6::pack() { switch (proto_) { @@ -709,15 +708,11 @@ Pkt6::makeLabel(const DuidPtr duid, const HWAddrPtr& hwaddr) { std::stringstream label; // DUID should be present at all times, so explicitly inform when // it is no present (no info). - label << "duid=[" << (duid ? duid->toText() : "no info") - << "]"; - // HW address is typically not carried in the DHCPv6 messages // and can be extracted using various, but not fully reliable, - // techniques. If it is not present, don't print anything. - if (hwaddr) { - label << ", [" << hwaddr->toText() << "]"; - } + // techniques. + label << "duid=[" << (duid ? duid->toText() : "no info") + << "], [" << (hwaddr ? hwaddr->toText() : "no hwaddr info") << "]"; return (label.str()); } @@ -735,28 +730,38 @@ Pkt6::toText() const { stringstream tmp; // First print the basics - tmp << "localAddr=[" << local_addr_ << "]:" << local_port_ - << " remoteAddr=[" << remote_addr_ << "]:" << remote_port_ << endl; - tmp << "msgtype=" << static_cast(msg_type_) << "(" << getName(msg_type_) - << "), transid=0x" << - hex << transid_ << dec << endl; - - // Then print the options - for (const auto& opt : options_) { - tmp << opt.second->toText() << std::endl; + tmp << "local_address=[" << local_addr_ << "]:" << local_port_ + << ", remote_address=[" << remote_addr_ << "]:" << remote_port_ << "," << endl; + + tmp << "msg_type=" << getName(msg_type_) << " (" << static_cast(msg_type_) << ")"; + tmp << ", trans_id=0x" << hex << transid_ << dec; + + if (!options_.empty()) { + tmp << "," << endl << "options:"; + for (const auto& opt : options_) { + try { + tmp << endl << opt.second->toText(2); + } catch (...) { + tmp << "(unknown)" << endl; + } + } + + } else { + tmp << "," << endl << "message contains no options"; } // Finally, print the relay information (if present) if (!relay_info_.empty()) { - tmp << relay_info_.size() << " relay(s):" << endl; + tmp << endl << relay_info_.size() << " relay(s):" << endl; int cnt = 0; for (const auto& relay : relay_info_) { tmp << "relay[" << cnt++ << "]: " << relay.toText(); } } else { - tmp << "No relays traversed." << endl; + tmp << endl << "No relays traversed." << endl; } - return tmp.str(); + + return (tmp.str()); } DuidPtr diff --git a/src/lib/dhcp/tests/pkt4_unittest.cc b/src/lib/dhcp/tests/pkt4_unittest.cc index bed3f860e5..8232b8f387 100644 --- a/src/lib/dhcp/tests/pkt4_unittest.cc +++ b/src/lib/dhcp/tests/pkt4_unittest.cc @@ -1289,8 +1289,8 @@ TEST_F(Pkt4Test, toText) { pkt.addOption(OptionPtr(new OptionUint32(Option::V4, 156, 123456))); pkt.addOption(OptionPtr(new OptionString(Option::V4, 87, "lorem ipsum"))); - EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68, " - "msg_type=DHCPDISCOVER (1), transid=0x9ef,\n" + EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68,\n" + "msg_type=DHCPDISCOVER (1), trans_id=0x9ef,\n" "options:\n" " type=053, len=001: 1 (uint8)\n" " type=087, len=011: \"lorem ipsum\" (string)\n" @@ -1305,8 +1305,8 @@ TEST_F(Pkt4Test, toText) { pkt.delOption(87); pkt.delOption(53); - EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68, " - "msg_type=(missing), transid=0x9ef, " + EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68,\n" + "msg_type=(missing), trans_id=0x9ef,\n" "message contains no options", pkt.toText()); diff --git a/src/lib/dhcp/tests/pkt6_unittest.cc b/src/lib/dhcp/tests/pkt6_unittest.cc index 2478040e5e..953a67a0bb 100644 --- a/src/lib/dhcp/tests/pkt6_unittest.cc +++ b/src/lib/dhcp/tests/pkt6_unittest.cc @@ -1287,12 +1287,13 @@ TEST_F(Pkt6Test, toText) { ASSERT_EQ(2, msg->relay_info_.size()); string expected = - "localAddr=[ff05::1:3]:547 remoteAddr=[fe80::1234]:547\n" - "msgtype=1(SOLICIT), transid=0x6b4fe2\n" - "type=00001, len=00014: 00:01:00:01:18:b0:33:41:00:00:21:5c:18:a9\n" - "type=00003(IA_NA), len=00012: iaid=1, t1=4294967295, t2=4294967295\n" - "type=00006, len=00006: 23(uint16) 242(uint16) 243(uint16)\n" - "type=00008, len=00002: 0 (uint16)\n" + "local_address=[ff05::1:3]:547, remote_address=[fe80::1234]:547,\n" + "msg_type=SOLICIT (1), trans_id=0x6b4fe2,\n" + "options:\n" + " type=00001, len=00014: 00:01:00:01:18:b0:33:41:00:00:21:5c:18:a9\n" + " type=00003(IA_NA), len=00012: iaid=1, t1=4294967295, t2=4294967295\n" + " type=00006, len=00006: 23(uint16) 242(uint16) 243(uint16)\n" + " type=00008, len=00002: 0 (uint16)\n" "2 relay(s):\n" "relay[0]: msg-type=12(RELAY_FORWARD), hop-count=1,\n" "link-address=2001:888:db8:1::, peer-address=fe80::200:21ff:fe5c:18a9, 2 option(s)\n" @@ -1963,7 +1964,7 @@ TEST_F(Pkt6Test, makeLabel) { HTYPE_ETHER))); // Specify DUID and no HW Address. - EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03], tid=0x123", + EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03], [no hwaddr info], tid=0x123", Pkt6::makeLabel(duid, 0x123, HWAddrPtr())); // Specify HW Address and no DUID. @@ -1976,7 +1977,7 @@ TEST_F(Pkt6Test, makeLabel) { Pkt6::makeLabel(duid, 0x123, hwaddr)); // Specify neither DUID nor HW Address. - EXPECT_EQ("duid=[no info], tid=0x0", + EXPECT_EQ("duid=[no info], [no hwaddr info], tid=0x0", Pkt6::makeLabel(DuidPtr(), 0x0, HWAddrPtr())); } @@ -1988,7 +1989,7 @@ TEST_F(Pkt6Test, makeLabelWithoutTransactionId) { HTYPE_ETHER))); // Specify DUID and no HW Address. - EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03]", + EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03], [no hwaddr info]", Pkt6::makeLabel(duid, HWAddrPtr())); // Specify HW Address and no DUID. @@ -2001,7 +2002,7 @@ TEST_F(Pkt6Test, makeLabelWithoutTransactionId) { Pkt6::makeLabel(duid, hwaddr)); // Specify neither DUID nor HW Address. - EXPECT_EQ("duid=[no info]", Pkt6::makeLabel(DuidPtr(), HWAddrPtr())); + EXPECT_EQ("duid=[no info], [no hwaddr info]", Pkt6::makeLabel(DuidPtr(), HWAddrPtr())); } // This test verifies that it is possible to obtain the packet @@ -2009,7 +2010,7 @@ TEST_F(Pkt6Test, makeLabelWithoutTransactionId) { TEST_F(Pkt6Test, getLabel) { // Create a packet. Pkt6Ptr pkt(new Pkt6(DHCPV6_SOLICIT, 0x2312)); - EXPECT_EQ("duid=[no info], tid=0x2312", + EXPECT_EQ("duid=[no info], [no hwaddr info], tid=0x2312", pkt->getLabel()); DuidPtr duid(new DUID(DUID::fromText("0102020202030303030303"))); @@ -2022,7 +2023,7 @@ TEST_F(Pkt6Test, getLabel) { Pkt6Ptr pkt_clone = packAndClone(pkt); ASSERT_NO_THROW(pkt_clone->unpack()); - EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03], tid=0x2312", + EXPECT_EQ("duid=[01:02:02:02:02:03:03:03:03:03:03], [no hwaddr info], tid=0x2312", pkt_clone->getLabel()); } @@ -2035,7 +2036,7 @@ TEST_F(Pkt6Test, getLabelEmptyClientId) { // Add empty client identifier option. pkt.addOption(OptionPtr(new Option(Option::V6, D6O_CLIENTID))); - EXPECT_EQ("duid=[no info], tid=0x2312", pkt.getLabel()); + EXPECT_EQ("duid=[no info], [no hwaddr info], tid=0x2312", pkt.getLabel()); } // Verifies that when the VIVSO, 17, has length that is too