Merge pull request #513 from dhadka/dhadka/download-progress

Display download progress when using Azure Storage SDK

packages/cache/RELEASES.md

@@ -12,5 +12,6 @@
 
 ### 1.0.0
 - Downloads Azure-hosted caches using the Azure SDK for speed and reliability
+- Displays download progress
 - Includes changes that break compatibility with earlier versions, including:
   - `retry`, `retryTypedResponse`, and `retryHttpClientResponse` moved from `cacheHttpClient` to `requestUtils`

packages/cache/__tests__/downloadUtils.test.ts

@@ -0,0 +1,159 @@
+import * as core from '@actions/core'
+import {DownloadProgress} from '../src/internal/downloadUtils'
+
+test('download progress tracked correctly', () => {
+  const progress = new DownloadProgress(1000)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(0)
+  expect(progress.segmentIndex).toBe(0)
+  expect(progress.segmentOffset).toBe(0)
+  expect(progress.segmentSize).toBe(0)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(0)
+  expect(progress.isDone()).toBe(false)
+
+  progress.nextSegment(500)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(0)
+  expect(progress.segmentIndex).toBe(1)
+  expect(progress.segmentOffset).toBe(0)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(0)
+  expect(progress.isDone()).toBe(false)
+
+  progress.setReceivedBytes(250)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(250)
+  expect(progress.segmentIndex).toBe(1)
+  expect(progress.segmentOffset).toBe(0)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(250)
+  expect(progress.isDone()).toBe(false)
+
+  progress.setReceivedBytes(500)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(500)
+  expect(progress.segmentIndex).toBe(1)
+  expect(progress.segmentOffset).toBe(0)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(500)
+  expect(progress.isDone()).toBe(false)
+
+  progress.nextSegment(500)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(0)
+  expect(progress.segmentIndex).toBe(2)
+  expect(progress.segmentOffset).toBe(500)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(500)
+  expect(progress.isDone()).toBe(false)
+
+  progress.setReceivedBytes(250)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(250)
+  expect(progress.segmentIndex).toBe(2)
+  expect(progress.segmentOffset).toBe(500)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(750)
+  expect(progress.isDone()).toBe(false)
+
+  progress.setReceivedBytes(500)
+
+  expect(progress.contentLength).toBe(1000)
+  expect(progress.receivedBytes).toBe(500)
+  expect(progress.segmentIndex).toBe(2)
+  expect(progress.segmentOffset).toBe(500)
+  expect(progress.segmentSize).toBe(500)
+  expect(progress.displayedComplete).toBe(false)
+  expect(progress.timeoutHandle).toBeUndefined()
+  expect(progress.getTransferredBytes()).toBe(1000)
+  expect(progress.isDone()).toBe(true)
+})
+
+test('display timer works correctly', () => {
+  const progress = new DownloadProgress(1000)
+
+  const infoMock = jest.spyOn(core, 'info')
+  infoMock.mockImplementation(() => {})
+
+  const check = (): void => {
+    expect(infoMock).toHaveBeenLastCalledWith(
+      expect.stringContaining('Received 500 of 1000')
+    )
+  }
+
+  // Validate no further updates are displayed after stopping the timer.
+  const test2 = (): void => {
+    check()
+    expect(progress.timeoutHandle).toBeUndefined()
+  }
+
+  // Validate the progress is displayed, stop the timer, and call test2.
+  const test1 = (): void => {
+    check()
+
+    progress.stopDisplayTimer()
+    progress.setReceivedBytes(1000)
+
+    setTimeout(() => test2(), 100)
+  }
+
+  // Start the timer, update the received bytes, and call test1.
+  const start = (): void => {
+    progress.startDisplayTimer(10)
+    expect(progress.timeoutHandle).toBeDefined()
+
+    progress.setReceivedBytes(500)
+
+    setTimeout(() => test1(), 100)
+  }
+
+  start()
+})
+
+test('display does not print completed line twice', () => {
+  const progress = new DownloadProgress(1000)
+
+  const infoMock = jest.spyOn(core, 'info')
+  infoMock.mockImplementation(() => {})
+
+  progress.display()
+
+  expect(progress.displayedComplete).toBe(false)
+  expect(infoMock).toHaveBeenCalledTimes(1)
+
+  progress.nextSegment(1000)
+  progress.setReceivedBytes(500)
+  progress.display()
+
+  expect(progress.displayedComplete).toBe(false)
+  expect(infoMock).toHaveBeenCalledTimes(2)
+
+  progress.setReceivedBytes(1000)
+  progress.display()
+
+  expect(progress.displayedComplete).toBe(true)
+  expect(infoMock).toHaveBeenCalledTimes(3)
+
+  progress.display()
+
+  expect(progress.displayedComplete).toBe(true)
+  expect(infoMock).toHaveBeenCalledTimes(3)
+})

