Add CURRENT_TIMESTAMP annotation

scripts/common/annotator.py

 # Copyright (c) 2015 The Chromium Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 """Contains the parsing system of the Chromium Buildbot Annotator."""
 
 import os
 import sys
+import time
 import traceback
 
 # These are maps of annotation key -> number of expected arguments.
 STEP_ANNOTATIONS = {
     'SET_BUILD_PROPERTY': 2,
     'STEP_CLEAR': 0,
     'STEP_EXCEPTION': 0,
     'STEP_FAILURE': 0,
     'STEP_LINK': 2,
     'STEP_LOG_END': 1,
     'STEP_LOG_END_PERF': 2,
     'STEP_LOG_LINE': 2,
     'STEP_SUMMARY_CLEAR': 0,
     'STEP_SUMMARY_TEXT': 1,
     'STEP_TEXT': 1,
     'STEP_TRIGGER': 1,
     'STEP_WARNINGS': 0,
     'STEP_NEST_LEVEL': 1,
 }
 
 CONTROL_ANNOTATIONS = {
     'STEP_CLOSED': 0,
     'STEP_STARTED': 0,
 }
 
 STREAM_ANNOTATIONS = {
+    # CURRENT_TIMESTAMP has one parameter, current Unix timestamp, which in
+    # practice specifies timestamp of the following annotation.
+    # The following annotation MUST be emitted immediately,
+    # however there is no requirement for the annotation after the next one
+    # to be emitted immediately. Annotation parsers must not consider
+    # CURRENT_TIMESTAMP for annotations that follow the annotation which is next
+    # after the CURRENT_TIMESTAMP.
+    'CURRENT_TIMESTAMP': 1,
     'HALT_ON_FAILURE': 0,
     'HONOR_ZERO_RETURN_CODE': 0,
     'SEED_STEP': 1,
     'SEED_STEP_TEXT': 2,
     'STEP_CURSOR': 1,
 }
 
 DEPRECATED_ANNOTATIONS = {
     'BUILD_STEP': 1,
 }
@@ skipping 145 matching lines @@
 
 class StructuredAnnotationStep(StepCommands, StepControlCommands):
   """Helper class to provide context for a step."""
 
   def __init__(self, annotation_stream, *args, **kwargs):
     self.annotation_stream = annotation_stream
     super(StructuredAnnotationStep, self).__init__(*args, **kwargs)
     self.control = StepControlCommands(self.stream, self.flush_before)
     self.emitted_logs = set()
 
-
   def __enter__(self):
     return self.step_started()
 
   def step_started(self):
+    self.annotation_stream.emit_current_timestamp()
     self.control.step_started()
     return self
 
   def __exit__(self, exc_type, exc_value, tb):
     self.annotation_stream.step_cursor(self.annotation_stream.current_step)
     #TODO(martinis) combine this and step_ended
     if exc_type:
       self.step_exception_occured(exc_type, exc_value, tb)
 
+    self.annotation_stream.emit_current_timestamp()
     self.control.step_closed()
     self.annotation_stream.current_step = ''
     return not exc_type
 
   def step_exception_occured(self, exc_type, exc_value, tb):
     trace = traceback.format_exception(exc_type, exc_value, tb)
     trace_lines = ''.join(trace).split('\n')
     self.write_log_lines('exception', filter(None, trace_lines))
     self.step_exception()
 
   def step_ended(self):
     self.annotation_stream.step_cursor(self.annotation_stream.current_step)
+    self.annotation_stream.emit_current_timestamp()
     self.control.step_closed()
     self.annotation_stream.current_step = ''
 
     return True
 
 
 class StructuredAnnotationStream(AnnotationPrinter):
   """Provides an interface to handle an annotated build.
 
   StructuredAnnotationStream handles most of the step setup and closure calls
@@ skipping 10 matching lines @@
       s.step_failure()
   with stream.step('test') as s:
     # do something
     if warnings:
       s.step_warnings()
   """
   ANNOTATIONS = STREAM_ANNOTATIONS
 
   def __init__(self, stream=sys.stdout,
                flush_before=sys.stderr,
-               seed_steps=None):  # pylint: disable=W0613
+               seed_steps=None,  # pylint: disable=W0613
+               time_fn=None):
     super(StructuredAnnotationStream, self).__init__(stream=stream,
                                                      flush_before=flush_before)
     self.current_step = ''
+    self.time_fn = time_fn or time.time
+
+  def emit_current_timestamp(self):
+    self.current_timestamp(self.time_fn())
 
   def step(self, name):
     """Provide a context with which to execute a step."""
     if self.current_step:
       raise Exception('Can\'t start step %s while in step %s.' % (
           name, self.current_step))
 
     self.seed_step(name)
     self.step_cursor(name)
     self.current_step = name
@@ skipping 69 matching lines @@
         # This prevents functions from showing up as:
         #   '<function foo at 0x7f523ec7a410>'
         # which is tricky to test.
         value = value.__name__+'(...)'
       step_info_lines.append(' %s: %s' % (key, value))
   step_info_lines.append('full environment:')
   for key, value in sorted(env.items()):
     step_info_lines.append(' %s: %s' % (key, value))
   step_info_lines.append('')
   stream.emit('\n'.join(step_info_lines))