From 086343cf7c919885c6b3a0f84d4ae3db94ab107f Mon Sep 17 00:00:00 2001
From: Thomas Markwalder <tmark@isc.org>
Date: Wed, 15 Apr 2015 14:08:33 -0400
Subject: [PATCH] [3743] Add bad_packet logger to dhcp4 server

doc/guide/logging.xml - added new logger description
src/bin/dhcp4/dhcp4_log.cc - added bad_packet logger and log name declarations
src/bin/dhcp4/dhcp4_log.h - added bad_packet and log name externs
src/bin/dhcp4/dhcp4_messages.mes - changed drop and NAK message identifiers
src/bin/dhcp4/dhcp4_srv.cc - changed packet drop and NAK log invocations
src/bin/dhcp4/main.cc - used extern for log name
---
 doc/guide/logging.xml            | 13 ++++-
 src/bin/dhcp4/dhcp4_log.cc       |  5 ++
 src/bin/dhcp4/dhcp4_log.h        | 12 ++++
 src/bin/dhcp4/dhcp4_messages.mes | 96 ++++++++++++++++----------------
 src/bin/dhcp4/dhcp4_srv.cc       | 31 +++++------
 src/bin/dhcp4/main.cc            |  6 +-
 6 files changed, 92 insertions(+), 71 deletions(-)

diff --git a/doc/guide/logging.xml b/doc/guide/logging.xml
index 5db5e0bd29..6ef86fc25f 100644
--- a/doc/guide/logging.xml
+++ b/doc/guide/logging.xml
@@ -154,6 +154,13 @@
             the settings from this logger if there is no specialized logger
             provided.</simpara>
           </listitem>
+          <listitem>
+            <simpara><command>kea-dhcp4.bad_packet</command> - this is the
+            logger used by the DHCPv4 server deamon for logging inbound clien
+            packets that were dropped or to which the server responded with a
+            NAK.  The allows adminstrators to configure a separate log
+            output that contains only packet drop and reject entries.</simpara>
+          </listitem>
           <listitem>
             <simpara><command>kea-dhcp4.dhcp4</command> - this is the logger
             used solely by the DHCPv4 server deamon. This logger does not
@@ -362,7 +369,7 @@ TODO; there's a ticket to determine these levels, see #1074
 
         </para>
 
-        <!-- configuration of flush is not supported yet. 
+        <!-- configuration of flush is not supported yet.
         <section>
           <title>flush (true of false)</title>
 
@@ -442,7 +449,7 @@ TODO; there's a ticket to determine these levels, see #1074
                 {
                     "output": "stdout"
                 }
-            ], 
+            ],
             "severity": "WARN"
         }
     ]
@@ -467,7 +474,7 @@ file be created.</para>
                     "maxsize": 204800,
                     "destination": "file"
                 }
-            ], 
+            ],
             "severity": "DEBUG",
             "debuglevel": 99
         }
diff --git a/src/bin/dhcp4/dhcp4_log.cc b/src/bin/dhcp4/dhcp4_log.cc
index b5c679817c..b6955aa138 100644
--- a/src/bin/dhcp4/dhcp4_log.cc
+++ b/src/bin/dhcp4/dhcp4_log.cc
@@ -19,7 +19,12 @@
 namespace isc {
 namespace dhcp {
 
+const char* DHCP4_ROOT_LOGGER_NAME = "kea-dhcp4";
+const char* DHCP4_APP_LOGGER_NAME = "dhcp4";
+const char* DHCP4_BAD_PACKET_LOGGER_NAME = "bad-packet";
+
 isc::log::Logger dhcp4_logger("dhcp4");
+isc::log::Logger bad_packet_logger(DHCP4_BAD_PACKET_LOGGER_NAME);
 
 } // namespace dhcp
 } // namespace isc
