Merge pull request #312 from HonakerM/add_duration_field

Add duration field to AlogJsonFormatter

src/python/alog/alog.py

@@ -95,7 +95,7 @@ class AlogJsonFormatter(AlogFormatterBase):
     """
     _FIELDS_TO_PRINT = ['name', 'levelname', 'asctime', 'message',
                         'exc_text', 'region-id', 'org-id', 'tran-id',
-                        'watson-txn-id', 'channel']
+                        'watson-txn-id', 'channel', 'duration']
 
     def __init__(self):
         AlogFormatterBase.__init__(self)
@@ -735,10 +735,10 @@ def _start_timed_log(self):
     def _end_timed_log(self):
         """Gets the end time and prints the end message for this timed logger.
         """
-        duration = str(timedelta(seconds=time.time() - self.start_time))
+        duration = timedelta(seconds=time.time() - self.start_time)
         fmt = self.format_str + "%s"
-        args = list(self.args) + [duration]
-        self.log_fn(fmt, *args)
+        args = list(self.args) + [str(duration)]
+        self.log_fn(fmt, *args, extra={"duration": duration.total_seconds()})
 
 # pylint: disable=too-few-public-methods
 class ScopedTimer(_TimedLogBase):

src/python/tests/test_alog.py

@@ -628,6 +628,7 @@ def test_timed_logger_context_managed_timer():
     timed_message = timed_log['message']
     assert timed_message.startswith('timed: 0:')
     assert re.match(r'^timed: [0-9]:[0-9][0-9]:[0-9][0-9]\.[0-9]+$', timed_message)
+    assert timed_log["duration"] > 0
 
 def test_timed_logger_scoped_timer():
     # Configure for log capture
@@ -651,6 +652,7 @@ def test():
     timed_message = timed_log['message']
     assert timed_message.startswith('timed: 0:')
     assert re.match(r'^timed: [0-9]:[0-9][0-9]:[0-9][0-9]\.[0-9]+$', timed_message)
+    assert timed_log["duration"] > 0
 
 def test_timed_logger_decorated_timer():
     # Configure for log capture
@@ -674,6 +676,7 @@ def test():
     timed_message = timed_log['message']
     assert timed_message.startswith('timed: 0:')
     assert re.match(r'^timed: [0-9]:[0-9][0-9]:[0-9][0-9]\.[0-9]+$', timed_message)
+    assert timed_log["duration"] > 0
 
 ## IsEnabled ###################################################################