diff --git a/changelog_unreleased/3531-how-can-i-log-the-pxe-boot-details-sent-to-my-clients b/changelog_unreleased/3531-how-can-i-log-the-pxe-boot-details-sent-to-my-clients new file mode 100644 index 0000000000..48e7fb79ce --- /dev/null +++ b/changelog_unreleased/3531-how-can-i-log-the-pxe-boot-details-sent-to-my-clients @@ -0,0 +1,5 @@ +[func] tmark + Additional packet details are now emitted in + debug level logs by kea-dhcp4 for both inbound + and outbound packets. + (Gitlab #3531) diff --git a/src/bin/dhcp4/dhcp4_messages.mes b/src/bin/dhcp4/dhcp4_messages.mes index a7b8c02d31..de0b4308e1 100644 --- a/src/bin/dhcp4/dhcp4_messages.mes +++ b/src/bin/dhcp4/dhcp4_messages.mes @@ -906,7 +906,8 @@ initially selected for allocation) from the same shared network. Logged at debug log level 55. A debug message printing the details of the received packet. The first argument includes the client and the transaction identification -information. +information. Packet fields ciaddr, yiaddr, siaddr, giaddr, sname, and file +will be included not empty. % DHCP4_QUERY_LABEL received query: %1 This information message indicates that a query was received. It displays @@ -1013,7 +1014,8 @@ 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. +packet information. Packet fields ciaddr, yiaddr, siaddr, giaddr, sname, +and file will be included not empty. % DHCP4_RESPONSE_FQDN_DATA %1: including FQDN option in the server's response: %2 Logged at debug log level 55. diff --git a/src/bin/dhcp4/dhcp4_srv.cc b/src/bin/dhcp4/dhcp4_srv.cc index 774cb9044e..39fdb96358 100644 --- a/src/bin/dhcp4/dhcp4_srv.cc +++ b/src/bin/dhcp4/dhcp4_srv.cc @@ -1463,7 +1463,7 @@ Dhcpv4Srv::processPacket(Pkt4Ptr query, bool allow_answer_park) { .arg(query->getIface()); LOG_DEBUG(packet4_logger, DBG_DHCP4_DETAIL_DATA, DHCP4_QUERY_DATA) .arg(query->getLabel()) - .arg(query->toText()); + .arg(query->toText(true)); // Let's execute all callouts registered for pkt4_receive if (HooksManager::calloutsPresent(Hooks.hook_index_pkt4_receive_)) { @@ -2018,7 +2018,7 @@ Dhcpv4Srv::processPacketBufferSend(CalloutHandlePtr& callout_handle, .arg(rsp->getLabel()) .arg(rsp->getName()) .arg(static_cast(rsp->getType())) - .arg(rsp->toText()); + .arg(rsp->toText(true)); sendPacket(rsp); // Update statistics accordingly for sent packet. diff --git a/src/lib/dhcp/pkt.h b/src/lib/dhcp/pkt.h index 2c698763cd..d35666a0f6 100644 --- a/src/lib/dhcp/pkt.h +++ b/src/lib/dhcp/pkt.h @@ -283,9 +283,10 @@ public: /// @note This is a pure virtual method and must be implemented in /// the derived classes. The @c Pkt4 and @c Pkt6 class have respective /// implementations of this method. + /// @param verbose output most if not all members. /// /// @return string with text representation - virtual std::string toText() const = 0; + virtual std::string toText(bool verbose = false) const = 0; /// @brief Returns packet size in binary format. /// diff --git a/src/lib/dhcp/pkt4.cc b/src/lib/dhcp/pkt4.cc index 88bbbce5d2..131ad8c5a6 100644 --- a/src/lib/dhcp/pkt4.cc +++ b/src/lib/dhcp/pkt4.cc @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -19,6 +20,7 @@ using namespace std; using namespace isc::dhcp; using namespace isc::asiolink; +using namespace isc::util::str; namespace { @@ -417,7 +419,7 @@ Pkt4::makeLabel(const HWAddrPtr& hwaddr, const ClientIdPtr& client_id) { } std::string -Pkt4::toText() const { +Pkt4::toText(bool verbose /* = false */) const { stringstream tmp; // First print the basics @@ -437,6 +439,36 @@ Pkt4::toText() const { tmp << ", trans_id=0x" << hex << transid_ << dec; + if (verbose) { + tmp << ", secs=" << secs_; + tmp << ", flags=0x" << hex << flags_; + if (!ciaddr_.isV4Zero()) { + tmp << ", ciaddr=" << ciaddr_.toText(); + } + + if (!yiaddr_.isV4Zero()) { + tmp << ", yiaddr=" << yiaddr_.toText(); + } + + if (!siaddr_.isV4Zero()) { + tmp << ", siaddr=" << siaddr_.toText(); + } + + if (!giaddr_.isV4Zero()) { + tmp << ", giaddr=" << giaddr_.toText(); + } + + auto sname_dump = printOrDump(getSname(), 32); + if (!sname_dump.empty()) { + tmp << ", sname=[" << sname_dump << "]"; + } + + auto file_dump = printOrDump(getFile(), 32); + if (!file_dump.empty()) { + tmp << ", file=[" << file_dump << "]"; + } + } + if (!options_.empty()) { tmp << "," << endl << "options:"; for (auto const& opt : options_) { diff --git a/src/lib/dhcp/pkt4.h b/src/lib/dhcp/pkt4.h index 7ede3889ba..0b555706e1 100644 --- a/src/lib/dhcp/pkt4.h +++ b/src/lib/dhcp/pkt4.h @@ -125,9 +125,10 @@ public: /// @brief Returns text representation of the packet. /// /// This function is useful mainly for debugging. - /// + /// @param verbose output includes secs, flags and if they are populated: + /// ciaddr, yiaddr, siaddr, giaddr, sname, and file /// @return string with text representation - std::string toText() const; + std::string toText(bool verbose = false) const; /// @brief Returns the size of the required buffer to build the packet. /// diff --git a/src/lib/dhcp/pkt6.cc b/src/lib/dhcp/pkt6.cc index 286a27405d..999c4a5304 100644 --- a/src/lib/dhcp/pkt6.cc +++ b/src/lib/dhcp/pkt6.cc @@ -725,7 +725,7 @@ Pkt6::getLabel() const { return (makeLabel(getClientId(), getTransid(), HWAddrPtr()));} std::string -Pkt6::toText() const { +Pkt6::toText(bool /* verbose = false */) const { stringstream tmp; // First print the basics diff --git a/src/lib/dhcp/pkt6.h b/src/lib/dhcp/pkt6.h index a29ab2a63c..95c15c7d6c 100644 --- a/src/lib/dhcp/pkt6.h +++ b/src/lib/dhcp/pkt6.h @@ -199,8 +199,11 @@ public: /// /// This function is useful mainly for debugging. /// + /// @param verbose output most if not all members. Not currently + /// used for v6. + /// /// @return string with text representation - virtual std::string toText() const; + virtual std::string toText(bool verbose = false) const; /// @brief Returns length of the packet. /// diff --git a/src/lib/dhcp/tests/pkt4_unittest.cc b/src/lib/dhcp/tests/pkt4_unittest.cc index 80920291b2..84f1e81160 100644 --- a/src/lib/dhcp/tests/pkt4_unittest.cc +++ b/src/lib/dhcp/tests/pkt4_unittest.cc @@ -19,6 +19,7 @@ #include #include #include +#include #include #include @@ -1336,6 +1337,83 @@ TEST_F(Pkt4Test, toText) { } +// This test checks that the packet data are correctly converted to the +// textual format. +TEST_F(Pkt4Test, toTextVerbose) { + Pkt4 pkt(DHCPDISCOVER, 2543); + pkt.setLocalAddr(IOAddress("192.0.2.34")); + pkt.setRemoteAddr(IOAddress("192.10.33.4")); + + pkt.addOption(OptionPtr(new Option4AddrLst(123, IOAddress("192.0.2.3")))); + pkt.addOption(OptionPtr(new OptionUint32(Option::V4, 156, 123456))); + pkt.addOption(OptionPtr(new OptionString(Option::V4, 87, "lorem ipsum"))); + OptionBuffer data = { 0x61, 0x62, 0x63, 0x64, 0x65, 0x66 }; + OptionPtr opt(new Option(Option::V4, 231, data)); + pkt.addOption(opt); + OptionBuffer data_sub = { 0x30, 0x31, 0x32, 0x33, 0x34, 0x35, 0x36, 0x37, 0x38, 0x39 }; + OptionPtr sub_opt(new Option(Option::V4, 1, data_sub)); + opt->addOption(sub_opt); + data_sub.clear(); + sub_opt.reset(new Option(Option::V4, 2, data_sub)); + opt->addOption(sub_opt); + + // Set verbose true but with verbose members not set. + EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68,\n" + "msg_type=DHCPDISCOVER (1), trans_id=0x9ef, secs=0, flags=0x0,\n" + "options:\n" + " type=053, len=001: 1 (uint8)\n" + " type=087, len=011: \"lorem ipsum\" (string)\n" + " type=123, len=004: 192.0.2.3\n" + " type=156, len=004: 123456 (uint32)\n" + " type=231, len=020: 61:62:63:64:65:66 'abcdef',\n" + "options:\n" + " type=001, len=010: 30:31:32:33:34:35:36:37:38:39 '0123456789'\n" + " type=002, len=000: ''", + pkt.toText(true)); + + // Now populate verbose members. + pkt.setSecs(2); + pkt.setFlags(0x80); + pkt.setCiaddr(IOAddress("1.1.1.1")); + pkt.setYiaddr(IOAddress("2.2.2.2")); + pkt.setSiaddr(IOAddress("3.3.3.3")); + pkt.setGiaddr(IOAddress("4.4.4.4")); + + std::vector sname = { 'x', 'y', 'z' }; + std::vector file = { 'A', 'B', 'C' }; + pkt.setSname(sname.data(), 3); + pkt.setFile(file.data(), 3); + + // Verbose defaulting to false. + 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" + " type=123, len=004: 192.0.2.3\n" + " type=156, len=004: 123456 (uint32)\n" + " type=231, len=020: 61:62:63:64:65:66 'abcdef',\n" + "options:\n" + " type=001, len=010: 30:31:32:33:34:35:36:37:38:39 '0123456789'\n" + " type=002, len=000: ''", + pkt.toText()); + + // Set verbose true. + EXPECT_EQ("local_address=192.0.2.34:67, remote_address=192.10.33.4:68,\n" + "msg_type=DHCPDISCOVER (1), trans_id=0x9ef, secs=2, flags=0x80, ciaddr=1.1.1.1," + " yiaddr=2.2.2.2, siaddr=3.3.3.3, giaddr=4.4.4.4, sname=[xyz], file=[ABC],\n" + "options:\n" + " type=053, len=001: 1 (uint8)\n" + " type=087, len=011: \"lorem ipsum\" (string)\n" + " type=123, len=004: 192.0.2.3\n" + " type=156, len=004: 123456 (uint32)\n" + " type=231, len=020: 61:62:63:64:65:66 'abcdef',\n" + "options:\n" + " type=001, len=010: 30:31:32:33:34:35:36:37:38:39 '0123456789'\n" + " type=002, len=000: ''", + pkt.toText(true)); +} + // Sanity check. Verifies that the getName() and getType() // don't throw. TEST_F(Pkt4Test, getType) { diff --git a/src/lib/util/str.cc b/src/lib/util/str.cc index 0bb7e8f67f..843c135fb3 100644 --- a/src/lib/util/str.cc +++ b/src/lib/util/str.cc @@ -347,6 +347,35 @@ dumpDouble(double val, size_t precision) { return (oss.str()); } +std::string +printOrDump(const std::vector& data, size_t max_dump) { + auto it = data.begin(); + bool print_it = true; + while (it != data.end() && *it != 0) { + if (!isprint(*it)) { + print_it = false; + break; + } + + ++it; + } + + if (print_it && it != data.begin()) { + return (std::string(data.begin(), it)); + } + + bool zeros = std::all_of(data.begin(), data.end(), [](int i) { return i==0; }); + if (!zeros) { + if (data.size() > max_dump) { + return (std::string(dumpAsHex(&data[0], max_dump) + std::string(".."))); + } + + return (dumpAsHex(&data[0], data.size())); + } + + return (""); +} + } // namespace str } // namespace util } // namespace isc diff --git a/src/lib/util/str.h b/src/lib/util/str.h index 4e817d5023..0e2a8549eb 100644 --- a/src/lib/util/str.h +++ b/src/lib/util/str.h @@ -293,6 +293,21 @@ dumpAsHex(const uint8_t* data, size_t length); /// @return string representation of val std::string dumpDouble(double val, size_t precision = 5); +/// @brief Outputs the contents of a vector as either a string printable +/// characters or a hex dump. +/// +/// Output of as string if all characters upto the first 0x0 are printable +/// characters, otherwise as a string of hex digits limited to max_dump +/// number of input bytes. If the vector is empty or all zeros it returns +/// an empty string. If the vector size exceeds max_dump when dumping as hex +/// the output will be suffixed with "..". +/// +/// @param data vector to be output +/// @param max_dump maximum number of bytes to include when dumping as hex +/// @return output string +std::string +printOrDump(const std::vector& data, size_t max_dump); + } // namespace str } // namespace util } // namespace isc diff --git a/src/lib/util/tests/str_unittests.cc b/src/lib/util/tests/str_unittests.cc index 78d28ce569..e1a87bb8f9 100644 --- a/src/lib/util/tests/str_unittests.cc +++ b/src/lib/util/tests/str_unittests.cc @@ -16,6 +16,7 @@ #include #include #include +#include #include @@ -526,4 +527,52 @@ TEST_F(StringUtilTest, vectorIsPrintable) { EXPECT_FALSE(isPrintable(content)); } +// Verifies the printOrDUmp operates correctly. +TEST_F(StringUtilTest, printOrDump) { + struct Scenario { + size_t line_; + std::vector input_; + size_t max_length_; + std::string exp_output_; + }; + + std::list scenarios { + { + __LINE__, + { '1', '2', '3', 0, 0 }, + 5, + "123", + }, + { + __LINE__, + { '4', '5', '6' }, + 3, + "456" + }, + { + __LINE__, + { 0 , 0, 0, 0}, + 4, + "" + }, + { + __LINE__, + { 0 , 1, 2, 3, 0}, + 5, + "00:01:02:03:00" + }, + { + __LINE__, + { 0 , 1, 2, 3, 0}, + 3, + "00:01:02.." + } + }; + + for ( auto const& scenario : scenarios ) { + EXPECT_EQ(printOrDump(scenario.input_, scenario.max_length_), + scenario.exp_output_); + } +} + } // namespace