packages/cache/package-lock.json

@@ -1,6 +1,6 @@
 {
   "name": "@actions/cache",
-  "version": "0.3.0",
+  "version": "1.0.0",
   "lockfileVersion": 1,
   "requires": true,
   "dependencies": {
@@ -129,6 +129,45 @@
         "tslib": "^1.9.3"
       }
     },
+    "@azure/ms-rest-js": {
+      "version": "2.0.7",
+      "resolved": "https://registry.npmjs.org/@azure/ms-rest-js/-/ms-rest-js-2.0.7.tgz",
+      "integrity": "sha512-rQpNxDhyOIyS4E+4sUCBMvjrtbNwB32wH06cC2SFoQM4TR29bIKaTlIC1tMe0K07w9c5tNk/2uUHs6/ld/Z3+A==",
+      "requires": {
+        "@types/node-fetch": "^2.3.7",
+        "@types/tunnel": "0.0.1",
+        "abort-controller": "^3.0.0",
+        "form-data": "^2.5.0",
+        "node-fetch": "^2.6.0",
+        "tough-cookie": "^3.0.1",
+        "tslib": "^1.10.0",
+        "tunnel": "0.0.6",
+        "uuid": "^3.3.2",
+        "xml2js": "^0.4.19"
+      },
+      "dependencies": {
+        "form-data": {
+          "version": "2.5.1",
+          "resolved": "https://registry.npmjs.org/form-data/-/form-data-2.5.1.tgz",
+          "integrity": "sha512-m21N3WOmEEURgk6B9GLOE4RuWOFf28Lhh9qGYeNlGq4VDXUlJy2th2slBNU8Gp8EzloYZOibZJ7t5ecIrFSjVA==",
+          "requires": {
+            "asynckit": "^0.4.0",
+            "combined-stream": "^1.0.6",
+            "mime-types": "^2.1.12"
+          }
+        },
+        "tough-cookie": {
+          "version": "3.0.1",
+          "resolved": "https://registry.npmjs.org/tough-cookie/-/tough-cookie-3.0.1.tgz",
+          "integrity": "sha512-yQyJ0u4pZsv9D4clxO69OEjLWYw+jbgspjTue4lTQZLfV0c5l1VmK2y1JK8E9ahdpltPOaAThPcp5nKPUgSnsg==",
+          "requires": {
+            "ip-regex": "^2.1.0",
+            "psl": "^1.1.28",
+            "punycode": "^2.1.1"
+          }
+        }
+      }
+    },
     "@azure/storage-blob": {
       "version": "12.1.2",
       "resolved": "https://registry.npmjs.org/@azure/storage-blob/-/storage-blob-12.1.2.tgz",
@@ -177,6 +216,28 @@
         "form-data": "^3.0.0"
       }
     },
+    "@types/prop-types": {
+      "version": "15.7.3",
+      "resolved": "https://registry.npmjs.org/@types/prop-types/-/prop-types-15.7.3.tgz",
+      "integrity": "sha512-KfRL3PuHmqQLOG+2tGpRO26Ctg+Cq1E01D2DMriKEATHgWLfeNDmq9e29Q9WIky0dQ3NPkd1mzYH8Lm936Z9qw=="
+    },
+    "@types/react": {
+      "version": "16.9.38",
+      "resolved": "https://registry.npmjs.org/@types/react/-/react-16.9.38.tgz",
+      "integrity": "sha512-pHAeZbjjNRa/hxyNuLrvbxhhnKyKNiLC6I5fRF2Zr/t/S6zS41MiyzH4+c+1I9vVfvuRt1VS2Lodjr4ZWnxrdA==",
+      "requires": {
+        "@types/prop-types": "*",
+        "csstype": "^2.2.0"
+      }
+    },
+    "@types/react-native": {
+      "version": "0.62.13",
+      "resolved": "https://registry.npmjs.org/@types/react-native/-/react-native-0.62.13.tgz",
+      "integrity": "sha512-hs4/tSABhcJx+J8pZhVoXHrOQD89WFmbs8QiDLNSA9zNrD46pityAuBWuwk1aMjPk9I3vC5ewkJroVRHgRIfdg==",
+      "requires": {
+        "@types/react": "*"
+      }
+    },
     "@types/semver": {
       "version": "6.2.1",
       "resolved": "https://registry.npmjs.org/@types/semver/-/semver-6.2.1.tgz",
@@ -197,6 +258,14 @@
       "integrity": "sha512-XDwyIlt/47l2kWLTzw/mtrpLdB+GPSskR2n/PIcPn+VYhVO77rGhRncIR5GPU0KRzXuqkDO+J5qqrG0Y8P6jzQ==",
       "dev": true
     },
