[2524] Add logging to lease manager factory and MySQL lease manager

src/lib/dhcpsrv/dhcpsrv_messages.mes

@@ -24,12 +24,74 @@ This informational message is logged when a DHCP server (either V4 or V6) is
 about to open a memory file lease database.  The parameters of the connection
 are logged.
 
+% DHCPSRV_MYSQL_ADD_ADDR4 adding IPv4 lease with address %1
+A debug message issued when the server is about to add an IPv4 lease
+with the specified address to the MySQL backend database.
+
+% DHCPSRV_MYSQL_ADD_ADDR6 adding IPv6 lease with address %1
+A debug message issued when the server is about to add an IPv6 lease
+with the specified address to the MySQL backend database.
+
 % DHCPSRV_MYSQL_DB opening MySQL lease database: %1
 This informational message is logged when a DHCP server (either V4 or V6) is
 about to open a MySQL lease database.  The parameters of the connection
 including database name and username needed to access it (but not the
 password if any) are logged.
 
+% DHCPSRV_MYSQL_DELETE_ADDR deleting lease for address %1
+A debug message issued when the server is attempting to delete
+a lease for the specified address from the database for the specified address.
+
+% DHCPSRV_MYSQL_GET_ADDR4 obtaining IPv4 lease for address %1
+A debug message issued when the server is attempting to obtain an
+IPv4 lease from the database for the specified address.
+
+% DHCPSRV_MYSQL_GET_ADDR6 obtaining IPv6 lease for address %1
+A debug message issued when the server is attempting to obtain an
+IPv6 lease from the database for the specified address.
+
+% DHCPSRV_MYSQL_GET_CLIENTID obtaining IPv4 leases for client ID %1
+A debug message issued when the server is attempting to obtain a set of
+IPv4 leases from the database for a client with the specified client
+identification.
+
+% DHCPSRV_MYSQL_GET_HWADDR obtaining IPv4 leases for hardware address %1
+A debug message issued when the server is attempting to obtain a set of
+IPv4 leases from the database for a client with the specified hardware
+address.
+
+% DHCPSRV_MYSQL_GET_IAID_DUID obtaining IPv4 leases for IAID %1 and DUID %2
+A debug message issued when the server is attempting to obtain a set of IPv6
+lease from the database for a client with the specified IAID (Identity Association ID) and
+DUID (DHCP Unique Identifier).
+
+% DHCPSRV_MYSQL_GET_IAID_SUBID_DUID obtaining IPv4 leases for IAID %1, Subnet ID %2 and DUID %3
+A debug message issued when the server is attempting to obtain an IPv6 lease
+from the database for a client with the specified IAID (Identity Association ID),
+Subnet ID and DUID (DHCP Unique Identifier).
+
+% DHCPSRV_MYSQL_GET_SUBID_CLIENTID obtaining IPv4 lease for subnet ID %1 and client ID %2
+A debug message issued when the server is attempting to obtain an IPv4
+lease from the database for a client with the specified subnet ID and
+client ID.
+
+% DHCPSRV_MYSQL_GET_SUBID_HWADDR obtaining IPv4 lease for subnet ID %1 and hardware address %2
+A debug message issued when the server is attempting to obtain an IPv4
+lease from the database for a client with the specified subnet ID and
+hardware address.
+
+% DHCPSRV_MYSQL_GET_VERSION obtaining schema version information
+A debug message issued when the server is about to obtain schema version
+information from the database.
+
+% DHCPSRV_MYSQL_UPDATE_ADDR4 updating IPv4 lease for address %1
+A debug message issued when the server is attempting to update
+IPv4 lease from the database for the specified address.
+
+% DHCPSRV_MYSQL_UPDATE_ADDR6 updating IPv6 lease for address %1
+A debug message issued when the server is attempting to update
+IPv6 lease from the database for the specified address.
+
 % DHCPSRV_NOTYPE_DB no 'type' keyword to determine database backend: %1
 This is an error message, logged when an attempt has been made to access a
 database backend, but where no 'type' keyword has been included in the access

