BIND 10 master, updated. 031eaf1e2378242b5ebd2804347cba5843408eab Merge #1944

BIND 10 source code commits bind10-changes at lists.isc.org
Wed May 30 08:38:44 UTC 2012


The branch, master has been updated
       via  031eaf1e2378242b5ebd2804347cba5843408eab (commit)
       via  b128daebb970c0b09680e1d1c485af8dcfc4ab55 (commit)
       via  b94f49bf264e058dac14287eca360c82edb0071d (commit)
       via  f77a1e4539afd8dea0a1db15d46d85b810c5c4ee (commit)
       via  eacdcb4322f7fc89f35af526768bf42403ad09a6 (commit)
      from  00d06904569e27ba56975b60906022585a43ab4e (commit)

Those revisions listed above that are new to this repository have
not appeared on any other notification email; so we list those
revisions in full, below.

- Log -----------------------------------------------------------------
commit 031eaf1e2378242b5ebd2804347cba5843408eab
Merge: 00d0690 b128dae
Author: Michal 'vorner' Vaner <michal.vaner at nic.cz>
Date:   Wed May 30 10:14:53 2012 +0200

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

-----------------------------------------------------------------------

Summary of changes:
 src/lib/datasrc/database.cc                 |   27 +++++++++++++++++------
 src/lib/datasrc/datasrc_messages.mes        |   11 ++++++----
 src/lib/log/log_formatter.cc                |    7 ++++++
 src/lib/log/log_formatter.h                 |   31 +++++++++++++++++++++++++--
 src/lib/log/tests/log_formatter_unittest.cc |   21 +++++++++++-------
 src/lib/python/isc/log/log.cc               |   10 +++++++--
 6 files changed, 85 insertions(+), 22 deletions(-)

-----------------------------------------------------------------------
diff --git a/src/lib/datasrc/database.cc b/src/lib/datasrc/database.cc
index 7b271f1..62fa61e 100644
--- a/src/lib/datasrc/database.cc
+++ b/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
diff --git a/src/lib/datasrc/datasrc_messages.mes b/src/lib/datasrc/datasrc_messages.mes
index a9870d6..7e3d5c2 100644
--- a/src/lib/datasrc/datasrc_messages.mes
+++ b/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.
diff --git a/src/lib/log/log_formatter.cc b/src/lib/log/log_formatter.cc
index c728cb5..9cd5cc7 100644
--- a/src/lib/log/log_formatter.cc
+++ b/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@@");
diff --git a/src/lib/log/log_formatter.h b/src/lib/log/log_formatter.h
index fc60203..eebdb1a 100644
--- a/src/lib/log/log_formatter.h
+++ b/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;
+        }
+    }
 };
 
 }
diff --git a/src/lib/log/tests/log_formatter_unittest.cc b/src/lib/log/tests/log_formatter_unittest.cc
index 83fc062..435b200 100644
--- a/src/lib/log/tests/log_formatter_unittest.cc
+++ b/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
diff --git a/src/lib/python/isc/log/log.cc b/src/lib/python/isc/log/log.cc
index ed05398..69e70b7 100644
--- a/src/lib/python/isc/log/log.cc
+++ b/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;
     }



More information about the bind10-changes mailing list