From 07d80598cb383589d40ce58d7a9b7a22ab4c20ef Mon Sep 17 00:00:00 2001
From: Thorarinn Sigurdsson <thorarinnsigurdsson@gmail.com>
Date: Fri, 26 Jun 2020 10:54:14 +0200
Subject: [PATCH] feat(workflows): add duration to step events

---
 garden-service/src/commands/run/workflow.ts   | 16 +++++++---
 garden-service/src/events.ts                  |  2 ++
 .../test/unit/src/commands/run/workflow.ts    | 31 ++++++++++++-------
 3 files changed, 32 insertions(+), 17 deletions(-)

diff --git a/garden-service/src/commands/run/workflow.ts b/garden-service/src/commands/run/workflow.ts
index d834992f30..f8a5ff360e 100644
--- a/garden-service/src/commands/run/workflow.ts
+++ b/garden-service/src/commands/run/workflow.ts
@@ -21,7 +21,7 @@ import { ConfigurationError, FilesystemError } from "../../exceptions"
 import { posix, join } from "path"
 import { ensureDir, writeFile } from "fs-extra"
 import Bluebird from "bluebird"
-import { splitStream } from "../../util/util"
+import { splitStream, getDurationMsec } from "../../util/util"
 import execa, { ExecaError } from "execa"
 import { LogLevel } from "../../logger/log-node"
 
@@ -107,6 +107,8 @@ export class RunWorkflowCommand extends Command<Args, {}> {
         stepName,
       })
 
+      const stepStartedAt = new Date()
+
       try {
         if (step.command) {
           step.command = resolveTemplateStrings(step.command, stepTemplateContext)
@@ -132,11 +134,11 @@ export class RunWorkflowCommand extends Command<Args, {}> {
             footerLog: stepFooterLog,
           })
         } else {
-          garden.events.emit("workflowStepError", { index })
+          garden.events.emit("workflowStepError", getStepEndEvent(index, stepStartedAt))
           throw new ConfigurationError(`Workflow steps must specify either a command or a script.`, { step })
         }
       } catch (err) {
-        garden.events.emit("workflowStepError", { index })
+        garden.events.emit("workflowStepError", getStepEndEvent(index, stepStartedAt))
         printStepDuration({
           log: outerLog,
           stepIndex: index,
@@ -160,12 +162,12 @@ export class RunWorkflowCommand extends Command<Args, {}> {
       }
 
       if (stepResult.errors) {
-        garden.events.emit("workflowStepError", { index })
+        garden.events.emit("workflowStepError", getStepEndEvent(index, stepStartedAt))
         logErrors(outerLog, stepResult.errors, index, steps.length, step.description)
         return { result, errors: stepResult.errors }
       }
 
-      garden.events.emit("workflowStepComplete", { index })
+      garden.events.emit("workflowStepComplete", getStepEndEvent(index, stepStartedAt))
       printStepDuration({
         log: outerLog,
         stepIndex: index,
@@ -401,3 +403,7 @@ export async function runStepScript({ garden, log, step }: RunStepParams): Promi
     })
   }
 }
+
+function getStepEndEvent(index: number, startedAt: Date) {
+  return { index, durationMsec: getDurationMsec(startedAt, new Date()) }
+}
diff --git a/garden-service/src/events.ts b/garden-service/src/events.ts
index 6fcce775a6..c2d4e441fe 100644
--- a/garden-service/src/events.ts
+++ b/garden-service/src/events.ts
@@ -142,9 +142,11 @@ export interface Events extends LoggerEvents {
   }
   workflowStepComplete: {
     index: number
+    durationMsec: number
   }
   workflowStepError: {
     index: number
+    durationMsec: number
   }
 }
 
diff --git a/garden-service/test/unit/src/commands/run/workflow.ts b/garden-service/test/unit/src/commands/run/workflow.ts
index 36f375f867..82ba07c37b 100644
--- a/garden-service/test/unit/src/commands/run/workflow.ts
+++ b/garden-service/test/unit/src/commands/run/workflow.ts
@@ -128,13 +128,19 @@ describe("RunWorkflowCommand", () => {
 
     await cmd.action({ ..._defaultParams, args: { workflow: "workflow-a" } })
 
-    const workflowEvents = getWorkflowEvents(_garden)
-    expect(workflowEvents).to.eql([
-      { name: "workflowStepProcessing", payload: { index: 0 } },
-      { name: "workflowStepComplete", payload: { index: 0 } },
-      { name: "workflowStepProcessing", payload: { index: 1 } },
-      { name: "workflowStepComplete", payload: { index: 1 } },
-    ])
+    const we = getWorkflowEvents(_garden)
+
+    expect(we[0]).to.eql({ name: "workflowStepProcessing", payload: { index: 0 } })
+
+    expect(we[1].name).to.eql("workflowStepComplete")
+    expect(we[1].payload.index).to.eql(0)
+    expect(we[1].payload.durationMsec).to.gte(0)
+
+    expect(we[2]).to.eql({ name: "workflowStepProcessing", payload: { index: 1 } })
+
+    expect(we[3].name).to.eql("workflowStepComplete")
+    expect(we[3].payload.index).to.eql(1)
+    expect(we[3].payload.durationMsec).to.gte(0)
   })
 
   function filterLogEntries(entries: LogEntry[], msgRegex: RegExp): LogEntry[] {
@@ -309,11 +315,12 @@ describe("RunWorkflowCommand", () => {
     })
     expect(testModuleLog.length).to.eql(0)
 
-    const workflowEvents = getWorkflowEvents(_garden)
-    expect(workflowEvents).to.eql([
-      { name: "workflowStepProcessing", payload: { index: 0 } },
-      { name: "workflowStepError", payload: { index: 0 } },
-    ])
+    const we = getWorkflowEvents(_garden)
+
+    expect(we[0]).to.eql({ name: "workflowStepProcessing", payload: { index: 0 } })
+    expect(we[1].name).to.eql("workflowStepError")
+    expect(we[1].payload.index).to.eql(0)
+    expect(we[1].payload.durationMsec).to.gte(0)
   })
 
   it("should write a file with string data ahead of the run, before resolving providers", async () => {