[trac756] The actual logging output

configure.ac

@@ -884,6 +884,7 @@ AC_OUTPUT([doc/version.ent
            src/lib/python/isc/config/tests/config_test
            src/lib/python/isc/cc/tests/cc_test
            src/lib/python/isc/notify/tests/notify_out_test
+           src/lib/python/isc/log/tests/log_console.py
            src/lib/dns/gen-rdatacode.py
            src/lib/python/bind10_config.py
            src/lib/dns/tests/testdata/gen-wiredata.py
@@ -923,6 +924,7 @@ AC_OUTPUT([doc/version.ent
            chmod +x src/lib/log/tests/console_test.sh
            chmod +x src/lib/log/tests/severity_test.sh
            chmod +x src/lib/util/python/mkpywrapper.py
+           chmod +x src/lib/python/isc/log/tests/log_console.py
            chmod +x tests/system/conf.sh
           ])
 AC_OUTPUT

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

@@ -22,7 +22,12 @@
 #include <log/logger_manager.h>
 #include <log/logger.h>
 
+#include <string>
+#include <boost/bind.hpp>
+
 using namespace isc::log;
+using std::string;
+using boost::bind;
 
 namespace {
 
@@ -358,6 +363,143 @@ Logger_isDebugEnabled(LoggerWrapper* self, PyObject* args) {
     }
 }
 
+// To propagate python exceptions trough our code
+class InternalError {};
+
+string
+objectToStr(PyObject* object, bool convert) {
+    PyObject* cleanup(NULL);
+    if (convert) {
+        object = cleanup = PyObject_Str(object);
+        if (object == NULL) {
+            throw InternalError();
+        }
+    }
+    const char* value;
+    PyObject* tuple(Py_BuildValue("(O)", object));
+    if (tuple == NULL) {
+        if (cleanup != NULL) {
+            Py_DECREF(cleanup);
+        }
+        throw InternalError();
+    }
+
+    if (!PyArg_ParseTuple(tuple, "s", &value)) {
+        Py_DECREF(tuple);
+        if (cleanup != NULL) {
+            Py_DECREF(cleanup);
+        }
+        throw InternalError();
+    }
+    string result(value);
+    Py_DECREF(tuple);
+    if (cleanup != NULL) {
+        Py_DECREF(cleanup);
+    }
+    return (result);
+}
+
+// Generic function to output the logging message. Called by the real functions.
+template<class Function>
+PyObject*
+Logger_performOutput(Function function, PyObject* args, bool dbgLevel) {
+    try {
+        Py_ssize_t number(PyObject_Length(args));
+        if (number < 0) {
+            return (NULL);
+        }
+
+        // Which argument is the first to format?
+        size_t start(1);
+        if (dbgLevel) {
+            start ++;
+        }
+
+        if (number < start) {
+            return (PyErr_Format(PyExc_TypeError, "Too few arguments to "
+                                 "logging call, at last %zu needed and %zd "
+                                 "given", start, number));
+        }
+
+        // Extract the fixed arguments
+        PyObject *midO(PySequence_GetItem(args, start - 1));
+        if (midO == NULL) {
+            return (NULL);
+        }
+        string mid(objectToStr(midO, false));
+        long dbg(0);
+        if (dbgLevel) {
+            PyObject *dbgO(PySequence_GetItem(args, 0));
+            if (dbgO == NULL) {
+                return (NULL);
+            }
+            dbg = PyLong_AsLong(dbgO);
+            if (PyErr_Occurred()) {
+                return (NULL);
+            }
+        }
+
+        // We create the logging message right now. If we fail to convert a
+        // parameter to string, at last the part that we already did will
+        // be output
+        Logger::Formatter formatter(function(dbg, mid.c_str()));
+
+        // Now process the rest of parameters, convert each to string and put
+        // into the formatter. It will print itself in the end.
+        for (size_t i(start); i < number; ++ i) {
+            PyObject* param(PySequence_GetItem(args, i));
+            if (param == NULL) {
+                return (NULL);
+            }
+            formatter = formatter.arg(objectToStr(param, true));
+        }
+        Py_RETURN_NONE;
+    }
+    catch (const InternalError&) {
+        return (NULL);
+    }
+    catch (const std::exception& e) {
+        PyErr_SetString(PyExc_RuntimeError, e.what());
+        return (NULL);
+    }
+    catch (...) {
+        PyErr_SetString(PyExc_RuntimeError, "Unknown C++ exception");
+        return (NULL);
+    }
+}
+
+// Now map the functions into the performOutput. I wish C++ could do
+// functional programming.
+PyObject*
+Logger_debug(LoggerWrapper* self, PyObject* args) {
+    return (Logger_performOutput(bind(&Logger::debug, self->logger_, _1, _2),
+                                 args, true));
+}
+
+PyObject*
+Logger_info(LoggerWrapper* self, PyObject* args) {
+    return (Logger_performOutput(bind(&Logger::info, self->logger_, _2),
+                                 args, false));
+}
+
+PyObject*
+Logger_warn(LoggerWrapper* self, PyObject* args) {
+    return (Logger_performOutput(bind(&Logger::warn, self->logger_, _2),
+                                 args, false));
+}
+
+PyObject*
+Logger_error(LoggerWrapper* self, PyObject* args) {
+    return (Logger_performOutput(bind(&Logger::error, self->logger_, _2),
+                                 args, false));
+}
+
+PyObject*
+Logger_fatal(LoggerWrapper* self, PyObject* args) {
+    return (Logger_performOutput(bind(&Logger::fatal, self->logger_, _2),
+                                 args, false));
+}
+
 PyMethodDef loggerMethods[] = {
     { "get_effective_severity",
         reinterpret_cast<PyCFunction>(Logger_getEffectiveSeverity),
@@ -369,11 +511,10 @@ PyMethodDef loggerMethods[] = {
         "Sets the severity of a logger. The parameters are severity as a "
         "string and, optionally, a debug level (integer in range 0-99). "
         "The severity may be NULL, in which case an inherited value is taken."
-        },
+    },
     { "is_debug_enabled", reinterpret_cast<PyCFunction>(Logger_isDebugEnabled),
         METH_VARARGS, "Returns if the logger would log debug message now. "
-            "You can provide a desired debug level."
-    },
+            "You can provide a desired debug level." },
     { "is_info_enabled", reinterpret_cast<PyCFunction>(Logger_isInfoEnabled),
         METH_NOARGS, "Returns if the logger would log info message now." },
     { "is_warn_enabled", reinterpret_cast<PyCFunction>(Logger_isWarnEnabled),
@@ -382,6 +523,21 @@ PyMethodDef loggerMethods[] = {
         METH_NOARGS, "Returns if the logger would log error message now." },
     { "is_fatal_enabled", reinterpret_cast<PyCFunction>(Logger_isFatalEnabled),
         METH_NOARGS, "Returns if the logger would log fatal message now." },
+    { "debug", reinterpret_cast<PyCFunction>(Logger_debug), METH_VARARGS,
+        "Logs a debug-severity message. It takes the debug level, message ID "
+        "and any number of stringifiable arguments to the message." },
+    { "info", reinterpret_cast<PyCFunction>(Logger_info), METH_VARARGS,
+        "Logs a info-severity message. It taskes the message ID and any "
+        "number of stringifiable arguments to the message." },
+    { "warn", reinterpret_cast<PyCFunction>(Logger_warn), METH_VARARGS,
+        "Logs a warn-severity message. It taskes the message ID and any "
+        "number of stringifiable arguments to the message." },
+    { "error", reinterpret_cast<PyCFunction>(Logger_error), METH_VARARGS,
+        "Logs a error-severity message. It taskes the message ID and any "
+        "number of stringifiable arguments to the message." },
+    { "fatal", reinterpret_cast<PyCFunction>(Logger_fatal), METH_VARARGS,
+        "Logs a fatal-severity message. It taskes the message ID and any "
+        "number of stringifiable arguments to the message." },
     { NULL, NULL, 0, NULL }
 };
 

src/lib/python/isc/log/tests/Makefile.am

 PYCOVERAGE_RUN = @PYCOVERAGE_RUN@
 PYTESTS = log_test.py
-EXTRA_DIST = $(PYTESTS)
+EXTRA_DIST = $(PYTESTS) log_console.py.in console.out check_output.sh
 
 # test using command-line arguments, so use check-local target instead of TESTS
 check-local:
+	env PYTHONPATH=$(abs_top_srcdir)/src/lib/python:$(abs_top_builddir)/src/lib/python:$(abs_top_builddir)/src/lib/python/isc/log \
+	$(abs_srcdir)/check_output.sh $(abs_builddir)/log_console.py $(abs_srcdir)/console.out
 if ENABLE_PYTHON_COVERAGE
 	touch $(abs_top_srcdir)/.coverage
 	rm -f .coverage

src/lib/python/isc/log/tests/check_output.sh

+#!/bin/sh
+
+"$1" 2>&1 | cut -d\  -f3- | diff - "$2" 1>&2

src/lib/python/isc/log/tests/console.out

+INFO  [test.output] MSG_ID, Message with list [1, 2, 3, 4]
+WARN  [test.output] DIFFERENT, Different message
+FATAL [test.output] MSG_ID, Message with 2 1
+DEBUG [test.output] MSG_ID, Message with 3 2

src/lib/python/isc/log/tests/log_console.py.in

+#!@PYTHON@
+
+import isc.log
+# This would come from a dictionary in real life
+MSG_ID = isc.log.create_message("MSG_ID", "Message with %2 %1")
+DIFFERENT = isc.log.create_message("DIFFERENT", "Different message")
+isc.log.init("test")
+logger = isc.log.Logger("output")
+
+logger.debug(20, MSG_ID, "test", "no output")
+logger.info(MSG_ID, [1, 2, 3, 4], "list")
+logger.warn(DIFFERENT)
+logger.fatal(MSG_ID, 1, 2)
+logger.setSeverity("DEBUG", 99)
+logger.debug(1, MSG_ID, 2, 3)

src/lib/python/isc/log/tests/log_test.py

@@ -110,5 +110,28 @@ class Logger(unittest.TestCase):
         self.assertTrue(logger.is_debug_enabled(50))
         self.assertFalse(logger.is_debug_enabled(99))
 
+    def test_invalid_params(self):
+        """
+           Tests invalid arguments for logging functions. The output is tested
+           in check_output.sh.
+        """
+        logger = isc.log.Logger("child")
+        methods = [
+            logger.info,
+            logger.warn,
+            logger.error,
+            logger.fatal
+        ]
+        for meth in methods:
+            # Not enough arguments
+            self.assertRaises(TypeError, meth)
+            # Bad type
+            self.assertRaises(TypeError, meth, 1)
+        # Too few arguments
+        self.assertRaises(TypeError, logger.debug, 42)
+        self.assertRaises(TypeError, logger.debug)
+        # Bad type
+        self.assertRaises(TypeError, logger.debug, "42", "hello")
+
 if __name__ == '__main__':
     unittest.main()