Merge #1944

This fixes the logging placeholders in messages to really match what is logged.

src/lib/datasrc/database.cc

@@ -839,8 +839,6 @@ DatabaseClient::Finder::findOnNameResult(const Name& name,
                                    flags));
     } else if (wti != found.second.end()) {
         bool any(type == RRType::ANY());
-        isc::log::MessageID lid(wild ? DATASRC_DATABASE_WILDCARD_MATCH :
-                                DATASRC_DATABASE_FOUND_RRSET);
         if (any) {
             // An ANY query, copy everything to the target instead of returning
             // directly.
@@ -851,15 +849,32 @@ DatabaseClient::Finder::findOnNameResult(const Name& name,
                     target->push_back(it->second);
                 }
             }
-            lid = wild ? DATASRC_DATABASE_WILDCARD_ANY :
-                DATASRC_DATABASE_FOUND_ANY;
+            if (wild) {
+                LOG_DEBUG(logger, DBG_TRACE_DETAILED,
+                          DATASRC_DATABASE_WILDCARD_ANY).
+                    arg(accessor_->getDBName()).arg(name);
+            } else {
+                LOG_DEBUG(logger, DBG_TRACE_DETAILED,
+                          DATASRC_DATABASE_FOUND_ANY).
+                    arg(accessor_->getDBName()).arg(name);
+            }
+        } else {
+            if (wild) {
+                LOG_DEBUG(logger, DBG_TRACE_DETAILED,
+                          DATASRC_DATABASE_WILDCARD_MATCH).
+                    arg(accessor_->getDBName()).arg(*wildname).
+                    arg(wti->second);
+            } else {
+                LOG_DEBUG(logger, DBG_TRACE_DETAILED,
+                          DATASRC_DATABASE_FOUND_RRSET).
+                    arg(accessor_->getDBName()).arg(wti->second);
+            }
         }
         // Found an RR matching the query, so return it.  (Note that this
         // includes the case where we were explicitly querying for a CNAME and
         // found it.  It also includes the case where we were querying for an
         // NS RRset and found it at the apex of the zone.)
-        return (logAndCreateResult(name, wildname, type, SUCCESS,
-                                   wti->second, lid, flags));
+        return (ResultContext(SUCCESS, wti->second, flags));
     }
 
     // If we get here, we have found something at the requested name but not

src/lib/datasrc/datasrc_messages.mes

@@ -79,9 +79,12 @@ in the answer as a result.
 Debug information. A search in an database data source for NSEC3 that
 matches or covers the given name is being started.
 
-% DATASRC_DATABASE_FINDNSEC3_COVER found a covering NSEC3 for %1: %2
+% DATASRC_DATABASE_FINDNSEC3_COVER found a covering NSEC3 for %1 at label count %2: %3
 Debug information. An NSEC3 that covers the given name is found and
-being returned.  The found NSEC3 RRset is also displayed.
+being returned.  The found NSEC3 RRset is also displayed. When the shown label
+count is smaller than that of the given name, the matching NSEC3 is for a
+superdomain of the given name (see DATASRC_DATABSE_FINDNSEC3_TRYHASH).  The
+found NSEC3 RRset is also displayed.
 
 % DATASRC_DATABASE_FINDNSEC3_MATCH found a matching NSEC3 for %1 at label count %2: %3
 Debug information. An NSEC3 that matches (a possibly superdomain of)
@@ -157,7 +160,7 @@ A search in the database for RRs for the specified name, type and class has
 located RRs that match the name and class but not the type.  DNSSEC information
 has been requested and returned.
 
-% DATASRC_DATABASE_FOUND_RRSET search in datasource %1 resulted in RRset %5
+% DATASRC_DATABASE_FOUND_RRSET search in datasource %1 resulted in RRset %2
 The data returned by the database backend contained data for the given domain
 name, and it either matches the type or has a relevant type. The RRset that is
 returned is printed.
@@ -276,7 +279,7 @@ nonterminal (e.g. there's nothing at *.example.com but something like
 subdomain.*.example.org, do exist: so *.example.org exists in the
 namespace but has no RRs assopciated with it). This will produce NXRRSET.
 
-% DATASRC_DATABASE_WILDCARD_MATCH search in datasource %1 resulted in wildcard match at %5 with RRset %6
+% DATASRC_DATABASE_WILDCARD_MATCH search in datasource %1 resulted in wildcard match at %2 with RRset %3
 The database doesn't contain directly matching name.  When searching
 for a wildcard match, a wildcard record matching the name and type of
 the query was found. The data at this point is returned.