+    "abort-controller": {
+      "version": "3.0.0",
+      "resolved": "https://registry.npmjs.org/abort-controller/-/abort-controller-3.0.0.tgz",
+      "integrity": "sha512-h8lQ8tacZYnR3vNQTgibj+tODHI5/+l06Au2Pcriv/Gmet0eaj4TwWH41sO9wnHDiQsEj19q0drzdWdeAHtweg==",
+      "requires": {
+        "event-target-shim": "^5.0.0"
+      }
+    },
     "asynckit": {
       "version": "0.4.0",
       "resolved": "https://registry.npmjs.org/asynckit/-/asynckit-0.4.0.tgz",
@@ -229,11 +298,21 @@
       "resolved": "https://registry.npmjs.org/concat-map/-/concat-map-0.0.1.tgz",
       "integrity": "sha1-2Klr13/Wjfd5OnMDajug1UBdR3s="
     },
+    "csstype": {
+      "version": "2.6.10",
+      "resolved": "https://registry.npmjs.org/csstype/-/csstype-2.6.10.tgz",
+      "integrity": "sha512-D34BqZU4cIlMCY93rZHbrq9pjTAQJ3U8S8rfBqjwHxkGPThWFjzZDQpgMJY0QViLxth6ZKYiwFBo14RdN44U/w=="
+    },
     "delayed-stream": {
       "version": "1.0.0",
       "resolved": "https://registry.npmjs.org/delayed-stream/-/delayed-stream-1.0.0.tgz",
       "integrity": "sha1-3zrhmayt+31ECqrgsp4icrJOxhk="
     },
+    "event-target-shim": {
+      "version": "5.0.1",
+      "resolved": "https://registry.npmjs.org/event-target-shim/-/event-target-shim-5.0.1.tgz",
+      "integrity": "sha512-i/2XbnSz/uxRCU6+NdVJgKWDTM427+MqYbkQzD321DuCQJUqOuJKIA0IM2+W2xtYHdKOmZ4dR6fExsd4SXL+WQ=="
+    },
     "events": {
       "version": "3.1.0",
       "resolved": "https://registry.npmjs.org/events/-/events-3.1.0.tgz",
@@ -249,6 +328,11 @@
         "mime-types": "^2.1.12"
       }
     },