diff --git a/src/bin/dhcp4/dhcp4_log.h b/src/bin/dhcp4/dhcp4_log.h
index b4979a2f21..23861c7e52 100644
--- a/src/bin/dhcp4/dhcp4_log.h
+++ b/src/bin/dhcp4/dhcp4_log.h
@@ -22,6 +22,9 @@
 namespace isc {
 namespace dhcp {
 
+/// Defines the name of the root level "default" logger for kea dhcp4 server.
+extern const char* DHCP4_ROOT_LOGGER_NAME;
+
 /// \brief DHCP4 Logging
 ///
 /// Defines the levels used to output debug messages in the non-library part of
@@ -54,8 +57,17 @@ const int DBG_DHCP4_DETAIL_DATA = DBGLVL_TRACE_DETAIL_DATA;
 /// a logger in each file, but we would want to define a common name to avoid
 /// spelling mistakes, so it is just one small step from there to define a
 /// module-common logger.
+extern const char* DHCP4_APP_LOGGER_NAME;
 extern isc::log::Logger dhcp4_logger;
 
+/// Define a separate logger to which bad packets are logged.  This allows
+/// users to segregate them into a separate log destination for easy monitoring
+/// and diagnostics.  Here "bad packet" are packets that are either dropped
+/// (i.e malformed, unsupported types) or packets that are rejected and NAKed
+/// for logical reasons.
+extern const char* DHCP4_BAD_PACKET_LOGGER_NAME;
+extern isc::log::Logger bad_packet_logger;
+
 } // namespace dhcp4
 } // namespace isc
 
diff --git a/src/bin/dhcp4/dhcp4_messages.mes b/src/bin/dhcp4/dhcp4_messages.mes
index 7707044e94..5e6ea32fef 100644
--- a/src/bin/dhcp4/dhcp4_messages.mes
+++ b/src/bin/dhcp4/dhcp4_messages.mes
@@ -157,33 +157,17 @@ The server has failed to initialize. This may be because the configuration
 was not successful, or it encountered any other critical error on startup.
 Attached error message provides more details about the issue.
 
-% DHCP4_INVALID_ADDRESS_INIT_REBOOT invalid address %1 requested by INIT-REBOOT client (id: %2, hwaddr: %3)
-This debug message is issued when the client being in the INIT-REBOOT state
-requested an address which is not assigned to him. The server will respond
-to this client with DHCPNAK.
-
 % DHCP4_LEASE_ADVERT lease %1 advertised (client client-id %2, hwaddr %3)
 This debug message indicates that the server successfully advertised
 a lease. It is up to the client to choose one server out of other advertised
 and continue allocation with that server. This is a normal behavior and
 indicates successful operation.
 
-% DHCP4_LEASE_ADVERT_FAIL failed to advertise a lease for client-id %1, hwaddr %2, client sent ciaddr %3, requested-ip-address %4
-This message indicates that the server has failed to offer a lease to
-the specified client after receiving a DISCOVER message from it. There are
-many possible reasons for such a failure.
-
 % DHCP4_LEASE_ALLOC lease %1 has been allocated for client-id %2, hwaddr %3
 This debug message indicates that the server successfully granted a lease
 in response to client's REQUEST message. This is a normal behavior and
 indicates successful operation.
 
-% DHCP4_LEASE_ALLOC_FAIL failed to grant a lease for client-id %1, hwaddr %2, client sent ciaddr %3, requested-ip-address %4
-This message indicates that the server failed to grant a lease to the
-specified client after receiving a REQUEST message from it.  There are many
-possible reasons for such a failure. Additional messages will indicate the
-reason.
-
 % DHCP4_LEASE_DATABASE_TIMERS_EXEC_FAIL failed to execute timer-based functions for lease database: %1
 A warning message executed when a server process is unable to execute
 the periodic actions for the lease database. An example of the periodic
@@ -217,13 +201,6 @@ This warning message is issued when current server configuration specifies
 no interfaces that server should listen on, or specified interfaces are not
 configured to receive the traffic.
 
-% DHCP4_NO_SUBNET_FOR_DIRECT_CLIENT no suitable subnet configured for a direct client sending packet with transaction id %1, on interface %2, received message is dropped
-This info message is logged when received a message from a directly connected
-client but there is no suitable subnet configured for the interface on
-which this message has been received. The IPv4 address assigned on this
-interface must belong to one of the configured subnets. Otherwise
-received message is dropped.
-
 % DHCP4_OPEN_SOCKET opening sockets on port %1
 A debug message issued during startup, this indicates that the DHCPv4
 server is about to open sockets on the specified port.
