[3222] Addressed review comments, augmented logging

In addition to minor corrections, unit tests for NameChangeTransaction::
responseString was added.  Also added a similiar method NameChangeTransaction::
transactionOutcomeString() and unit tests.

src/bin/d2/d2_messages.mes

@@ -344,10 +344,10 @@ due to invalid data contained in the NameChangeRequest. The request will be
 aborted.  This is most likely a configuration issue.
 
 % DHCP_DDNS_ADD_SUCCEEDED DHCP_DDNS successfully added the DNS mapping addition for this request: %1
-This is a debug message issued after DHCP_DDNS has submitted DNS mapping
-additions which were received and accepted by an appropriate DNS server.
+This is an informational message issued after DHCP_DDNS has submitted DNS
+mapping additions which were received and accepted by an appropriate DNS server.
 
-% DHCP_DDNS_ADD_FAILED DHCP_DDNS failed attempting to make DNS mapping additions for this request: %1, event: %2
+% DHCP_DDNS_ADD_FAILED DHCP_DDNS Transaction outcome: %1
 This is an error message issued after DHCP_DDNS attempts to submit DNS mapping
 entry additions have failed.  The precise reason for the failure should be
 documented in preceding log entries.
@@ -430,10 +430,10 @@ while DHCP_DDNS was removing a reverse address mapping.  The request will be
 aborted.  This is most likely a programmatic issue and should be reported.
 
 % DHCP_DDNS_REMOVE_SUCCEEDED DHCP_DDNS successfully removed the DNS mapping addition for this request: %1
-This is a debug message issued after DHCP_DDNS has submitted DNS mapping
-removals which were received and accepted by an appropriate DNS server.
+This is an informational message issued after DHCP_DDNS has submitted DNS
+mapping removals which were received and accepted by an appropriate DNS server.
 
-% DHCP_DDNS_REMOVE_FAILED DHCP_DDNS failed attempting to make DNS mapping removals for this request: %1, event: %2
+% DHCP_DDNS_REMOVE_FAILED DHCP_DDNS Transaction outcome: %1
 This is an error message issued after DHCP_DDNS attempts to submit DNS mapping
 entry removals have failed.  The precise reason for the failure should be
 documented in preceding log entries.

src/bin/d2/nc_add.cc

