milo: fix step duration

client/logdog/annotee/annotation/annotation.go

 // Copyright 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.
 
 package annotation
 
 import (
         "fmt"
         "sort"
         "strconv"
         "strings"
+        "time"
 
         "github.com/luci/luci-go/common/clock"
         "github.com/luci/luci-go/common/logdog/types"
         "github.com/luci/luci-go/common/proto/google"
         "github.com/luci/luci-go/common/proto/milo"
 )
 
 // Callbacks is the set of callbacks that a State may invoke as it processes
 // annotations.
 type Callbacks interface {
@@ skipping 13 matching lines @@
 // and can be serialized to a Milo annotation state protobuf.
 type State struct {
         // LogNameBase is the base log stream name that is prepeneded to generated
         // log streams.
         LogNameBase types.StreamName
         // Callbacks implements annotation callbacks. It may not be nil.
         Callbacks Callbacks
         // Execution is the supplied Execution. If nil, no execution details will be
         // added to the generated Milo protos.
         Execution *Execution
+        // Offline specifies whether parsing happens not at the same time as
+        // emitting. If true and CURRENT_TIMESTAMP annotations are not provided
+        // then step start/end times are left empty.
+        Offline bool
         // Clock is the clock implementation to use for time information.
+        // Defaults to system time.
         Clock clock.Clock
 
         // stepMap is a map of step name to Step instance.
         //
         // If stepMap is nil, the State is considered uninitialized.
         stepMap  map[string]*Step
         steps    []*Step
         rootStep Step
         // stepCursor is the current cursor step name. This will always point to a
         // valid Step, falling back to rootStep.
         stepCursor *Step
+        // startedProcessing is true iff processed at least one annotation.
+        startedProcessing bool
 
-        closed        bool
-        haltOnFailure bool
+        // currentTimestamp is time for the next annotation expected in Append.
+        currentTimestamp *google.Timestamp
+        closed           bool
+        haltOnFailure    bool
 }
 
 // initialize sets of the State's initial state. It will execute exactly once,
 // and must be called by any State methods that access internal variables.
 func (s *State) initialize() {
         if s.stepMap != nil {
                 return
         }
 
         s.stepMap = map[string]*Step{}
@@ skipping 26 matching lines @@
                         }
                 }
 
                 s.rootStep.Command = &milo.Command{
                         CommandLine: s.Execution.Command,
                         Cwd:         s.Execution.Dir,
                         Environ:     env,
                 }
         }
 