@@ -232,26 +209,66 @@ server is about to open sockets on the specified port.
 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_NO_TYPE packet received on interface %1 dropped, because of missing msg-type option
-This is a debug message informing that incoming DHCPv4 packet did not
-have mandatory DHCP message type option and thus was dropped.
+% DHCP4_PACKET_DROP_0001 failed to parse incoming packet: %1
+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.
+
+% DHCP4_PACKET_DROP_0002 no suitable subnet configured for a direct client sending packet with transaction id %1, on interface %2, received message is dropped
+This info message is logged when received a message from a directly connected
+client but there is no suitable subnet configured for the interface on
+which this message has been received. The IPv4 address assigned on this
+interface must belong to one of the configured subnets. Otherwise
+received message is dropped.
 
-% DHCP4_PACKET_NOT_FOR_US received DHCPv4 message (transid=%1, iface=%2) dropped because it contains foreign server identifier
+% DHCP4_PACKET_DROP_0003 received DHCPv4 message (transid=%1, iface=%2) dropped because it contains foreign server identifier
 This debug message is issued when received DHCPv4 message is dropped because
 it is addressed to a different server, i.e. a server identifier held by
 this message doesn't match the identifier used by our server. The arguments
 of this message hold the name of the transaction id and interface on which
 the message has been received.
 
-% DHCP4_PACKET_PARSE_FAIL failed to parse incoming packet: %1
-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.
+% DHCP4_PACKET_DROP_0004 packet received on interface %1 dropped, because of missing msg-type option
+This is a debug message informing that incoming DHCPv4 packet did not
+have mandatory DHCP message type option and thus was dropped.
+
+% DHCP4_PACKET_DROP_0005 received message (transaction id %1) has unrecognized type %2 in option 53
+This debug message indicates that the message type carried in DHCPv4 option
+53 is unrecognized by the server. The valid message types are listed
+on the IANA website: http://www.iana.org/assignments/bootp-dhcp-parameters/bootp-dhcp-parameters.xhtml#message-type-53.
+The message will not be processed by the server.
+
+% DHCP4_PACKET_DROP_0006 received message (transaction id %1), having type %2 is not supported
+This debug message indicates that the message type carried in DHCPv4 option
+53 is valid but the message will not be processed by the server. This includes
+messages being normally sent by the server to the client, such as Offer, ACK,
+NAK etc.
 
-% DHCP4_PACKET_PROCESS_FAIL failed to process packet received from %1: %2
+% DHCP4_PACKET_DROP_0007 failed to process packet received from %1: %2
 This is a general catch-all message indicating that the processing of a
 received packet failed.  The reason is given in the message.  The server
 will not send a response but will instead ignore the packet.
 
+% DHCP4_PACKET_NAK_0001 failed to select a subnet for incoming packet, src: %1, type: %2
+This warning message is output when a packet was received from a subnet
+for which the DHCPv4 server has not been configured. The most probable
+cause is a misconfiguration of the server.
+
+% DHCP4_PACKET_NAK_0002 invalid address %1 requested by INIT-REBOOT client (id: %2, hwaddr: %3)
+This debug message is issued when the client being in the INIT-REBOOT state
+requested an address which is not assigned to him. The server will respond
+to this client with DHCPNAK.
+
+% DHCP4_PACKET_NAK_0003 failed to advertise a lease for client-id %1, hwaddr %2, client sent ciaddr %3, requested-ip-address %4
+This message indicates that the server has failed to offer a lease to
+the specified client after receiving a DISCOVER message from it. There are
+many possible reasons for such a failure.
+
+% DHCP4_PACKET_NAK_0004 failed to grant a lease for client-id %1, hwaddr %2, client sent ciaddr %3, requested-ip-address %4
+This message indicates that the server failed to grant a lease to the
+specified client after receiving a REQUEST message from it.  There are many
+possible reasons for such a failure. Additional messages will indicate the
+reason.
+
 % DHCP4_PACKET_RECEIVED %1 (type %2) packet received on interface %3
 A debug message noting that the server has received the specified type of
 packet on the specified interface.  Note that a packet marked as UNKNOWN
