Make it easy to output milliseconds (and improve documentation on this)

README.rst

@@ -25,7 +25,6 @@ defined by my verboselogs_ package: if you install both `coloredlogs` and
 
 .. contents::
    :local:
-   :depth: 1
 
 Format of log messages
 ----------------------
@@ -46,6 +45,30 @@ You can customize the log format and styling using environment variables as
 well as programmatically, please refer to the `online documentation`_ for
 details.
 
+Enabling millisecond precision
+~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
+
+If you're switching from `logging.basicConfig()`_ to `coloredlogs.install()`_
+you may notice that timestamps no longer include milliseconds. This is because
+coloredlogs doesn't output milliseconds in timestamps unless you explicitly
+tell it to. There are two ways to do that:
+
+1. The easy way is to pass the `milliseconds` argument to
+   `coloredlogs.install()`_::
+
+    coloredlogs.install(milliseconds=True)
+
+2. Alternatively you can change the log format `to include 'msecs'`_::
+
+    %(asctime)s,%(msecs)03d %(hostname)s %(name)s[%(process)d] %(levelname)s %(message)s
+
+   Here's what the call to `coloredlogs.install()`_ would then look like::
+
+    coloredlogs.install(fmt='%(asctime)s,%(msecs)03d %(hostname)s %(name)s[%(process)d] %(levelname)s %(message)s')
+
+   Customizing the log format also enables you to change the delimiter that
+   separates seconds from milliseconds (the comma above).
+
 Usage
 -----
 
@@ -147,12 +170,15 @@ This software is licensed under the `MIT license`_.
 .. _Colorama: https://pypi.python.org/pypi/colorama
 .. _ColoredCronMailer: https://coloredlogs.readthedocs.io/en/latest/#coloredlogs.converter.ColoredCronMailer
 .. _ColoredFormatter: https://coloredlogs.readthedocs.io/en/latest/#coloredlogs.ColoredFormatter
+.. _coloredlogs.install(): https://coloredlogs.readthedocs.io/en/latest/#coloredlogs.install
 .. _cron: https://en.wikipedia.org/wiki/Cron
 .. _GitHub: https://github.com/xolox/python-coloredlogs
+.. _logging.basicConfig(): https://docs.python.org/2/library/logging.html#logging.basicConfig
 .. _logging.Formatter: https://docs.python.org/2/library/logging.html#logging.Formatter
 .. _logging: https://docs.python.org/2/library/logging.html
 .. _MIT license: https://en.wikipedia.org/wiki/MIT_License
 .. _online documentation: https://coloredlogs.readthedocs.io/
 .. _peter@peterodding.com: peter@peterodding.com
 .. _PyPI: https://pypi.python.org/pypi/coloredlogs
+.. _to include 'msecs': https://stackoverflow.com/questions/6290739/python-logging-use-milliseconds-in-time-format
 .. _verboselogs: https://pypi.python.org/pypi/verboselogs

coloredlogs/__init__.py

@@ -1,7 +1,7 @@
 # Colored terminal output for Python's logging module.
 #
 # Author: Peter Odding <peter@peterodding.com>
-# Last Change: July 14, 2017
+# Last Change: July 15, 2017
 # URL: https://coloredlogs.readthedocs.io
 
 """
@@ -273,6 +273,9 @@ def install(level=None, **kw):
                 :data:`DEFAULT_LOG_FORMAT`).
     :param datefmt: Set the date/time format (a string, defaults to
                     :data:`DEFAULT_DATE_FORMAT`).
+    :param milliseconds: :data:`True` to show milliseconds like :mod:`logging`
+                         does by default, :data:`False` to hide milliseconds
+                         (the default is :data:`False`, see `#16`_).
     :param level_styles: A dictionary with custom level styles (defaults to
                          :data:`DEFAULT_LEVEL_STYLES`).
     :param field_styles: A dictionary with custom field styles (defaults to
@@ -327,6 +330,8 @@ def install(level=None, **kw):
 
     6. The formatter is added to the handler and the handler is added to the
        logger.
+
+    .. _issue 16: https://github.com/xolox/python-coloredlogs/issues/16
     """
     logger = kw.get('logger') or logging.getLogger()
     reconfigure = kw.get('reconfigure', True)
