SERVER-18572 Use the same timestamp format as MongoDB log messages.

5 files changed, 63 insertions, 12 deletions

diff --git a/buildscripts/resmokeconfig/loggers/buildlogger.yml b/buildscripts/resmokeconfig/loggers/buildlogger.yml
index a11b4c7bacf..302d2677491 100644
--- a/buildscripts/resmokeconfig/loggers/buildlogger.yml
+++ b/buildscripts/resmokeconfig/loggers/buildlogger.yml
@@ -1,13 +1,13 @@
 logging:
   executor:
-    format: '[%(name)s] %(message)s'
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: logging.StreamHandler
-  tests:
+  fixture:
     format: '[%(name)s] %(message)s'
     handlers:
       - class: buildlogger
-  fixture:
-    format: '%(message)s'
+  tests:
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: buildlogger
diff --git a/buildscripts/resmokeconfig/loggers/console.yml b/buildscripts/resmokeconfig/loggers/console.yml
index 0280f41c7ed..b233de409b3 100644
--- a/buildscripts/resmokeconfig/loggers/console.yml
+++ b/buildscripts/resmokeconfig/loggers/console.yml
@@ -1,6 +1,6 @@
 logging:
   executor:
-    format: '%(asctime)s [%(name)s] %(message)s'
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: logging.StreamHandler
   fixture:
@@ -8,6 +8,6 @@ logging:
     handlers:
       - class: logging.StreamHandler
   tests:
-    format: '%(asctime)s [%(name)s] %(message)s'
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: logging.StreamHandler
diff --git a/buildscripts/resmokeconfig/loggers/file.yml b/buildscripts/resmokeconfig/loggers/file.yml
index 012aed5d331..3d2d15cd5bc 100644
--- a/buildscripts/resmokeconfig/loggers/file.yml
+++ b/buildscripts/resmokeconfig/loggers/file.yml
@@ -1,6 +1,6 @@
 logging:
   executor:
-    format: '%(asctime)s [%(name)s] %(message)s'
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: logging.FileHandler
         filename: executor.log
@@ -12,7 +12,7 @@ logging:
         filename: fixture.log
         mode: w
   tests:
-    format: '%(asctime)s [%(name)s] %(message)s'
+    format: '[%(name)s] %(asctime)s %(message)s'
     handlers:
       - class: logging.FileHandler
         filename: tests.log
diff --git a/buildscripts/resmokelib/logging/config.py b/buildscripts/resmokelib/logging/config.py
index 9f3ca94dc82..c3960bbafd3 100644
--- a/buildscripts/resmokelib/logging/config.py
+++ b/buildscripts/resmokelib/logging/config.py
@@ -8,6 +8,7 @@ import logging
 import sys
 
 from . import buildlogger
+from . import formatters
 from . import loggers
 
 
@@ -64,7 +65,7 @@ def apply_buildlogger_global_handler(logger, logging_config, build_id=None, buil
 
     if all(x is not None for x in (build_id, build_config)):
         log_format = logger_info.get("format", _DEFAULT_FORMAT)
-        formatter = logging.Formatter(fmt=log_format)
+        formatter = formatters.ISO8601Formatter(fmt=log_format)
 
         handler = buildlogger.BuildloggerGlobalHandler(build_id,
                                                        build_config,
@@ -95,7 +96,7 @@ def apply_buildlogger_test_handler(logger,
 
     if all(x is not None for x in (build_id, build_config, test_id)):
         log_format = logger_info.get("format", _DEFAULT_FORMAT)
-        formatter = logging.Formatter(fmt=log_format)
+        formatter = formatters.ISO8601Formatter(fmt=log_format)
 
         handler = buildlogger.BuildloggerTestHandler(build_id,
                                                      build_config,
@@ -115,7 +116,7 @@ def _configure_logger(logger, logger_info):
     """
 
     log_format = logger_info.get("format", _DEFAULT_FORMAT)
-    formatter = logging.Formatter(fmt=log_format)
+    formatter = formatters.ISO8601Formatter(fmt=log_format)
 
     for handler_info in logger_info.get("handlers", []):
         handler_class = handler_info["class"]
@@ -140,7 +141,7 @@ def _fallback_buildlogger_handler():
     """
 
     log_format = "[buildlogger:%(name)s] %(message)s"
-    formatter = logging.Formatter(fmt=log_format)
+    formatter = formatters.ISO8601Formatter(fmt=log_format)
 
     handler = logging.StreamHandler(sys.stderr)
     handler.setFormatter(formatter)
diff --git a/buildscripts/resmokelib/logging/formatters.py b/buildscripts/resmokelib/logging/formatters.py
new file mode 100644
index 00000000000..4cc36da32d4
--- /dev/null
+++ b/buildscripts/resmokelib/logging/formatters.py
@@ -0,0 +1,50 @@
+"""
+Custom formatters for the logging handlers.
+"""
+
+from __future__ import absolute_import
+
+import logging
+import sys
+import time
+
+
+class ISO8601Formatter(logging.Formatter):
+    """
+    An ISO 8601 compliant formatter for log messages. It formats the
+    timezone as an hour/minute offset and uses a period as the
+    millisecond separator in order to match the log messages of MongoDB.
+    """
+
+    def formatTime(self, record, datefmt=None):
+        converted_time = self.converter(record.created)
+
+        if datefmt is not None:
+            return time.strftime(datefmt, converted_time)
+
+        formatted_time = time.strftime("%Y-%m-%dT%H:%M:%S", converted_time)
+        timezone = ISO8601Formatter._format_timezone_offset(converted_time)
+        return "%s.%03d%s" % (formatted_time, record.msecs, timezone)
+
+    @staticmethod
+    def _format_timezone_offset(converted_time):
+        """
+        Returns the timezone as an hour/minute offset in the form
+        "+HHMM" or "-HHMM".
+        """
+
+        # Windows treats %z in the format string as %Z, so we compute the hour/minute offset
+        # manually.
+        if converted_time.tm_isdst == 1 and time.daylight:
+            utc_offset_secs = time.altzone
+        else:
+            utc_offset_secs = time.timezone
+
+        # The offset is positive if the local timezone is behind (east of) UTC, and negative if it
+        # is ahead (west) of UTC.
+        utc_offset_prefix =  "-" if utc_offset_secs > 0 else "+"
+        utc_offset_secs = abs(utc_offset_secs)
+
+        utc_offset_mins = (utc_offset_secs / 60) % 60
+        utc_offset_hours = utc_offset_secs / 3600
+        return "%s%02d%02d" % (utc_offset_prefix, utc_offset_hours, utc_offset_mins)