@@ -390,20 +407,3 @@ is running.
 This is a debug message noting the selection of a subnet to be used for
 address and option assignment.  Subnet selection is one of the early
 steps in the processing of incoming client message.
-
-% DHCP4_SUBNET_SELECTION_FAILED failed to select a subnet for incoming packet, src: %1, type: %2
-This warning message is output when a packet was received from a subnet
-for which the DHCPv4 server has not been configured. The most probable
-cause is a misconfiguration of the server.
-
-% DHCP4_UNRECOGNIZED_RCVD_PACKET_TYPE received message (transaction id %1) has unrecognized type %2 in option 53
-This debug message indicates that the message type carried in DHCPv4 option
-53 is unrecognized by the server. The valid message types are listed
-on the IANA website: http://www.iana.org/assignments/bootp-dhcp-parameters/bootp-dhcp-parameters.xhtml#message-type-53.
-The message will not be processed by the server.
-
-% DHCP4_UNSUPPORTED_RCVD_PACKET_TYPE received message (transaction id %1), having type %2 is not supported
-This debug message indicates that the message type carried in DHCPv4 option
-53 is valid but the message will not be processed by the server. This includes
-messages being normally sent by the server to the client, such as Offer, ACK,
-NAK etc.
diff --git a/src/bin/dhcp4/dhcp4_srv.cc b/src/bin/dhcp4/dhcp4_srv.cc
index 914e46ed13..1ff92ebd89 100644
--- a/src/bin/dhcp4/dhcp4_srv.cc
+++ b/src/bin/dhcp4/dhcp4_srv.cc
@@ -402,8 +402,9 @@ Dhcpv4Srv::run() {
                 query->unpack();
             } catch (const std::exception& e) {
                 // Failed to parse the packet.
-                LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL,
-                          DHCP4_PACKET_PARSE_FAIL).arg(e.what());
+                LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL,
+                          DHCP4_PACKET_DROP_0001)
+                    .arg(e.what());
                 continue;
             }
         }
@@ -500,8 +501,8 @@ Dhcpv4Srv::run() {
                 if (hwptr) {
                     source = hwptr->toText();
                 }
-                LOG_DEBUG(dhcp4_logger, DBG_DHCP4_BASIC,
-                          DHCP4_PACKET_PROCESS_FAIL)
+                LOG_DEBUG(bad_packet_logger, DBG_DHCP4_BASIC,
+                          DHCP4_PACKET_DROP_0007)
                     .arg(source).arg(e.what());
             }
         }
@@ -1058,7 +1059,7 @@ Dhcpv4Srv::assignLease(Dhcpv4Exchange& ex) {
 
         // perhaps this should be logged on some higher level? This is most
         // likely configuration bug.
-        LOG_ERROR(dhcp4_logger, DHCP4_SUBNET_SELECTION_FAILED)
+        LOG_ERROR(bad_packet_logger, DHCP4_PACKET_NAK_0001)
             .arg(query->getRemoteAddr().toText())
             .arg(serverReceivedPacketName(query->getType()));
         resp->setType(DHCPNAK);
@@ -1123,8 +1124,8 @@ Dhcpv4Srv::assignLease(Dhcpv4Exchange& ex) {
         }
         // Got a lease so we can check the address.
         if (lease && (lease->addr_ != hint)) {
-            LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL,
-                      DHCP4_INVALID_ADDRESS_INIT_REBOOT)
+            LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL,
+                      DHCP4_PACKET_NAK_0002)
                 .arg(hint.toText())
                 .arg(client_id ? client_id->toText():"(no client-id)")
                 .arg(hwaddr ? hwaddr->toText():"(no hwaddr info)");