@@ -401,6 +406,20 @@ def install(level=None, **kw):
         # back to the default).
         if not formatter_options['datefmt']:
             formatter_options['datefmt'] = os.environ.get('COLOREDLOGS_DATE_FORMAT') or DEFAULT_DATE_FORMAT
+        # Python's logging module shows milliseconds by default through special
+        # handling in the logging.Formatter.formatTime() method [1]. Because
+        # coloredlogs always defines a `datefmt' it bypasses this special
+        # handling, which is fine because ever since publishing coloredlogs
+        # I've never needed millisecond precision ;-). However there are users
+        # of coloredlogs that do want milliseconds to be shown [2] so we
+        # provide a shortcut to make it easy.
+        #
+        # [1] https://stackoverflow.com/questions/6290739/python-logging-use-milliseconds-in-time-format
+        # [2] https://github.com/xolox/python-coloredlogs/issues/16
+        if kw.get('milliseconds') and '%(msecs)' not in formatter_options['fmt']:
+            formatter_options['fmt'] = formatter_options['fmt'].replace(
+                '%(asctime)s', '%(asctime)s,%(msecs)03d',
+            )
         # Do we need to make %(hostname) available to the formatter?
         HostNameFilter.install(
             handler=handler,

coloredlogs/tests.py

@@ -1,7 +1,7 @@
 # Automated tests for the `coloredlogs' package.
 #
 # Author: Peter Odding <peter@peterodding.com>
-# Last Change: May 17, 2017
+# Last Change: July 15, 2017
 # URL: https://coloredlogs.readthedocs.io
 
 """Automated tests for the `coloredlogs` package."""
@@ -66,6 +66,18 @@
     \s (?P<message> .* )
 ''', re.VERBOSE)
 
+# Compiled regular expression that matches a single line of output produced by
+# the default log format with milliseconds=True.
+PATTERN_INCLUDING_MILLISECONDS = re.compile(r'''
+    (?P<date> \d{4}-\d{2}-\d{2} )
+    \s (?P<time> \d{2}:\d{2}:\d{2},\d{3} )
+    \s (?P<hostname> \S+ )
+    \s (?P<logger_name> \w+ )
+    \[ (?P<process_id> \d+ ) \]
+    \s (?P<severity> [A-Z]+ )
+    \s (?P<message> .* )
+''', re.VERBOSE)
+
 # The pathname of the system log file on Ubuntu Linux (my laptops and Travis CI).
 UNIX_SYSTEM_LOG = '/var/log/syslog'
 
@@ -308,6 +320,19 @@ def get_logger_tree(self):
         grand_child = logging.getLogger(grand_child_name)
         return root, parent, child, grand_child
 
+    def test_support_for_milliseconds(self):
+        """Make sure milliseconds are hidden by default but can be easily enabled."""
+        # Check that the default log format doesn't include milliseconds.
+        stream = StringIO()
+        install(reconfigure=True, stream=stream)
+        logging.info("This should not include milliseconds.")
+        assert all(map(PLAIN_TEXT_PATTERN.match, stream.getvalue().splitlines()))
+        # Check that milliseconds can be enabled via a shortcut.
+        stream = StringIO()
+        install(milliseconds=True, reconfigure=True, stream=stream)
+        logging.info("This should include milliseconds.")
+        assert all(map(PATTERN_INCLUDING_MILLISECONDS.match, stream.getvalue().splitlines()))
+
     def test_plain_text_output_format(self):
         """Inspect the plain text output of coloredlogs."""
         logger = VerboseLogger(random_string(25))