[1892] Conditionally throw an exception if logger placeholders are not matched

configure.ac

@@ -977,6 +977,11 @@ AC_ARG_ENABLE(install-configurations,
 
 AM_CONDITIONAL(INSTALL_CONFIGURATIONS, test x$install_configurations = xyes || test x$install_configurations = xtrue)
 
+AC_ARG_ENABLE(logger-checks, [AC_HELP_STRING([--enable-logger-checks],
+  [check logger messages [default=no]])], enable_logger_checks=$enableval, enable_logger_checks=no)
+AM_CONDITIONAL(ENABLE_LOGGER_CHECKS, test x$enable_logger_checks != xno)
+AM_COND_IF([ENABLE_LOGGER_CHECKS], [AC_DEFINE([ENABLE_LOGGER_CHECKS], [1], [Check logger messages?])])
+
 AC_CONFIG_FILES([Makefile
                  doc/Makefile
                  doc/guide/Makefile

src/lib/log/log_formatter.cc

@@ -12,6 +12,7 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
+#include "config.h"
 #include <log/log_formatter.h>
 
 using namespace std;
@@ -31,11 +32,28 @@ replacePlaceholder(string* message, const string& arg,
             message->replace(pos, mark.size(), arg);
             pos = message->find(mark, pos + arg.size());
         } while (pos != string::npos);
-    } else {
-        // We're missing the placeholder, so add some complain
-        message->append(" @@Missing placeholder " + mark + " for '" + arg +
-                        "'@@");
     }
+#ifdef ENABLE_LOGGER_CHECKS
+    else {
+        // We're missing the placeholder, so throw an exception
+        isc_throw(MismatchedPlaceholders,
+		  "Missing logger placeholder in message: " << message);
+    }
+#endif /* ENABLE_LOGGER_CHECKS */
+}
+
+void
+checkExcessPlaceholders(string* message, unsigned int placeholder)
+{
+#ifdef ENABLE_LOGGER_CHECKS
+    string mark("%" + lexical_cast<string>(placeholder));
+    size_t pos(message->find(mark));
+    if (pos != string::npos) {
+        // Excess placeholders were found, so throw an exception
+        isc_throw(MismatchedPlaceholders,
+		  "Excess logger placeholders still exist in message: " << message);
+    }
+#endif /* ENABLE_LOGGER_CHECKS */
 }
 
 }

src/lib/log/log_formatter.h

@@ -39,6 +39,27 @@ public:
 };
 
 
+/// \brief Mismatched Placeholders
+///
+/// This exception is used when the number of placeholders do not match
+/// the number of arguments passed to the formatter.
+
+class MismatchedPlaceholders : public isc::Exception {
+public:
+    MismatchedPlaceholders(const char* file, size_t line, const char* what) :
+        isc::Exception(file, line, what)
+    {}
+};
+
+
+///
+/// \brief Internal excess placeholder checker
+///
+/// This is used internally by the Formatter to check for excess
+/// placeholders (and fewer arguments).
+void
+checkExcessPlaceholders(std::string* message, unsigned int placeholder);
+
 ///
 /// \brief The internal replacement routine
 ///
@@ -142,6 +163,7 @@ public:
     /// This is the place where output happens if the formatter is active.
     ~ Formatter() {
         if (logger_) {
+            checkExcessPlaceholders(message_, ++nextPlaceholder_);
             logger_->output(severity_, *message_);
             delete message_;
         }

src/lib/log/tests/log_formatter_unittest.cc

@@ -12,6 +12,7 @@
 // OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 // PERFORMANCE OF THIS SOFTWARE.
 
+#include "config.h"
 #include <gtest/gtest.h>
 #include <log/log_formatter.h>
 #include <log/logger_level.h>
@@ -94,16 +95,41 @@ TEST_F(FormatterTest, multiArg) {
     EXPECT_EQ("The arguments are switched", outputs[0].second);
 }
 
-// Can survive and complains if placeholder is missing
-TEST_F(FormatterTest, missingPlace) {
+#ifdef ENABLE_LOGGER_CHECKS
+
+#ifdef EXPECT_ABORT
+// Throws MismatchedPlaceholders exception if number of placeholders
+// don't match number of arguments. This causes it to abort.
+TEST_F(FormatterTest, mismatchedPlaceholders) {
+    EXPECT_ABORT({
+        Formatter(isc::log::INFO, s("Missing the first %2"), this).arg("missing").arg("argument");
+    }, ".*");
+
+    EXPECT_ABORT({
+	Formatter(isc::log::INFO, s("Too many arguments in %1 %2"), this).arg("only one");
+    }, ".*");
+}
+#endif /* EXPECT_ABORT */
+
+#else
+
+// If logger checks are not enabled, nothing is thrown
+TEST_F(FormatterTest, mismatchedPlaceholders) {
     EXPECT_NO_THROW(Formatter(isc::log::INFO, s("Missing the first %2"), this).
                     arg("missing").arg("argument"));
     ASSERT_EQ(1, outputs.size());
     EXPECT_EQ(isc::log::INFO, outputs[0].first);
-    EXPECT_EQ("Missing the first argument "
-              "@@Missing placeholder %1 for 'missing'@@", outputs[0].second);
+    EXPECT_EQ("Missing the first argument", outputs[0].second);
+
+    EXPECT_NO_THROW(Formatter(isc::log::INFO, s("Too many arguments in %1 %2"), this).
+                    arg("only one"));
+    ASSERT_EQ(2, outputs.size());
+    EXPECT_EQ(isc::log::INFO, outputs[1].first);
+    EXPECT_EQ("Too many arguments in only one %2", outputs[1].second);
 }
 
+#endif /* ENABLE_LOGGER_CHECKS */
+
 // Can replace multiple placeholders
 TEST_F(FormatterTest, multiPlaceholder) {
     Formatter(isc::log::INFO, s("The %1 is the %1"), this).

src/lib/log/tests/logger_manager_unittest.cc

@@ -296,7 +296,7 @@ TEST_F(LoggerManagerTest, FileSizeRollover) {
     manager.process(spec);
     {
         Logger logger(file_spec.getLoggerName().c_str());
-        LOG_FATAL(logger, LOG_NO_MESSAGE_TEXT).arg(big_arg);
+        LOG_FATAL(logger, LOG_NO_MESSAGE_TEXT).arg("42").arg(big_arg);
     }
 
     LoggerManager::reset();     // Ensure files are closed

src/lib/log/tests/logger_support_unittest.cc

@@ -79,5 +79,5 @@ TEST_F(LoggerSupportTest, LoggingInitializationCheck) {
     // ... and check that they work when logging is initialized.
     setLoggingInitialized(true);
     EXPECT_NO_THROW(test_logger.isDebugEnabled());
-    EXPECT_NO_THROW(test_logger.info(LOG_INPUT_OPEN_FAIL));
+    EXPECT_NO_THROW(test_logger.info(LOG_INPUT_OPEN_FAIL).arg("foo").arg("bar"));
 }