utils: support log_to_file(usec=True)

docs/api.rst

@@ -873,7 +873,7 @@ A random assortment of utility functions useful on masters and children.
     OS X bundles some ancient version of the :py:mod:`six` module.
 
 .. currentmodule:: mitogen.utils
-.. function:: log_to_file (path=None, io=True, level='INFO')
+.. function:: log_to_file (path=None, io=True, usec=False, level='INFO')
 
     Install a new :py:class:`logging.Handler` writing applications logs to the
     filesystem. Useful when debugging slave IO problems.
@@ -886,6 +886,10 @@ A random assortment of utility functions useful on masters and children.
         If ``True``, include extremely verbose IO logs in the output. Useful
         for debugging hangs, less useful for debugging application code.
 
+    :parm bool usec:
+        If ``True``, include microsecond timestamps. This greatly helps when
+        debugging races and similar determinism issues.
+
     :param str level:
         Name of the :py:mod:`logging` package constant that is the minimum
         level to log at. Useful levels are ``DEBUG``, ``INFO``, ``WARNING``,

mitogen/utils.py

@@ -25,6 +25,7 @@
 # OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
+import datetime
 import logging
 import sys
 
@@ -42,7 +43,12 @@ def disable_site_packages():
             sys.path.remove(entry)
 
 
-def log_to_file(path=None, io=True, level='INFO'):
+def _formatTime(record, datefmt=None):
+    dt = datetime.datetime.fromtimestamp(record.created)
+    return dt.strftime(datefmt)
+
+
+def log_to_file(path=None, io=True, usec=False, level='INFO'):
     log = logging.getLogger('')
     if path:
         fp = open(path, 'w', 1)
@@ -57,8 +63,11 @@ def log_to_file(path=None, io=True, level='INFO'):
 
     fmt = '%(asctime)s %(levelname).1s %(name)s: %(message)s'
     datefmt = '%H:%M:%S'
+    if usec:
+        datefmt += '.%f'
     handler = logging.StreamHandler(fp)
     handler.formatter = logging.Formatter(fmt, datefmt)
+    handler.formatter.formatTime = _formatTime
     log.handlers.insert(0, handler)