[2414] Allocation process is now logged properly.

src/bin/dhcp6/dhcp6_messages.mes

@@ -30,6 +30,11 @@ from the BIND 10 control system by the IPv6 DHCP server.
 A debug message indicating that the IPv6 DHCP server has received an
 updated configuration from the BIND 10 configuration system.
 
+% DHCP6_DB_BACKEND_STARTED Lease database started (backend type: %1)
+This informational message is printed every time DHCPv6 is started.
+It indicates which backend type will be used throughout the server
+operation.
+
 % DHCP6_NOT_RUNNING IPv6 DHCP server is not running
 A warning message is issued when an attempt is made to shut down the
 IPv6 DHCP server but it is not running.
@@ -42,6 +47,17 @@ interfaces and is therefore shutting down.
 A debug message issued during startup, this indicates that the IPv6 DHCP
 server is about to open sockets on the specified port.
 
+% DHCP6_LEASE_ALLOC Lease %1 %2 allocated (client duid=%3, iaid=%4)
+This debug message indicates that the server successfully advertised (i.e.
+responded to SOLICIT) or granted (i.e. responded to REQUEST) a lease.
+This is a normal behavior and incicates successful operation.
+
+% DHCP6_LEASE_ALLOC_FAIL Failed to %1 a lease for client duid=%2, iaid=%3
+This message indicates that the server failed to advertise (i.e. respond
+to SOLICIT) or grant (i.e. respond to REQUEST) a lease for a given client.
+There may be many reasons for such failure. Each specific failure is logged
+in a separate log entry.
+
 % DHCP6_PACKET_PARSE_FAIL failed to parse incoming packet
 The IPv6 DHCP server has received a packet that it is unable to interpret.
 
@@ -66,6 +82,11 @@ This error is output if the server failed to assemble the data to be
 returned to the client into a valid packet.  The reason is most likely
 to be to a programming error: please raise a bug report.
 
+% DHCP6_PROCESS_IA_NA_REQUEST Server is processing IA_NA option (duid=%1, iaid=%2, hint=%3)
+This is a debug message that indicates a processing of received IA_NA
+option. It may optionally contain an address that may be used by the server
+as a hint for possible requested address.
+
 % DHCP6_QUERY_DATA received packet length %1, data length %2, data is %3
 A debug message listing the data received from the client or relay.
 
@@ -110,6 +131,17 @@ This is a debug message issued during the IPv6 DHCP server startup.
 It lists some information about the parameters with which the server
 is running.
 
+% DHCP6_SUBNET_SELECTED The %s subnet was selected for client assignment
+This is a debug message informing that a given subnet was selected. It will
+be used for address and option assignment. This is one of the early steps
+in the processing of incoming client message.
+
+% DHCP6_SUBNET_SELECTION_FAILED Failed to select a subnet for incoming packet, src=%1 type=%2
+This is a warning message that a packet was received, but the server is
+not configured to support the subnet the packet originated from. This
+message means that the received traffic does not match server configuration
+and is likely a configuration issue.
+
 % DHCP6_CONFIG_LOAD_FAIL failed to load configuration: %1
 This critical error message indicates that the initial DHCPv6
 configuration has failed. The server will start, but nothing will be

src/bin/dhcp6/dhcp6_srv.cc

@@ -79,6 +79,9 @@ Dhcpv6Srv::Dhcpv6Srv(uint16_t port) {
     // @todo: Replace this with MySQL_LeaseMgr once it is merged
     new isc::dhcp::test::Memfile_LeaseMgr("");
 
+    LOG_INFO(dhcp6_logger, DHCP6_DB_BACKEND_STARTED)
+        .arg(LeaseMgr::instance().getName());
+
     // Instantiate allocation engine
     alloc_engine_ = new AllocEngine(AllocEngine::ALLOC_ITERATIVE, 100);
 
@@ -330,9 +333,12 @@ void Dhcpv6Srv::assignLeases(const Pkt6Ptr& question, Pkt6Ptr& answer) {
 
     Subnet6Ptr subnet = selectSubnet(question);
     if (subnet) {
-        cout << "#### Selected subnet " << subnet->toText() << endl;
+        LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL_DATA, DHCP6_SUBNET_SELECTED)
+            .arg(subnet->toText());
     } else {
-        cout << "#### Failed to select a subnet" << endl;
+        // perhaps this should be logged on some higher level? This is most likely
+        // configuration bug.
+        LOG_DEBUG(dhcp6_logger, DBG_DHCP6_BASIC, DHCP6_SUBNET_SELECTION_FAILED);
     }
 
     // @todo: We should implement Option6Duid some day, but we can do without it
@@ -342,11 +348,6 @@ void Dhcpv6Srv::assignLeases(const Pkt6Ptr& question, Pkt6Ptr& answer) {
     if (opt_duid) {
         duid = DuidPtr(new DUID(opt_duid->getData()));
     }
-    if (duid) {
-        cout << "#### Processing request from client with duid=" << duid->toText() << endl;
-    } else {
-        cout << "#### Failed to find client-id :(" << endl;
-    }
 
     for (Option::OptionCollection::iterator opt = question->options_.begin();
          opt != question->options_.end(); ++opt) {
@@ -375,16 +376,15 @@ OptionPtr Dhcpv6Srv::handleIA_NA(const Subnet6Ptr& subnet, const DuidPtr& duid,
     }
 
     shared_ptr<Option6IAAddr> hintOpt = dynamic_pointer_cast<Option6IAAddr>(ia->getOption(D6O_IAADDR));
-
     IOAddress hint("::");
-    cout << "#### Processing request IA_NA: iaid=" << ia->getIAID();
     if (hintOpt) {
         hint = hintOpt->getAddress();
-        cout << ", hint=" << hint.toText() << endl;
-    } else {
-        cout << ", no hint provided" << endl;
     }
 
+    LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL, DHCP6_PROCESS_IA_NA_REQUEST)
+        .arg(duid?duid->toText():"(no-duid)").arg(ia->getIAID())
+        .arg(hintOpt?hint.toText():"(no hint)");
+
     bool fake_allocation = false;
     if (question->getType() == DHCPV6_SOLICIT) {
         /// @todo: Check if we support rapid commit
@@ -397,7 +397,11 @@ OptionPtr Dhcpv6Srv::handleIA_NA(const Subnet6Ptr& subnet, const DuidPtr& duid,
     boost::shared_ptr<Option6IA> ia_rsp(new Option6IA(D6O_IA_NA, ia->getIAID()));
 
     if (lease) {
-        cout << "#### Allocated lease:" << lease->addr_.toText() << endl;
+        LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL, DHCP6_LEASE_ALLOC)
+            .arg(lease->addr_.toText())
+            .arg(fake_allocation?"would be":"has been")
+            .arg(duid?duid->toText():"(no-duid)")
+            .arg(ia->getIAID());
 
         ia_rsp->setT1(subnet->getT1());
         ia_rsp->setT2(subnet->getT2());
@@ -409,7 +413,11 @@ OptionPtr Dhcpv6Srv::handleIA_NA(const Subnet6Ptr& subnet, const DuidPtr& duid,
                                    lease->valid_lft_));
         ia_rsp->addOption(addr);
     } else {
-        cout << "#### Failed to allocate a lease";
+        LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL, DHCP6_LEASE_ALLOC_FAIL)
+            .arg(fake_allocation?"advertise":"grant")
+            .arg(duid?duid->toText():"(no-duid)")
+            .arg(ia->getIAID())
+            .arg(subnet->toText());
 
         ia_rsp->addOption(createStatusCode(STATUS_NoAddrsAvail, "Sorry, no address could be allocated."));
     }