Add progress logging to await task (#343)

* Add showprogress flag to input parameters

* Add show progress logic

* Fix last task not being logged.

* Update read me with more test + build instructions

Author: octopus-hideaki

README.md

@@ -52,7 +52,15 @@ This will generate the full extension content required to create the extension V
 
 In order to package and test the extension on a local TFS instance, without publishing to the marketplace, you can run the following at a PowerShell command prompt.
 
-`./pack.ps1 -environment localtest -version "x.x.x"`
+`./pack.ps1 -environment localtest -version "x.x.x" -setupTaskDependencies`
+
+Alternatively you can run the build + packaging scripts:
+
+Windows:
+`./localBuild.cmd`
+
+MacOS:
+`source localbuild.sh`
 
 ### Releasing
 
@@ -71,6 +79,7 @@ If you're doing updates, enhancements, or bug fixes, the fastest development flo
 It's highly recommended to set up two Virtual Machines running Windows Server. This is generally done locally, and it's best to give your VM at least 8 gigs of memory and 4 CPU cores, otherwise the TFS/ADO installation can fail or take hours.
 
 1. Microsoft TFS Server 2017 Update 1 - This is the first version of TFS that supported extensions, so it's very good for regression testing.
+    - Note that the `.exe` installers of older versions may fail to install due to broken dependency downloads. It's recommended to use the `.iso` downloads
 2. Microsoft Azure DevOps Server vLatest - This is the on-prem version of Microsoft's hosted Azure DevOps services/tooling. It's generally faster/easier to test this locally than continually publishing to the Azure DevOps Marketplace.
 
 To install locally, build and package the application as per the instructions above. Then install the extension by uploading it. Instructions to do this are available in Microsoft's [TFS/ADO docs](https://docs.microsoft.com/en-us/vsts/marketplace/get-tfs-extensions?view=tfs-2018#install-extensions-for-disconnected-tfs).
@@ -86,6 +95,13 @@ To install locally, build and package the application as per the instructions ab
 * If you design a build pipeline with the current live extension, you can't upgrade it to a local version. You need to install the `localtest` extension first and use it in your builds. Then you can upgrade it and you will get your latest changes.
 * We need to maintain backwards compatibility, and we need to ensure any existing builds will not break after we publish an update. Therefore regression testing is critical. The recommended approach for regression testing is to build the current live extension for `localtest` and create build pipelines covering the areas you're changing. Then update the extension and re-run all your builds to ensure everything is still green/working.
 * Building on the previous point, there is no way to roll back an extension so testing is difficult as well. The recommended approach to this is to snapshot your local test VMs when you have a working build, so you can update the extension and revert back to the snapshot as needed.
+* Older versions of Azure DevOps/Team Foundation Server has limits on the size of extensions to upload which may prevent you from installing the extension.
+  - For Azure Devops 2019. You can increase the limit by running the following SQL script on the Azure Devops "Configuration" database. (``)
+    ```
+    DECLARE @keyvalues dbo.typ_keyvaluepairstringtablenullable;
+    INSERT @keyvalues VALUES ('#\Configuration\Service\Gallery\LargeExtensionUpload\MaxPackageSizeMB', '50')
+    exec prc_UpdateRegistry 1, @keyvalues;
+    ```
 * During manual testing against our test environment on Azure DevOps, the `devops@...` account has access for publishing to test and production environments (if you try to do this from your personal account, publishing will fail). When you create your security tokens, do this from the devops account and either setup an expiry and/or remove the token when you are finished with it.
 * At the time of writing, we have a [build pipeline on ADO](https://octopus-deploy.visualstudio.com/VstsExtension/_build?definitionId=5&_a=summary), which builds and pushes packages to our [deployhq](https://deploy.octopushq.com/app#/Spaces-1/projects/azure-devops-extension/deployments) project, where we can then release to Test and Production.
 * If the deployHQ task fails due to a timeout (which is common), trying again on the octopusHQ task *will not fix it*. You need to squirrel into the VSTS task (see the task log in octopusHQ, it will have a link to the VSTS task in the log, which will have a link to the `Web`, click that and it'll take you to the problem), see that it's failing on all the steps related to v4 of our octo tool, *run the same task again (as new)* (don't re-run the existing task that's failed), wait for that to succeed, then re-run our task in deployHQ and it will then succeed. We want to allocate time to investigate why this is so awkward, but for now, we're documenting here for discoverability.

source/tasks/AwaitTask/AwaitTaskV6/input-parameters.ts

@@ -8,6 +8,7 @@ export interface InputParameters {
     tasks: WaitExecutionResult[];
     pollingInterval: number;
     timeout: number;
+    showProgress: boolean;
 }
 
 export function getInputParameters(logger: Logger, task: TaskWrapper): InputParameters {
@@ -21,10 +22,14 @@ export function getInputParameters(logger: Logger, task: TaskWrapper): InputPara
         throw new Error("Failed to successfully build parameters: step name is required.");
     }
 
-    const tasks = task.getOutputVariable(step, "server_tasks");
-    if (tasks === undefined) {
+    const taskJson = task.getOutputVariable(step, "server_tasks");
+    if (taskJson === undefined) {
         throw new Error(`Failed to successfully build parameters: cannot find '${step}.server_tasks' variable from execution step`);
     }
+    const tasks = JSON.parse(taskJson);
+    if (!Array.isArray(tasks)) {
+        throw new Error(`Failed to successfully build parameters: '${step}.server_tasks' variable from execution step is not an array`);
+    }
 
     let pollingInterval = 10;
     const pollingIntervalField = task.getInput("PollingInterval");
@@ -38,10 +43,16 @@ export function getInputParameters(logger: Logger, task: TaskWrapper): InputPara
         timeoutSeconds = +timeoutField;
     }
 
+    const showProgress = task.getBoolean("ShowProgress") ?? false;
+    if (showProgress && tasks.length > 1) {
+        throw new Error("Failed to successfully build parameters: ShowProgress can only be enabled when waiting for a single task");
+    }
+
     const parameters: InputParameters = {
         space: task.getInput("Space") || "",
         step: step,
-        tasks: JSON.parse(tasks),
+        tasks: tasks,
+        showProgress: showProgress,
         pollingInterval: pollingInterval,
         timeout: timeoutSeconds,
     };

source/tasks/AwaitTask/AwaitTaskV6/task.json

@@ -57,6 +57,14 @@
             "defaultValue": "600",
             "required": false,
             "helpMarkDown": "Duration, in seconds, to allow for completion before timing out. (Default: 600s)"
+        },
+        {
+            "name": "ShowProgress",
+            "type": "boolean",
+            "label": "Show Progress",
+            "defaultValue": "false",
+            "required": false,
+            "helpMarkDown": "Log Octopus task outputs to Azure DevOps output. (Default: false)"
         }
     ],
     "outputVariables": [

source/tasks/AwaitTask/AwaitTaskV6/waiter.ts

@@ -1,7 +1,7 @@
-import { Client, Logger, ServerTaskWaiter, SpaceRepository, TaskState } from "@octopusdeploy/api-client";
+import { ActivityElement, ActivityLogEntryCategory, ActivityStatus, Client, Logger, ServerTaskWaiter, SpaceRepository, SpaceServerTaskRepository, TaskState } from "@octopusdeploy/api-client";
 import { OctoServerConnectionDetails } from "tasks/Utils/connection";
 import { TaskWrapper } from "tasks/Utils/taskInput";
-import { getInputParameters } from "./input-parameters";
+import { getInputParameters, InputParameters } from "./input-parameters";
 import { ExecutionResult } from "../../Utils/executionResult";
 import { getClient } from "../../Utils/client";
 
@@ -10,46 +10,14 @@ export interface WaitExecutionResult extends ExecutionResult {
 }
 
 export class Waiter {
-    constructor(readonly connection: OctoServerConnectionDetails, readonly task: TaskWrapper, readonly logger: Logger) {}
+    constructor(readonly connection: OctoServerConnectionDetails, readonly task: TaskWrapper, readonly logger: Logger) { }
 
     public async run() {
         const inputParameters = getInputParameters(this.logger, this.task);
 
-        const client = await getClient(this.connection, this.logger, "task", "wait", 6)
+        const client = await getClient(this.connection, this.logger, "task", "wait", 6);
 
-        const waiter = new ServerTaskWaiter(client, inputParameters.space);
-
-        const taskIds: string[] = [];
-        const waitExecutionResults: WaitExecutionResult[] = [];
-        const lookup: Map<string, WaitExecutionResult> = new Map<string, WaitExecutionResult>();
-        inputParameters.tasks.map((t) => {
-            lookup.set(t.serverTaskId, t);
-            taskIds.push(t.serverTaskId);
-        });
-
-        await waiter.waitForServerTasksToComplete(taskIds, inputParameters.pollingInterval * 1000, inputParameters.timeout * 1000, (t) => {
-            let context = "";
-            const taskResult = lookup.get(t.Id);
-            if (taskResult) {
-                if (taskResult?.environmentName) {
-                    context = ` to environment '${taskResult.environmentName}'`;
-                }
-                if (taskResult?.tenantName) {
-                    context += ` for tenant '${taskResult?.tenantName}'`;
-                }
-
-                if (t.IsCompleted) {
-                    this.logger.info?.(`${taskResult.type}${context} ${t.State === TaskState.Success ? "completed successfully" : "did not complete successfully"}`);
-                } else {
-                    this.logger.info?.(`${taskResult.type}${context} is '${t.State}'`);
-                }
-
-                if (t.IsCompleted) {
-                    taskResult.successful = t.IsCompleted && t.State == TaskState.Success;
-                    waitExecutionResults.push(taskResult);
-                }
-            }
-        });
+        const waitExecutionResults = inputParameters.showProgress ? await this.waitWithProgress(client, inputParameters) : await this.waitWithoutProgress(client, inputParameters);
 
         const spaceId = await this.getSpaceId(client, inputParameters.space);
         let failedDeploymentsCount = 0;
@@ -86,4 +54,136 @@ export class Waiter {
     getContext(result: WaitExecutionResult): string {
         return result.tenantName ? result.tenantName.replace(" ", "_") : result.environmentName.replace(" ", "_");
     }
+
+    async waitWithoutProgress(client: Client, inputParameters: InputParameters): Promise<WaitExecutionResult[]> {
+        const waiter = new ServerTaskWaiter(client, inputParameters.space);
+        const taskIds = inputParameters.tasks.map((t) => t.serverTaskId);
+        const lookup = new Map(inputParameters.tasks.map((t) => [t.serverTaskId, t]));
+
+        const results: WaitExecutionResult[] = [];
+
+        await waiter.waitForServerTasksToComplete(taskIds, inputParameters.pollingInterval * 1000, inputParameters.timeout * 1000, (t) => {
+            const taskResult = lookup.get(t.Id);
+            if (!taskResult) return;
+            const context = this.getProgressContext(taskResult);
+
+            if (!t.IsCompleted) {
+                this.logger.info?.(`${taskResult.type}${context} is '${t.State}'`);
+                return;
+            }
+
+            this.logger.info?.(`${taskResult.type}${context} ${t.State === TaskState.Success ? "completed successfully" : "did not complete successfully"}`);
+            taskResult.successful = t.State == TaskState.Success;
+            results.push(taskResult);
+        });
+        return results;
+    }
+
+    async waitWithProgress(client: Client, inputParameters: InputParameters): Promise<WaitExecutionResult[]> {
+        const waiter = new ServerTaskWaiter(client, inputParameters.space);
+        const taskIds = inputParameters.tasks.map((t) => t.serverTaskId);
+        const taskLookup = new Map(inputParameters.tasks.map((t) => [t.serverTaskId, t]));
+
+        const taskRepository = new SpaceServerTaskRepository(client, inputParameters.space);
+        const loggedChildTaskIds: string[] = [];
+        const lastTaskUpdate: { [taskId: string]: string } = {};
+
+        const results: WaitExecutionResult[] = [];
+
+        const promises: Promise<void>[] = [];
+        await waiter.waitForServerTasksToComplete(taskIds, inputParameters.pollingInterval * 1000, inputParameters.timeout * 1000, (t) => {
+            const taskResult = taskLookup.get(t.Id);
+            if (!taskResult) return;
+
+            const taskUpdate = `${taskResult.type}${this.getProgressContext(taskResult)} is '${t.State}'`;
+            if (loggedChildTaskIds.length == 0 && lastTaskUpdate[taskResult.serverTaskId] !== taskUpdate) {
+                // Log top level updates until we have details, don't log them again
+                this.logger.info?.(taskUpdate);
+                lastTaskUpdate[taskResult.serverTaskId] = taskUpdate;
+            }
+
+            // Log details of the task
+            const promise = this.printTaskDetails(taskRepository, taskResult, loggedChildTaskIds, results);
+            promises.push(promise);
+        });
+
+        await Promise.all(promises);
+        return results;
+    }
+
+    async printTaskDetails(repository: SpaceServerTaskRepository, task: WaitExecutionResult, loggedChildTaskIds: string[], results: WaitExecutionResult[]): Promise<void> {
+        try {
+            this.logger.debug?.(`Fetching details on ${task.serverTaskId}`);
+            const taskDetails = await repository.getDetails(task.serverTaskId);
+            this.logger.debug?.(`Fetched details on ${task.serverTaskId}: ${JSON.stringify(taskDetails)}`);
+
+            const activities = taskDetails.ActivityLogs.flatMap((parentActivity) => parentActivity.Children.filter(isComplete).filter((activity) => !loggedChildTaskIds.includes(activity.Id)));
+
+            for (const activity of activities) {
+                this.logWithStatus(`\t${activity.Status}: ${activity.Name}`, activity.Status);
+
+                if (activity.Started && activity.Ended) {
+                    const startTime = new Date(activity.Started);
+                    const endTime = new Date(activity.Ended);
+                    const duration = (endTime.getTime() - startTime.getTime()) / 1000;
+                    this.logger.info?.(`\t\t\t---------------------------------`);
+                    this.logger.info?.(`\t\t\tStarted: \t${activity.Started}\n\t\t\tEnded:   \t${activity.Ended}\n\t\t\tDuration:\t${duration.toFixed(1)}s`);
+                    this.logger.info?.(`\t\t\t---------------------------------`);
+                }
+
+                activity.Children.filter(isComplete)
+                    .flatMap((child) => child.LogElements)
+                    .forEach((log) => {
+                        this.logWithCategory(`\t\t${log.OccurredAt}: ${log.MessageText}`, log.Category);
+                        log.Detail && this.logger.debug?.(log.Detail);
+                    });
+
+                loggedChildTaskIds.push(activity.Id);
+            }
+            if (!taskDetails.Task.IsCompleted) return;
+
+            const message = taskDetails.Task.State === TaskState.Success ? "completed successfully" : "did not complete successfully";
+            this.logger.info?.(`${task.type}${this.getProgressContext(task)} ${message}`);
+            task.successful = taskDetails.Task.State === TaskState.Success;
+            results.push(task);
+        } catch (e) {
+            const error = e instanceof Error ? e : undefined;
+            this.logger.error?.(`Failed to fetch details on ${task}: ${e}`, error);
+        }
+    }
+
+    getProgressContext(task: WaitExecutionResult): string {
+        return `${task.environmentName ? ` to environment '${task.environmentName}'` : ""}${task.tenantName ? ` for tenant '${task.tenantName}'` : ""}`;
+    }
+
+    logWithCategory(message: string, category?: ActivityLogEntryCategory) {
+        switch (category) {
+            case "Error":
+            case "Fatal":
+                this.logger.error?.(message, undefined);
+                break;
+            case "Warning":
+                this.logger.warn?.(message);
+                break;
+            default:
+                this.logger.info?.(message);
+        }
+    }
+
+    logWithStatus(message: string, status?: ActivityStatus) {
+        switch (status) {
+            case "Failed":
+                this.logger.error?.(message, undefined);
+                break;
+            case "SuccessWithWarning":
+                this.logger.warn?.(message);
+                break;
+            default:
+                this.logger.info?.(message);
+        }
+    }
+}
+
+function isComplete(element: ActivityElement) {
+    return element.Status != "Pending" && element.Status != "Running";
 }

source/vsts.md

@@ -296,13 +296,14 @@ From version 6, the deploy release step is split into two seperate functions for
 
 #### 📥 Inputs
 
-| Name                       | Description                                                                      |
-| :------------------------- | :------------------------------------------------------------------------------- |
-| `OctoConnectedServiceName` | **Required.** Name of the Octopus Server connection.                             |
-| `Space`                    | **Required.** The Octopus space the release is in.                               |
-| `Step`                     | **Required** The name of the step that queued the deployment/runbook run.        |
-| `PollingInterval`          | How frequently, in seconds, to check the status. (Default: 10s)                  |
-| `TimeoutAfter`             | Duration, in seconds, to allow for completion before timing out. (Default: 600s) |
+| Name                          | Description                                                                       |
+| :---------------------------- | :-------------------------------------------------------------------------------- |
+| `OctoConnectedServiceName`    | **Required.** Name of the Octopus Server connection.                              |
+| `Space`                       | **Required.** The Octopus space the release is in.                                |
+| `Step`                        | **Required** The name of the step that queued the deployment/runbook run.         |
+| `PollingInterval`             | How frequently, in seconds, to check the status. (Default: 10s)                   |
+| `TimeoutAfter`                | Duration, in seconds, to allow for completion before timing out. (Default: 600s)  |
+| `ShowProgress`                | Log Octopus task outputs to Azure DevOps output. (Default: false)                 |
 
 The `Step` input parameter needs to be set to the `name` of the deployment step that generated the server tasks to be waited. In the classic-pipeline mode, you need to set the reference name on the `server_tasks` output variable and use that value for `Step`.