Add str.format variants of all log output methods

doc/mainpage.dox

@@ -50,7 +50,7 @@ A logger object may be retrieved and used to avoid the cost of excessive lookups
     subject = "important stuff"
     lsst.log.log("myLogger", lsst.log.INFO, "Here is some information about %s.", subject)
 
-
+    lsst.log.warnf("Possible problem {} using {name}", errcode, name=program)
     lsst.log.debug("My debugging statement.")
 
 
@@ -135,6 +135,15 @@ In Python, the following logging functions are available in the `lsst.log` modul
 - `error(fmt, *args)` Log a message of level `ERROR` with format string '''`fmt`''' and corresponding arguments '''`*args`''' to the default logger.
 - `fatal(fmt, *args)` Log a message of level `FATAL` with format string '''`fmt`''' and corresponding arguments '''`*args`''' to the default logger.
 
+Additionally, Python has variants of the above functions, with a trailing `f` in the name, supporting the Python string `format()` syntax. The use of `*args` and `**kwargs` is recommended over the use of the `format()` method directly so that formatting of log messages that do not meet the level threshold can be avoided.
+- `logf(loggername, level, fmt, *args, **kwargs)` Log a message of level '''`level`''' with format string '''`fmt`''' and variable arguments '''`*args`''' and '''`**kwargs`''' to the logger named '''`loggername`''' using format method syntax.
+- `tracef(fmt, *args, **kwargs)` Log a message of level `TRACE` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+- `debugf(fmt, *args, **kwargs)` Log a message of level `DEBUG` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+- `infof(fmt, *args, **kwargs)` Log a message of level `INFO` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+- `warnf(fmt, *args, **kwargs)` Log a message of level `WARN` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+- `errorf(fmt, *args, **kwargs)` Log a message of level `ERROR` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+- `fatalf(fmt, *args, **kwargs)` Log a message of level `FATAL` with format string '''`fmt`''' and corresponding arguments '''`*args`''' and '''`**kwargs`''' to the default logger using format method syntax.
+
 \section initialization Initialization
 
 The underlying log4cxx system can be initialized explicitly from either the C++ or Python layers or default-initialized.

python/lsst/log/log.py

@@ -81,31 +81,59 @@ def isEnabledFor(logger, level):
 
 
 def log(loggername, level, fmt, *args, **kwargs):
-    Log.getLogger(loggername)._log(level, fmt, *args)
+    Log.getLogger(loggername)._log(level, False, fmt, *args)
 
 
 def trace(fmt, *args):
-    Log.getDefaultLogger()._log(TRACE, fmt, *args)
+    Log.getDefaultLogger()._log(TRACE, False, fmt, *args)
 
 
 def debug(fmt, *args):
-    Log.getDefaultLogger()._log(DEBUG, fmt, *args)
+    Log.getDefaultLogger()._log(DEBUG, False, fmt, *args)
 
 
 def info(fmt, *args):
-    Log.getDefaultLogger()._log(INFO, fmt, *args)
+    Log.getDefaultLogger()._log(INFO, False, fmt, *args)
 
 
 def warn(fmt, *args):
-    Log.getDefaultLogger()._log(WARN, fmt, *args)
+    Log.getDefaultLogger()._log(WARN, False, fmt, *args)
 
 
 def error(fmt, *args):
-    Log.getDefaultLogger()._log(ERROR, fmt, *args)
+    Log.getDefaultLogger()._log(ERROR, False, fmt, *args)
 
 
 def fatal(fmt, *args):