@@ -539,7 +539,7 @@ void
 NameAddTransaction::processAddOkHandler() {
     switch(getNextEvent()) {
     case UPDATE_OK_EVT:
-        LOG_DEBUG(dctl_logger, DBGLVL_TRACE_DETAIL, DHCP_DDNS_ADD_SUCCEEDED)
+        LOG_INFO(dctl_logger, DHCP_DDNS_ADD_SUCCEEDED)
                   .arg(getNcr()->toText());
         setNcrStatus(dhcp_ddns::ST_COMPLETED);
         endModel();
@@ -556,9 +556,9 @@ NameAddTransaction::processAddFailedHandler() {
     switch(getNextEvent()) {
     case UPDATE_FAILED_EVT:
     case NO_MORE_SERVERS_EVT:
-        LOG_ERROR(dctl_logger, DHCP_DDNS_ADD_FAILED).arg(getNcr()->toText())
-        .arg(getEventLabel(getNextEvent()));
         setNcrStatus(dhcp_ddns::ST_FAILED);
+        LOG_ERROR(dctl_logger, DHCP_DDNS_ADD_FAILED)
+                  .arg(transactionOutcomeString());
         endModel();
         break;
     default:

src/bin/d2/nc_remove.cc

@@ -547,8 +547,8 @@ void
 NameRemoveTransaction::processRemoveOkHandler() {
     switch(getNextEvent()) {
     case UPDATE_OK_EVT:
-        LOG_DEBUG(dctl_logger, DBGLVL_TRACE_DETAIL, DHCP_DDNS_REMOVE_SUCCEEDED)
-                  .arg(getNcr()->toText());
+        LOG_INFO(dctl_logger, DHCP_DDNS_REMOVE_SUCCEEDED)
+                .arg(getNcr()->toText());
         setNcrStatus(dhcp_ddns::ST_COMPLETED);
         endModel();
         break;
@@ -565,9 +565,9 @@ NameRemoveTransaction::processRemoveFailedHandler() {
     case UPDATE_FAILED_EVT:
     case NO_MORE_SERVERS_EVT:
     case SERVER_IO_ERROR_EVT:
-        LOG_ERROR(dctl_logger, DHCP_DDNS_REMOVE_FAILED).arg(getNcr()->toText())
-        .arg(getEventLabel(getNextEvent()));
         setNcrStatus(dhcp_ddns::ST_FAILED);
+        LOG_ERROR(dctl_logger, DHCP_DDNS_REMOVE_FAILED)
+                  .arg(transactionOutcomeString());
         endModel();
         break;
     default:

src/bin/d2/nc_trans.cc

@@ -107,7 +107,7 @@ NameChangeTransaction::operator()(DNSClient::Status status) {
 }
 
 std::string
-NameChangeTransaction::responseString() {
+NameChangeTransaction::responseString() const {
     std::ostringstream stream;
     switch (getDnsUpdateStatus()) {
         case DNSClient::SUCCESS:
@@ -140,6 +140,28 @@ NameChangeTransaction::responseString() {
     return (stream.str());
 }
 
+std::string
+NameChangeTransaction::transactionOutcomeString() const {
+    std::ostringstream stream;
+    stream << "Status: " << (getNcrStatus() == dhcp_ddns::ST_COMPLETED
+                             ? "Completed, " : "Failed, ")
+           << "Event: " << getEventLabel(getNextEvent()) << ", ";
+
+    if (ncr_->isForwardChange()) {
+        stream << " Forward change:" << (getForwardChangeCompleted()
+                                         ? " completed, " : " failed, ");
+    }
+
+    if (ncr_->isReverseChange()) {
+        stream << " Reverse change:" << (getReverseChangeCompleted()
+                                          ? " completed, " : " failed, ");
+    }
+
+    stream << " request: " << ncr_->toText();
+    return (stream.str());
+}
+
+
 void
 NameChangeTransaction::sendUpdate(const std::string& comment,
                                   bool /* use_tsig_ */) {

src/bin/d2/nc_trans.h

@@ -409,7 +409,17 @@ protected:
     /// and RCODE (if status is DNSClient::SUCCESS)
     ///
     /// @return std::string containing constructed text
-    std::string responseString();
+    std::string responseString() const;
+
+    /// @brief Returns a string version of transaction outcome.
+    ///
+    /// Renders a string containing summarizes the outcome of the
+    /// transaction. The information includes the overall status,
+    /// the last event, whether not forward and reverse changes were
+    /// done, as well as the NCR serviced.
+    ///
+    /// @return std::string containing constructed text
+    std::string transactionOutcomeString() const;
 
 public:
     /// @brief Fetches the NameChangeRequest for this transaction.

src/bin/d2/tests/nc_trans_unittests.cc

@@ -262,6 +262,8 @@ public:
     using NameChangeTransaction::addLeaseAddressRdata;
     using NameChangeTransaction::addDhcidRdata;
     using NameChangeTransaction::addPtrRdata;
+    using NameChangeTransaction::responseString;
+    using NameChangeTransaction::transactionOutcomeString;
 };
 
 // Declare them so Gtest can see them.
@@ -507,8 +509,87 @@ TEST_F(NameChangeTransactionTest, dnsUpdateResponseAccessors) {
 
     // Should be empty again.
     EXPECT_FALSE(name_change->getDnsUpdateResponse());
+
+}
+
+/// @brief Tests responseString method.
+TEST_F(NameChangeTransactionTest, responseString) {
+    // Create a transaction.
+    NameChangeStubPtr name_change;
+    ASSERT_NO_THROW(name_change = makeCannedTransaction());
+
+    // Make sure it is safe to call when status says success but there
+    // is no update response.
+    ASSERT_NO_THROW(name_change->setDnsUpdateStatus(DNSClient::SUCCESS));
+    EXPECT_EQ("SUCCESS, rcode:  update response is NULL",
+              name_change->responseString());
+
+    // Create a response. (We use an OUTBOUND message so we can set RCODE)
+    D2UpdateMessagePtr resp;
+    ASSERT_NO_THROW(resp.reset(new D2UpdateMessage(D2UpdateMessage::OUTBOUND)));
+    ASSERT_NO_THROW(name_change->setDnsUpdateResponse(resp));
+
+    // Make sure we decode Rcode when status is successful.
+    ASSERT_NO_THROW(resp->setRcode(dns::Rcode::NXDOMAIN()));
+    EXPECT_EQ("SUCCESS, rcode: NXDOMAIN", name_change->responseString());
+
+    // Test all of the non-success values for status.
+    ASSERT_NO_THROW(name_change->setDnsUpdateStatus(DNSClient::TIMEOUT));
+    EXPECT_EQ("TIMEOUT", name_change->responseString());
+
+    ASSERT_NO_THROW(name_change->setDnsUpdateStatus(DNSClient::IO_STOPPED));
+    EXPECT_EQ("IO_STOPPED", name_change->responseString());
+
+    ASSERT_NO_THROW(name_change->setDnsUpdateStatus(DNSClient::
+                                                    INVALID_RESPONSE));
+    EXPECT_EQ("INVALID_RESPONSE", name_change->responseString());
+
+    ASSERT_NO_THROW(name_change->setDnsUpdateStatus(DNSClient::OTHER));
+    EXPECT_EQ("OTHER", name_change->responseString());
 }
 
+/// @brief Tests transactionOutcomeString method.
+TEST_F(NameChangeTransactionTest, transactionOutcomeString) {
+    // Create a transaction.
+    NameChangeStubPtr name_change;
+    dhcp_ddns::NameChangeRequestPtr ncr;
+    ASSERT_NO_THROW(name_change = makeCannedTransaction());
+    ncr = name_change->getNcr();
+
+    // Check case of failed transaction in both directions
+    std::string exp_str("Status: Failed, Event: UNDEFINED,  Forward change:"
+                        " failed,  Reverse change: failed,  request: ");
+    exp_str += ncr->toText();
+
+    std::string tstring = name_change->transactionOutcomeString();
+    std::cout << "tstring is: [" << tstring << "]" << std::endl;
+
+    EXPECT_EQ(exp_str, name_change->transactionOutcomeString());
+
+    // Check case of success all around
+    name_change->setNcrStatus(dhcp_ddns::ST_COMPLETED);
+    name_change->setForwardChangeCompleted(true);
+    name_change->setReverseChangeCompleted(true);
+
+    exp_str = "Status: Completed, Event: UNDEFINED,  Forward change: completed,"
+              "  Reverse change: completed,  request: " + ncr->toText();
+    EXPECT_EQ(exp_str, name_change->transactionOutcomeString());
+
+    // Check case of success, with no forward change
+    name_change->setNcrStatus(dhcp_ddns::ST_COMPLETED);
+    ncr->setForwardChange(false);
+    exp_str = "Status: Completed, Event: UNDEFINED, "
+              " Reverse change: completed,  request: " + ncr->toText();
+    EXPECT_EQ(exp_str, name_change->transactionOutcomeString());
+
+    // Check case of success, with no reverse change
+    name_change->setNcrStatus(dhcp_ddns::ST_COMPLETED);
+    ncr->setForwardChange(true);
+    ncr->setReverseChange(false);
+    exp_str = "Status: Completed, Event: UNDEFINED, "
+              " Forward change: completed,  request: " + ncr->toText();
+    EXPECT_EQ(exp_str, name_change->transactionOutcomeString());
+}
 
 /// @brief Tests event and state dictionary construction and verification.
 TEST_F(NameChangeTransactionTest, dictionaryCheck) {

src/bin/dhcp6/dhcp6_srv.cc

@@ -1081,12 +1081,13 @@ Dhcpv6Srv::createNameChangeRequests(const Pkt6Ptr& answer) {
                                         true, opt_fqdn->getDomainName(),
                                         iaaddr->getAddress().toText(),
                                         dhcid, 0, iaaddr->getValid()));
-        // Post the NCR to the D2ClientMgr.
-        CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
 
         LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL,
                   DHCP6_DDNS_CREATE_ADD_NAME_CHANGE_REQUEST).arg(ncr->toText());
 
+        // Post the NCR to the D2ClientMgr.
+        CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
+
         /// @todo Currently we create NCR with the first IPv6 address that
         /// is carried in one of the IA_NAs. In the future, the NCR API should
         /// be extended to map multiple IPv6 addresses to a single FQDN.
@@ -1142,11 +1143,12 @@ Dhcpv6Srv::createRemovalNameChangeRequest(const Lease6Ptr& lease) {
                                     lease->hostname_,
                                     lease->addr_.toText(),
                                     dhcid, 0, lease->valid_lft_));
-    CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
 
     LOG_DEBUG(dhcp6_logger, DBG_DHCP6_DETAIL,
               DHCP6_DDNS_CREATE_REMOVE_NAME_CHANGE_REQUEST).arg(ncr->toText());
 
+    // Post the NCR to the D2ClientMgr.
+    CfgMgr::instance().getD2ClientMgr().sendRequest(ncr);
 }
 
 OptionPtr