-        s.rootStep.Start()
+        var annotatedNow *google.Timestamp
+        if !s.Offline {
+                annotatedNow = s.now()
+        }
+        s.rootStep.Start(annotatedNow)
 }
 
 // Append adds an annotation to the state. If the state was updated, Append will
 // return true.
 //
 // The appended annotation should only contain the annotation text body, not any
 // annotation indicators (e.g., "@@@") that surround it.
 //
 // If the annotation is invalid or could not be added to the state, an error
 // will be returned.
 //
 // Steps and descriptions can be found at:
 // https://chromium.googlesource.com/chromium/tools/build/+/master/scripts/
 // master/chromium_step.py
 func (s *State) Append(annotation string) error {
         s.initialize()
 
+        firstAnnotation := !s.startedProcessing
+        s.startedProcessing = true
+
         command, params := annotation, ""
         splitIdx := strings.IndexAny(command, "@ ")
         if splitIdx > 0 {
                 command, params = command[:splitIdx], command[splitIdx+1:]
         }
 
         if s.closed {
                 return nil
         }
 
         var updated *Step
         updatedIf := func(s *Step, b bool) {
                 if b {
                         updated = s
                 }
         }
 
+        annotatedNow := s.currentTimestamp
+        s.currentTimestamp = nil
+        if annotatedNow == nil && !s.Offline {
+                annotatedNow = s.now()
+        }
+
         switch command {
+        // @@@CURRENT_TIMESTAMP@unix_timestamp@@@
+        case "CURRENT_TIMESTAMP":
+                // This annotation is printed at the beginning and end of the
+                // stream, as well as before each STEP_STARTED and STEP_CLOSED
+                // annotations. It effectively specifies step start/end times,
+                // including root step.
+                timestamp, err := strconv.ParseFloat(params, 64)
+                if err != nil {
+                        return fmt.Errorf("CURRENT_TIMESTAMP parameter %q is not a number: %s", params, err)
+                }
+                s.currentTimestamp = google.NewTimestamp(time.Unix(
+                        int64(timestamp),
+                        int64(timestamp*1000000000)%1000000000))
+                if firstAnnotation {
+                        s.rootStep.StepComponent.Started = s.currentTimestamp
+                }
+
         // @@@BUILD_STEP <stepname>@@@
         case "BUILD_STEP":
                 // Close the last section.
                 step := s.CurrentStep()
                 if step != nil && step != s.RootStep() {
                         if step.Name() == params {
                                 // Same step; ignore the command.
                                 break
                         }
-                        step.Close()
+                        step.Close(annotatedNow)
                 }
 
                 step = s.rootStep.AddStep(params)
-                step.Start()
+                step.Start(annotatedNow)
                 s.SetCurrentStep(step)
                 updatedIf(step, true)
 
         //  @@@SEED_STEP <stepname>@@@
         case "SEED_STEP":
                 step := s.LookupStep(params)
                 if step == nil {
                         step = s.rootStep.AddStep(params)
                         updatedIf(step, true)
                 }
@@ skipping 14 matching lines @@
                 parts := strings.SplitN(params, "@", 2)
                 if len(parts) != 2 {
                         return fmt.Errorf("STEP_LINK link [%s] missing URL", parts[0])
                 }
                 step.AddURLLink(parts[0], parts[1])
                 updatedIf(step, true)
 
         //  @@@STEP_STARTED@@@
         case "STEP_STARTED":
                 step := s.CurrentStep()
-                updatedIf(step, step.Start())
+                updatedIf(step, step.Start(annotatedNow))
 
         //  @@@STEP_WARNINGS@@@
         case "BUILD_WARNINGS":
                 fallthrough
         case "STEP_WARNINGS":
                 // No warnings because they don't generally help. Builds that want to add
                 // information can do so with notes. A "WARNING" state is traditionally a
                 // success state with a call to attention, and that call can be done through
                 // other means.
                 break
@@ skipping 11 matching lines @@
         // @@@STEP_EXCEPTION@@@
         case "BUILD_EXCEPTION":
                 fallthrough
         case "STEP_EXCEPTION":
                 step := s.CurrentStep()
                 updatedIf(step, step.SetStatus(milo.Status_EXCEPTION))
 
                 // @@@STEP_CLOSED@@@
         case "STEP_CLOSED":
                 step := s.CurrentStep()
-                updatedIf(step, step.Close())
+                updatedIf(step, step.Close(annotatedNow))
 
-                // @@@STEP_LOG_LINE@<label>@<line>@@@
+        // @@@STEP_LOG_LINE@<label>@<line>@@@
         case "STEP_LOG_LINE":
                 step := s.CurrentStep()
 
                 parts := strings.SplitN(params, "@", 2)
                 label, line := parts[0], ""
                 if len(parts) == 2 {
                         line = parts[1]
                 }
                 updatedIf(step, step.LogLine(label, line))
 
@@ skipping 79 matching lines @@
 // Finish closes the top-level annotation state and any outstanding steps.
 func (s *State) Finish() {
         s.initialize()
         s.finishWithStatusImpl(nil)
 }
 
 func (s *State) finishWithStatus(st milo.Status) bool {
         return s.finishWithStatusImpl(&st)
 }
 
-func (s *State) finishWithStatusImpl(sp *milo.Status) bool {
+func (s *State) finishWithStatusImpl(status *milo.Status) bool {
         if s.closed {
                 return false
         }
 
+        // if s.currentTimestamp is not nil, the last annotation was
+        // CURRENT_TIMESTAMP and s.currentTimestamp contains its value.
+        buildEndTime := s.currentTimestamp
+        s.currentTimestamp = nil
+        if buildEndTime == nil && !s.Offline {
+                buildEndTime = s.now()
+        }
+
         unfinished := false
         for _, step := range s.steps[1:] {
-                if u := step.closeWithStatus(nil); u {
+                if step.closeWithStatus(buildEndTime, nil) {
                         unfinished = true
                 }
         }
 
         // If some steps were unfinished, show a root exception.
-        if unfinished && sp == nil {
-                status := milo.Status_EXCEPTION
-                sp = &status
+        if unfinished && status == nil {
+                exception := milo.Status_EXCEPTION
+                status = &exception
         }
-        s.rootStep.closeWithStatus(sp)
+        s.rootStep.closeWithStatus(buildEndTime, status)
 
         // Probe the status from our steps, if one is not supplied.
         s.closed = true
         return true
 }
 
 // LookupStep returns the step with the supplied name, or nil if no such step
 // exists.
 func (s *State) LookupStep(name string) *Step {
         return s.stepMap[name]
@@ skipping 53 matching lines @@
 }
 
 // ForEachStep iterates over all registered steps, invoking the supplied
 // callback with each step's protobuf state.
 func (s *State) ForEachStep(f func(*Step)) {
         for _, as := range s.steps {
                 f(as)
         }
 }
 
-func (s *State) annotationNow() *google.Timestamp {
+// now returns current time of s.Clock. Defaults to system clock.
+func (s *State) now() *google.Timestamp {
         c := s.Clock
         if c == nil {
                 c = clock.GetSystemClock()
         }
         return google.NewTimestamp(c.Now())
 }
 
 // Step represents a single step.
 type Step struct {
         milo.Step
@@ skipping 97 matching lines @@
         }
 
         nas := (&Step{}).initialize(as.s, as, name, index, as.BaseStream(logPath))
         as.substeps = append(as.substeps, nas)
         as.s.registerStep(nas)
         as.EnsureSubstepLogNameBase(nas.logNameBase)
         return nas
 }
 
 // Start marks the Step as started.
-func (as *Step) Start() bool {
+func (as *Step) Start(startTime *google.Timestamp) bool {
         if as.StepComponent.Started != nil {
                 return false
         }
-        as.StepComponent.Started = as.s.annotationNow()
+        as.StepComponent.Started = startTime
         return true
 }
 
 // Close closes this step and any outstanding resources that it owns.
-func (as *Step) Close() bool {
-        return as.closeWithStatus(nil)
+// If it is already closed, does not have side effects and returns false.
+func (as *Step) Close(closeTime *google.Timestamp) bool {
+        return as.closeWithStatus(closeTime, nil)
 }
 
-func (as *Step) closeWithStatus(sp *milo.Status) bool {
+func (as *Step) closeWithStatus(closeTime *google.Timestamp, sp *milo.Status) bool {
         if as.closed {
                 return false
         }
 
         // Close our outstanding substeps, and get their highest status value.
         stepStatus := milo.Status_SUCCESS
         for _, sub := range as.substeps {
-                sub.Close()
+                sub.Close(closeTime)
                 if sub.StepComponent.Status > stepStatus {
                         stepStatus = sub.StepComponent.Status
                 }
         }
 
         // Close any ourstanding log streams.
         for l := range as.logLines {
                 as.LogEnd(l)
         }
 
         // If a status is provided, use it.
         if sp != nil {
                 stepStatus = *sp
         }
 
         if as.StepComponent.Status == milo.Status_RUNNING {
                 as.StepComponent.Status = stepStatus
         }
-        as.StepComponent.Ended = as.s.annotationNow()
+        as.StepComponent.Ended = closeTime
         if as.StepComponent.Started == nil {
                 as.StepComponent.Started = as.StepComponent.Ended
         }
         as.closed = true
         as.s.unregisterStep(as)
         as.s.Callbacks.Updated(as)
         as.s.Callbacks.StepClosed(as)
         return true
 }
 
@@ skipping 142 matching lines @@
 func (as *Step) EnsureSubstepLogNameBase(name types.StreamName) bool {
         nameStr := string(name)
         for _, lnb := range as.SubstepLogdogNameBase {
                 if lnb == nameStr {
                         return false
                 }
         }
         as.SubstepLogdogNameBase = append(as.SubstepLogdogNameBase, nameStr)
         return true
 }