src/lib/log/log_formatter.cc

@@ -17,6 +17,10 @@
 
 #include <cassert>
 
+#ifdef ENABLE_LOGGER_CHECKS
+#include <iostream>
+#endif
+
 using namespace std;
 using namespace boost;
 
@@ -59,6 +63,9 @@ checkExcessPlaceholders(string* message, unsigned int placeholder) {
         // but we can't at least for now because this function is called from
         // the Formatter's destructor.
 #ifdef ENABLE_LOGGER_CHECKS
+        // Also, make sure we print the message so we can identify which
+        // identifier has the problem.
+        cerr << "Message " << *message << endl;
         assert("Excess logger placeholders still exist in message" == NULL);
 #else
         message->append(" @@Excess logger placeholders still exist@@");

src/lib/log/log_formatter.h

@@ -197,7 +197,9 @@ public:
             try {
                 return (arg(boost::lexical_cast<std::string>(value)));
             } catch (const boost::bad_lexical_cast& ex) {
-
+                // The formatting of the log message got wrong, we don't want
+                // to output it.
+                deactivate();
                 // A bad_lexical_cast during a conversion to a string is
                 // *extremely* unlikely to fail.  However, there is nothing
                 // in the documentation that rules it out, so we need to handle
@@ -229,10 +231,35 @@ public:
             // occurrences of "%2" with 42. (Conversely, the sequence
             // .arg(42).arg("%1") would return "42 %1" - there are no recursive
             // replacements).
-            replacePlaceholder(message_, arg, ++nextPlaceholder_ );
+            try {
+                replacePlaceholder(message_, arg, ++nextPlaceholder_ );
+            }
+            catch (...) {
+                // Something went wrong here, the log message is broken, so
+                // we don't want to output it, nor we want to check all the
+                // placeholders were used (because they won't be).
+                deactivate();
+                throw;
+            }
         }
         return (*this);
     }
+
+    /// \brief Turn off the output of this logger.
+    ///
+    /// If the logger would output anything at the end, now it won't.
+    /// Also, this turns off the strict checking of placeholders, if
+    /// it is compiled in.
+    ///
+    /// The expected use is when there was an exception processing
+    /// the arguments for the message.
+    void deactivate() {
+        if (logger_) {
+            delete message_;
+            message_ = NULL;
+            logger_ = NULL;
+        }
+    }
 };
 
 }

src/lib/log/tests/log_formatter_unittest.cc

@@ -81,6 +81,14 @@ TEST_F(FormatterTest, stringArg) {
     }
 }
 
+// Test the .deactivate() method
+TEST_F(FormatterTest, deactivate) {
+    Formatter(isc::log::INFO, s("Text of message"), this).deactivate();
+    // If there was no .deactivate, it should have output it.
+    // But not now.
+    ASSERT_EQ(0, outputs.size());
+}
+
 // Can convert to string
 TEST_F(FormatterTest, intArg) {
     Formatter(isc::log::INFO, s("The answer is %1"), this).arg(42);
@@ -117,15 +125,12 @@ TEST_F(FormatterTest, mismatchedPlaceholders) {
             arg("only one");
     }, ".*");
 
-    // Mixed case of above two: the exception will be thrown due to the missing
-    // placeholder, but before even it's caught the program will be aborted
-    // due to the unused placeholder as a result of the exception.
-    EXPECT_DEATH({
-        isc::util::unittests::dontCreateCoreDumps();
-        Formatter(isc::log::INFO, s("Missing the first %2"), this).
-            arg("missing").arg("argument");
-    }, ".*");
 #endif /* EXPECT_DEATH */
+    // Mixed case of above two: the exception will be thrown due to the missing
+    // placeholder. The other check is disabled due to that.
+    EXPECT_THROW(Formatter(isc::log::INFO, s("Missing the first %2"), this).
+                 arg("missing").arg("argument"),
+                 isc::log::MismatchedPlaceholders);
 }
 
 #else

src/lib/python/isc/log/log.cc

@@ -541,8 +541,14 @@ Logger_performOutput(Function function, PyObject* args, bool dbgLevel) {
         // into the formatter. It will print itself in the end.
         for (size_t i(start); i < number; ++ i) {
             PyObjectContainer param_container(PySequence_GetItem(args, i));
-            formatter = formatter.arg(objectToStr(param_container.get(),
-                                                  true));
+            try {
+                formatter = formatter.arg(objectToStr(param_container.get(),
+                                                      true));
+            }
+            catch (...) {
+                formatter.deactivate();
+                throw;
+            }
         }
         Py_RETURN_NONE;
     }