src/lib/dhcpsrv/lease_mgr.cc

@@ -55,7 +55,19 @@ std::string LeaseMgr::getParameter(const std::string& name) const {
 }
 
 std::string
-Lease6::toText() {
+Lease4::toText() const {
+    ostringstream stream;
+
+    stream << "Address:       " << addr_.toText() << "\n"
+           << "Valid life:    " << valid_lft_ << "\n"
+           << "Cltt:          " << cltt_ << "\n"
+           << "Subnet ID:     " << subnet_id_ << "\n";
+
+    return (stream.str());
+}
+
+std::string
+Lease6::toText() const {
     ostringstream stream;
 
     stream << "Type:          " << static_cast<int>(type_) << " (";

src/lib/dhcpsrv/lease_mgr.h

@@ -222,12 +222,17 @@ struct Lease4 {
           comments_()
     {}
 
-    /// @brief Default Constructor
+    /// @brief Default constructor
     ///
     /// Initialize fields that don't have a default constructor.
     Lease4() : addr_(0), fixed_(false), fqdn_fwd_(false), fqdn_rev_(false)
     {}
 
+    /// @brief Convert lease to printable form
+    ///
+    /// @return Textual represenation of lease data
+    std::string toText() const;
+
     /// @brief Compare two leases for equality
     ///
     /// @param other lease6 object with which to compare
@@ -377,7 +382,7 @@ struct Lease6 {
     /// @brief Convert Lease6 to Printable Form
     ///
     /// @return String form of the lease
-    std::string toText();
+    std::string toText() const;
 
     /// @brief Compare two leases for equality
     ///

src/lib/dhcpsrv/lease_mgr_factory.cc

@@ -14,6 +14,7 @@
 
 #include "config.h"
 
+#include <dhcpsrv/dhcpsrv_log.h>
 #include <dhcpsrv/lease_mgr_factory.h>
 #include <dhcpsrv/memfile_lease_mgr.h>
 #ifdef HAVE_MYSQL
@@ -61,6 +62,7 @@ LeaseMgrFactory::parse(const std::string& dbaccess) {
                 string value = token.substr(pos + 1);
                 mapped_tokens.insert(make_pair(name, value));
             } else {
+                LOG_ERROR(dhcpsrv_logger, DHCPSRV_INVALID_ACCESS).arg(dbaccess);
                 isc_throw(InvalidParameter, "Cannot parse " << token
                           << ", expected format is name=value");
             }
@@ -101,26 +103,36 @@ void
 LeaseMgrFactory::create(const std::string& dbaccess) {
     const std::string type = "type";
 
-    // Is "type" present?
+    // Parse the access string and create a redacted string for logging.
     LeaseMgr::ParameterMap parameters = parse(dbaccess);
+    std::string redacted = redactedAccessString(parameters);
+
+    // Is "type" present?
     if (parameters.find(type) == parameters.end()) {
+        LOG_ERROR(dhcpsrv_logger, DHCPSRV_NOTYPE_DB).arg(dbaccess);
         isc_throw(InvalidParameter, "Database configuration parameters do not "
                   "contain the 'type' keyword");
     }
 
+
     // Yes, check what it is.
 #ifdef HAVE_MYSQL
     if (parameters[type] == string("mysql")) {
+        LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_DB)
+            .arg(redacted);
         getLeaseMgrPtr().reset(new MySqlLeaseMgr(parameters));
         return;
     }
 #endif
     if (parameters[type] == string("memfile")) {
+        LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MEMFILE_DB)
+            .arg(redacted);
         getLeaseMgrPtr().reset(new Memfile_LeaseMgr(parameters));
         return;
     }
 
     // Get here on no match
+    LOG_ERROR(dhcpsrv_logger, DHCPSRV_UNKNOWN_DB).arg(parameters[type]);
     isc_throw(InvalidType, "Database access parameter 'type' does "
               "not specify a supported database backend");
 }

src/lib/dhcpsrv/mysql_lease_mgr.cc

@@ -16,14 +16,15 @@
 
 #include <asiolink/io_address.h>
 #include <dhcp/duid.h>
+#include <dhcpsrv/dhcpsrv_log.h>
 #include <dhcpsrv/mysql_lease_mgr.h>
 
 #include <boost/static_assert.hpp>
 #include <mysql/mysqld_error.h>
 
-#include <algorithm>
 #include <iostream>
 #include <iomanip>
+#include <sstream>
 #include <string>
 #include <time.h>
 
@@ -191,8 +192,38 @@ TaggedStatement tagged_statements[] = {
     {MySqlLeaseMgr::NUM_STATEMENTS, NULL}
 };
 
+/// @brief Produce string representation of hardware address
+///
+/// Returns a string containing the hardware address. This is only used for
+/// logging.
+///
+/// @note Six characters is an arbitrary length, chosen to provide a
+///       suitably wide string.
+///
+/// @todo Create a "hardware address" class of which this will be a member.
+///
+/// @param hwaddr Hardware address to convert to string form
+///
+/// @return String form of the hardware address.
+std::string
+hardwareAddressString(const LeaseMgr::HWAddr& hwaddr) {
+    std::ostringstream stream;
+
+    for (size_t i = 0; i < hwaddr.size(); ++i) {
+        if (i > 0) {
+            stream << ":";
+        }
+        stream << std::setw(2) << std::setfill('0')
+               << static_cast<unsigned int>(hwaddr[i]);
+    }
+
+    return (stream.str());
+}
+
 };  // Anonymous namespace
 
+
+
 namespace isc {
 namespace dhcp {
 
@@ -1112,6 +1143,9 @@ MySqlLeaseMgr::addLeaseCommon(StatementIndex stindex,
 
 bool
 MySqlLeaseMgr::addLease(const Lease4Ptr& lease) {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_ADD_ADDR4)
+        .arg(lease->addr_.toText());
+
     // Create the MYSQL_BIND array for the lease
     std::vector<MYSQL_BIND> bind = exchange4_->createBindForSend(lease);
 
@@ -1121,6 +1155,9 @@ MySqlLeaseMgr::addLease(const Lease4Ptr& lease) {
 
 bool
 MySqlLeaseMgr::addLease(const Lease6Ptr& lease) {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_ADD_ADDR6)
+        .arg(lease->addr_.toText());
+
     // Create the MYSQL_BIND array for the lease
     std::vector<MYSQL_BIND> bind = exchange6_->createBindForSend(lease);
 
@@ -1257,6 +1294,9 @@ void MySqlLeaseMgr::getLease(StatementIndex stindex, MYSQL_BIND* bind,
 
 Lease4Ptr
 MySqlLeaseMgr::getLease4(const isc::asiolink::IOAddress& addr) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_ADDR4)
+        .arg(addr.toText());
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[1];
     memset(inbind, 0, sizeof(inbind));
@@ -1276,6 +1316,9 @@ MySqlLeaseMgr::getLease4(const isc::asiolink::IOAddress& addr) const {
 
 Lease4Collection
 MySqlLeaseMgr::getLease4(const HWAddr& hwaddr) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_HWADDR)
+        .arg(hardwareAddressString(hwaddr));
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[1];
     memset(inbind, 0, sizeof(inbind));
@@ -1303,6 +1346,9 @@ MySqlLeaseMgr::getLease4(const HWAddr& hwaddr) const {
 
 Lease4Ptr
 MySqlLeaseMgr::getLease4(const HWAddr& hwaddr, SubnetID subnet_id) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_SUBID_HWADDR)
+        .arg(subnet_id).arg(hardwareAddressString(hwaddr));
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[2];
     memset(inbind, 0, sizeof(inbind));
@@ -1334,6 +1380,9 @@ MySqlLeaseMgr::getLease4(const HWAddr& hwaddr, SubnetID subnet_id) const {
 
 Lease4Collection
 MySqlLeaseMgr::getLease4(const ClientId& clientid) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_CLIENTID)
+        .arg(clientid.toText());
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[1];
     memset(inbind, 0, sizeof(inbind));
@@ -1355,6 +1404,9 @@ MySqlLeaseMgr::getLease4(const ClientId& clientid) const {
 
 Lease4Ptr
 MySqlLeaseMgr::getLease4(const ClientId& clientid, SubnetID subnet_id) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_SUBID_CLIENTID)
+        .arg(subnet_id).arg(clientid.toText());
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[2];
     memset(inbind, 0, sizeof(inbind));
@@ -1380,6 +1432,9 @@ MySqlLeaseMgr::getLease4(const ClientId& clientid, SubnetID subnet_id) const {
 
 Lease6Ptr
 MySqlLeaseMgr::getLease6(const isc::asiolink::IOAddress& addr) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_ADDR6)
+        .arg(addr.toText());
+
     // Set up the WHERE clause value
     MYSQL_BIND inbind[1];
     memset(inbind, 0, sizeof(inbind));
@@ -1403,6 +1458,8 @@ MySqlLeaseMgr::getLease6(const isc::asiolink::IOAddress& addr) const {
 
 Lease6Collection
 MySqlLeaseMgr::getLease6(const DUID& duid, uint32_t iaid) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_IAID_DUID)
+        .arg(iaid).arg(duid.toText());
 
     // Set up the WHERE clause value
     MYSQL_BIND inbind[2];
@@ -1444,6 +1501,8 @@ MySqlLeaseMgr::getLease6(const DUID& duid, uint32_t iaid) const {
 Lease6Ptr
 MySqlLeaseMgr::getLease6(const DUID& duid, uint32_t iaid,
                          SubnetID subnet_id) const {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_IAID_SUBID_DUID)
+        .arg(iaid).arg(subnet_id).arg(duid.toText());
 
     // Set up the WHERE clause value
     MYSQL_BIND inbind[3];
@@ -1511,6 +1570,9 @@ void
 MySqlLeaseMgr::updateLease4(const Lease4Ptr& lease) {
     const StatementIndex stindex = UPDATE_LEASE4;
 
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_UPDATE_ADDR4)
+        .arg(lease->addr_.toText());
+
     // Create the MYSQL_BIND array for the data being updated
     std::vector<MYSQL_BIND> bind = exchange4_->createBindForSend(lease);
 
@@ -1533,6 +1595,9 @@ void
 MySqlLeaseMgr::updateLease6(const Lease6Ptr& lease) {
     const StatementIndex stindex = UPDATE_LEASE6;
 
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_UPDATE_ADDR6)
+        .arg(lease->addr_.toText());
+
     // Create the MYSQL_BIND array for the data being updated
     std::vector<MYSQL_BIND> bind = exchange6_->createBindForSend(lease);
 
@@ -1579,6 +1644,8 @@ MySqlLeaseMgr::deleteLeaseCommon(StatementIndex stindex, MYSQL_BIND* bind) {
 
 bool
 MySqlLeaseMgr::deleteLease(const isc::asiolink::IOAddress& addr) {
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_DELETE_ADDR)
+        .arg(addr.toText());
 
     // Set up the WHERE clause value
     MYSQL_BIND inbind[1];
@@ -1632,6 +1699,8 @@ std::pair<uint32_t, uint32_t>
 MySqlLeaseMgr::getVersion() const {
     const StatementIndex stindex = GET_VERSION;
 
+    LOG_DEBUG(dhcpsrv_logger, DHCPSRV_DBG_TRACE, DHCPSRV_MYSQL_GET_VERSION);
+
     uint32_t    major;      // Major version number
     uint32_t    minor;      // Minor version number