-    Log.getDefaultLogger()._log(FATAL, fmt, *args)
+    Log.getDefaultLogger()._log(FATAL, False, fmt, *args)
+
+
+def logf(loggername, level, fmt, *args, **kwargs):
+    Log.getLogger(loggername)._log(level, True, fmt, *args, **kwargs)
+
+
+def tracef(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(TRACE, True, fmt, *args, **kwargs)
+
+
+def debugf(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(DEBUG, True, fmt, *args, **kwargs)
+
+
+def infof(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(INFO, True, fmt, *args, **kwargs)
+
+
+def warnf(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(WARN, True, fmt, *args, **kwargs)
+
+
+def errorf(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(ERROR, True, fmt, *args, **kwargs)
+
+
+def fatalf(fmt, *args, **kwargs):
+    Log.getDefaultLogger()._log(FATAL, True, fmt, *args, **kwargs)
 
 
 def lwpID():
@@ -172,8 +200,10 @@ def handle(self, record):
             logging.Handler.handle(self, record)
 
     def emit(self, record):
-        Log.getLogger(record.name).logMsg(self.translateLevel(record.levelno), record.filename,
-                                          record.funcName, record.lineno, record.msg % record.args)
+        Log.getLogger(record.name).logMsg(self.translateLevel(record.levelno),
+                                          record.filename, record.funcName,
+                                          record.lineno,
+                                          record.msg % record.args)
 
     def translateLevel(self, levelno):
         """

python/lsst/log/logLib.i

@@ -77,31 +77,51 @@ import os
     FATAL = 50000
 
     def trace(self, fmt, *args):
-        self._log(Log.TRACE, fmt, *args)
+        self._log(Log.TRACE, False, fmt, *args)
 
     def debug(self, fmt, *args):
-        self._log(Log.DEBUG, fmt, *args)
+        self._log(Log.DEBUG, False, fmt, *args)
 
     def info(self, fmt, *args):
-        self._log(Log.INFO, fmt, *args)
+        self._log(Log.INFO, False, fmt, *args)
 
     def warn(self, fmt, *args):
-        self._log(Log.WARN, fmt, *args)
+        self._log(Log.WARN, False, fmt, *args)
 
     def error(self, fmt, *args):
-        self._log(Log.ERROR, fmt, *args)
+        self._log(Log.ERROR, False, fmt, *args)
 
     def fatal(self, fmt, *args):
-        self._log(Log.FATAL, fmt, *args)
+        self._log(Log.FATAL, False, fmt, *args)
 
-    def _log(self, level, fmt, *args):
+    def tracef(self, fmt, *args, **kwargs):
+        self._log(Log.TRACE, True, fmt, *args, **kwargs)
+
+    def debugf(self, fmt, *args, **kwargs):
+        self._log(Log.DEBUG, True, fmt, *args, **kwargs)
+
+    def infof(self, fmt, *args, **kwargs):
+        self._log(Log.INFO, True, fmt, *args, **kwargs)
+
+    def warnf(self, fmt, *args, **kwargs):
+        self._log(Log.WARN, True, fmt, *args, **kwargs)
+
+    def errorf(self, fmt, *args, **kwargs):
+        self._log(Log.ERROR, True, fmt, *args, **kwargs)
+
+    def fatalf(self, fmt, *args, **kwargs):
+        self._log(Log.FATAL, True, fmt, *args, **kwargs)
+
+    def _log(self, level, use_format, fmt, *args, **kwargs):
         if self.isEnabledFor(level):
             frame = inspect.currentframe().f_back    # calling method
             frame = frame.f_back    # original log location
-            filename=os.path.split(frame.f_code.co_filename)[1]
-            funcname=inspect.stack()[2][3]
-            msg=fmt % args if args else fmt
+            filename = os.path.split(frame.f_code.co_filename)[1]
+            funcname = inspect.stack()[2][3]
+            if use_format:
+                msg = fmt.format(*args, **kwargs) if args or kwargs else fmt
+            else:
+                msg = fmt % args if args else fmt
             self.logMsg(level, filename, funcname, frame.f_lineno, msg)
     }
 }
-

tests/testLog.py

@@ -112,6 +112,35 @@ def testBasic(self):
 root ERROR: This is ERROR
 root FATAL: This is FATAL
 root WARN: Format 3 2.71828 foo
+""")
+
+    def testBasicFormat(self):
+        """
+        Test basic log output with default configuration but using
+        the f variants.
+        Since the default threshold is INFO, the DEBUG or TRACE
+        message is not emitted.
+        """
+        with TestLog.StdoutCapture(self.outputFilename):
+            log.configure()
+            log.logf(log.getDefaultLoggerName(), log.INFO,
+                     "This is {{INFO}} Item 1: {item[1]}",
+                     item=["a", "b", "c"])
+            log.infof(u"This is {unicode} INFO")
+            log.tracef("This is TRACE")
+            log.debugf("This is DEBUG")
+            log.warnf("This is WARN {city}", city="Tucson")
+            log.errorf("This is ERROR {1}->{0}", 2, 1)
+            log.fatalf("This is FATAL {1} out of {0} times for {place}",
+                       4, 3, place="LSST")
+            log.warnf("Format {} {} {}", 3, 2.71828, "foo")
+        self.check("""
+root INFO: This is {INFO} Item 1: b
+root INFO: This is {unicode} INFO
+root WARN: This is WARN Tucson
+root ERROR: This is ERROR 1->2
+root FATAL: This is FATAL 3 out of 4 times for LSST
+root WARN: Format 3 2.71828 foo
 """)
 
     def testContext(self):
@@ -135,7 +164,7 @@ def testContext(self):
                 log.debug("This is DEBUG 3")
                 ctx.setLevel(log.INFO)
                 self.assertEqual(ctx.getLevel(), log.INFO)
-                self.assert_(ctx.isEnabledFor(log.INFO))
+                self.assertTrue(ctx.isEnabledFor(log.INFO))
                 log.trace("This is TRACE 3a")
                 log.info("This is INFO 3a")
                 log.debug("This is DEBUG 3a")
@@ -216,7 +245,7 @@ def testPattern(self):
 DEBUG component  testPattern (testLog.py:{0[7]}) testLog.py({0[7]}) - This is DEBUG 4 - {{{{y,foo}}}}
 INFO  root  testPattern (testLog.py:{0[8]}) testLog.py({0[8]}) - This is INFO 5 - {{{{y,foo}}}}
 DEBUG root  testPattern (testLog.py:{0[9]}) testLog.py({0[9]}) - This is DEBUG 5 - {{{{y,foo}}}}
-""".format([x + 180 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__))  # noqa line too long
+""".format([x + 209 for x in (0, 1, 8, 9, 14, 15, 18, 19, 22, 23)], __name__))  # noqa E501 line too long
 
     def testMDCPutPid(self):
         """
@@ -231,22 +260,24 @@ def testMDCPutPid(self):
 log4j.appender.CA=ConsoleAppender
 log4j.appender.CA.layout=PatternLayout
 log4j.appender.CA.layout.ConversionPattern=%-5p PID:%X{{PID}} %c %C %M (%F:%L) %l - %m%n
-""")
+""")  # noqa E501 line too long
             self.assertGreaterEqual(pid, 0, "Failed to fork")
 
             msg = "This is INFO"
             if pid == 0:
                 self.tempDir = tempfile.mkdtemp()
-                self.outputFilename = os.path.join(self.tempDir, "log-child.out")
+                self.outputFilename = os.path.join(self.tempDir,
+                                                   "log-child.out")
                 msg += " in child process"
             elif pid > 0:
                 child_pid, child_status = os.wait()
-                self.assertEqual(child_status, 0, "Child returns incorrect code")
+                self.assertEqual(child_status, 0,
+                                 "Child returns incorrect code")
                 msg += " in parent process"
 
             with TestLog.StdoutCapture(self.outputFilename):
                 log.info(msg)
-                line = 248
+                line = 279
         finally:
             log.MDCRemove("PID")
 
@@ -370,7 +401,8 @@ def testLoggerLevel(self):
 log4j.appender.CA.layout=PatternLayout
 log4j.appender.CA.layout.ConversionPattern=%-5p %c (%F)- %m%n
 """)
-            self.assertEqual(log.Log.getLevel(log.Log.getDefaultLogger()), log.TRACE)
+            self.assertEqual(log.Log.getLevel(log.Log.getDefaultLogger()),
+                             log.TRACE)
             logger = log.Log.getLogger("a.b")
             self.assertEqual(logger.getName(), "a.b")
             logger.trace("This is TRACE")
@@ -421,9 +453,5 @@ def testMsgWithPercentS(self):
 """)
 
 
-####################################################################################
-def main():
-    unittest.main()
-
 if __name__ == "__main__":
-    main()
+    unittest.main()