+    "ip-regex": {
+      "version": "2.1.0",
+      "resolved": "https://registry.npmjs.org/ip-regex/-/ip-regex-2.1.0.tgz",
+      "integrity": "sha1-+ni/XS5pE8kRzp+BnuUUa7bYROk="
+    },
     "mime-db": {
       "version": "1.44.0",
       "resolved": "https://registry.npmjs.org/mime-db/-/mime-db-1.44.0.tgz",

packages/cache/package.json

@@ -42,6 +42,7 @@
     "@actions/glob": "^0.1.0",
     "@actions/http-client": "^1.0.8",
     "@actions/io": "^1.0.1",
+    "@azure/ms-rest-js": "^2.0.7",
     "@azure/storage-blob": "^12.1.2",
     "semver": "^6.1.0",
     "uuid": "^3.3.3"

packages/cache/src/internal/downloadUtils.ts

@@ -2,6 +2,7 @@ import * as core from '@actions/core'
 import {HttpClient} from '@actions/http-client'
 import {IHttpClientResponse} from '@actions/http-client/interfaces'
 import {BlockBlobClient} from '@azure/storage-blob'
+import {TransferProgressEvent} from '@azure/ms-rest-js'
 import * as buffer from 'buffer'
 import * as fs from 'fs'
 import * as stream from 'stream'
@@ -26,6 +27,139 @@ async function pipeResponseToStream(
   await pipeline(response.message, output)
 }
 
+/**
+ * Class for tracking the download state and displaying stats.
+ */
+export class DownloadProgress {
+  contentLength: number
+  segmentIndex: number
+  segmentSize: number
+  segmentOffset: number
+  receivedBytes: number
+  startTime: number
+  displayedComplete: boolean
+  timeoutHandle?: ReturnType<typeof setTimeout>
+
+  constructor(contentLength: number) {
+    this.contentLength = contentLength
+    this.segmentIndex = 0
+    this.segmentSize = 0
+    this.segmentOffset = 0
+    this.receivedBytes = 0
+    this.displayedComplete = false
+    this.startTime = Date.now()
+  }
+
+  /**
+   * Progress to the next segment. Only call this method when the previous segment
+   * is complete.
+   *
+   * @param segmentSize the length of the next segment
+   */
+  nextSegment(segmentSize: number): void {
+    this.segmentOffset = this.segmentOffset + this.segmentSize
+    this.segmentIndex = this.segmentIndex + 1
+    this.segmentSize = segmentSize
+    this.receivedBytes = 0
+
+    core.debug(
+      `Downloading segment at offset ${this.segmentOffset} with length ${this.segmentSize}...`
+    )
+  }
+
+  /**
+   * Sets the number of bytes received for the current segment.
+   *
+   * @param receivedBytes the number of bytes received
+   */
+  setReceivedBytes(receivedBytes: number): void {
+    this.receivedBytes = receivedBytes
+  }
+
+  /**
+   * Returns the total number of bytes transferred.
+   */
+  getTransferredBytes(): number {
+    return this.segmentOffset + this.receivedBytes
+  }
+
+  /**
+   * Returns true if the download is complete.
+   */
+  isDone(): boolean {
+    return this.getTransferredBytes() === this.contentLength
+  }
+
+  /**
+   * Prints the current download stats. Once the download completes, this will print one
+   * last line and then stop.
+   */
+  display(): void {
+    if (this.displayedComplete) {
+      return
+    }
+
+    const transferredBytes = this.segmentOffset + this.receivedBytes
+    const percentage = (100 * (transferredBytes / this.contentLength)).toFixed(
+      1
+    )
+    const elapsedTime = Date.now() - this.startTime
+    const downloadSpeed = (
+      transferredBytes /
+      (1024 * 1024) /
+      (elapsedTime / 1000)
+    ).toFixed(1)
+
+    core.info(
+      `Received ${transferredBytes} of ${this.contentLength} (${percentage}%), ${downloadSpeed} MBs/sec`
+    )
+
+    if (this.isDone()) {
+      this.displayedComplete = true
+    }
+  }
+
+  /**
+   * Returns a function used to handle TransferProgressEvents.
+   */
+  onProgress(): (progress: TransferProgressEvent) => void {
+    return (progress: TransferProgressEvent) => {
+      this.setReceivedBytes(progress.loadedBytes)
+    }
+  }
+
+  /**
+   * Starts the timer that displays the stats.
+   *
+   * @param delayInMs the delay between each write
+   */
+  startDisplayTimer(delayInMs: number = 1000): void {
+    const displayCallback = (): void => {
+      this.display()
+
+      if (!this.isDone()) {
+        this.timeoutHandle = setTimeout(displayCallback, delayInMs)
+      }
+    }
+
+    this.timeoutHandle = setTimeout(displayCallback, delayInMs)
+  }
+
+  /**
+   * Stops the timer that displays the stats. As this typically indicates the download
+   * is complete, this will display one last line, unless the last line has already
+   * been written.
+   */
+  stopDisplayTimer(): void {
+    if (this.timeoutHandle) {
+      clearTimeout(this.timeoutHandle)
+      this.timeoutHandle = undefined
+    }
+
+    this.display()
+  }
+}
+
 /**
  * Download the cache using the Actions toolkit http-client
  *
@@ -107,27 +241,34 @@ export async function downloadCacheStorageSDK(
     // If the file exceeds the buffer maximum length (~1 GB on 32-bit systems and ~2 GB
     // on 64-bit systems), split the download into multiple segments
     const maxSegmentSize = buffer.constants.MAX_LENGTH
-    let offset = 0
+    const downloadProgress = new DownloadProgress(contentLength)
 
     const fd = fs.openSync(archivePath, 'w')
 
     try {
-      while (offset < contentLength) {
+      downloadProgress.startDisplayTimer()
-        const segmentSize = Math.min(maxSegmentSize, contentLength - offset)
+
-        core.debug(
+      while (!downloadProgress.isDone()) {
-          `Downloading segment at offset ${offset} with length ${segmentSize}...`
+        const segmentSize = Math.min(
+          maxSegmentSize,
+          contentLength - downloadProgress.segmentOffset
         )
 
-        const result = await client.downloadToBuffer(offset, segmentSize, {
+        downloadProgress.nextSegment(segmentSize)
-          concurrency: options.downloadConcurrency
+
-        })
+        const result = await client.downloadToBuffer(
+          downloadProgress.segmentOffset,
+          segmentSize,
+          {
+            concurrency: options.downloadConcurrency,
+            onProgress: downloadProgress.onProgress()
+          }
+        )
 
         fs.writeFileSync(fd, result)
-
-        core.debug(`Finished segment at offset ${offset}`)
-        offset += segmentSize
       }
     } finally {
+      downloadProgress.stopDisplayTimer()
       fs.closeSync(fd)
     }
   }

packages/cache/tsconfig.json

@@ -3,7 +3,8 @@
   "compilerOptions": {
     "baseUrl": "./",
     "outDir": "./lib",
-    "rootDir": "./src"
+    "rootDir": "./src",
+    "lib": ["es6", "dom"]
   },
   "include": [
     "./src"