@@ -1288,8 +1289,8 @@ Dhcpv4Srv::assignLease(Dhcpv4Exchange& ex) {
         // cause of that failure. The only thing left is to insert
         // status code to pass the sad news to the client.
 
-        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, fake_allocation?
-                  DHCP4_LEASE_ADVERT_FAIL:DHCP4_LEASE_ALLOC_FAIL)
+        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, fake_allocation ?
+                  DHCP4_PACKET_NAK_0003 : DHCP4_PACKET_NAK_0004)
             .arg(client_id?client_id->toText():"(no client-id)")
             .arg(hwaddr?hwaddr->toText():"(no hwaddr info)")
             .arg(query->getCiaddr().toText())
@@ -1752,7 +1753,7 @@ Dhcpv4Srv::accept(const Pkt4Ptr& query) const {
     // Check if the message from directly connected client (if directly
     // connected) should be dropped or processed.
     if (!acceptDirectRequest(query)) {
-        LOG_INFO(dhcp4_logger, DHCP4_NO_SUBNET_FOR_DIRECT_CLIENT)
+        LOG_INFO(bad_packet_logger, DHCP4_PACKET_DROP_0002)
             .arg(query->getTransid())
             .arg(query->getIface());
         return (false);
@@ -1761,7 +1762,7 @@ Dhcpv4Srv::accept(const Pkt4Ptr& query) const {
     // Check if the DHCPv4 packet has been sent to us or to someone else.
     // If it hasn't been sent to us, drop it!
     if (!acceptServerId(query)) {
-        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_NOT_FOR_US)
+        LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DROP_0003)
             .arg(query->getTransid())
             .arg(query->getIface());
         return (false);
@@ -1805,15 +1806,14 @@ Dhcpv4Srv::acceptMessageType(const Pkt4Ptr& query) const {
         type = query->getType();
 
     } catch (...) {
-        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DROP_NO_TYPE)
+        LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DROP_0004)
             .arg(query->getIface());
         return (false);
     }
 
     // If we receive a message with a non-existing type, we are logging it.
     if (type > DHCPLEASEQUERYDONE) {
-        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL,
-                  DHCP4_UNRECOGNIZED_RCVD_PACKET_TYPE)
+        LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DROP_0005)
             .arg(type)
             .arg(query->getTransid());
         return (false);
@@ -1830,8 +1830,7 @@ Dhcpv4Srv::acceptMessageType(const Pkt4Ptr& query) const {
     if ((type != DHCPDISCOVER) && (type != DHCPREQUEST) &&
         (type != DHCPRELEASE) && (type != DHCPDECLINE) &&
         (type != DHCPINFORM)) {
-        LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL,
-                  DHCP4_UNSUPPORTED_RCVD_PACKET_TYPE)
+        LOG_DEBUG(bad_packet_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DROP_0006)
             .arg(type)
             .arg(query->getTransid());
         return (false);
diff --git a/src/bin/dhcp4/main.cc b/src/bin/dhcp4/main.cc
index 28435072e0..bf6ce7b890 100644
--- a/src/bin/dhcp4/main.cc
+++ b/src/bin/dhcp4/main.cc
@@ -40,8 +40,6 @@ namespace {
 
 const char* const DHCP4_NAME = "kea-dhcp4";
 
-const char* const DHCP4_LOGGER_NAME = "kea-dhcp4";
-
 /// @brief Prints Kea Usage and exits
 ///
 /// Note: This function never returns. It terminates the process.
@@ -126,10 +124,10 @@ main(int argc, char* argv[]) {
         // It is important that we set a default logger name because this name
         // will be used when the user doesn't provide the logging configuration
         // in the Kea configuration file.
-        CfgMgr::instance().setDefaultLoggerName(DHCP4_LOGGER_NAME);
+        CfgMgr::instance().setDefaultLoggerName(DHCP4_ROOT_LOGGER_NAME);
 
         // Initialize logging.  If verbose, we'll use maximum verbosity.
-        Daemon::loggerInit(DHCP4_LOGGER_NAME, verbose_mode);
+        Daemon::loggerInit(DHCP4_ROOT_LOGGER_NAME, verbose_mode);
         LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_START_INFO)
             .arg(getpid()).arg(port_number).arg(verbose_mode ? "yes" : "no");
 
-- 
2.47.3