[#3109] consistent pkt info logging in v4 and v6

isc-projects · Nov 27, 2023 · f65c0fb · f65c0fb
1 parent 37d9d81
commit f65c0fb
Show file tree

Hide file tree

Showing 9 changed files with 87 additions and 59 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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<int>(rsp->getType())).arg(rsp->toText());
-
+            .arg(rsp->getLabel())
+            .arg(rsp->getName())
+            .arg(static_cast<int>(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
@@ -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<int>(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<int>(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
@@ -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<int>(msg_type) << ")";
+        tmp << getName(msg_type) << " (" << static_cast<int>(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
@@ -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<int>(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<int>(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
@@ -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
@@ -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,15 +2002,15 @@ 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
 // identifiers in the textual format from the packet instance.
 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