test: timestamped logs changes

Author: pieh

tests/netlify-deploy.ts

@@ -23,6 +23,7 @@ async function packNextRuntimeImpl() {
 }
 
 let packNextRuntimePromise: ReturnType<typeof packNextRuntimeImpl> | null = null
+let nextRuntimePacked = false
 function packNextRuntime() {
   if (!packNextRuntimePromise) {
     packNextRuntimePromise = packNextRuntimeImpl()
@@ -38,13 +39,35 @@ export class NextDeployInstance extends NextInstance {
   private _shouldDeleteDeploy: boolean = false
   private _isCurrentlyDeploying: boolean = false
   private _deployOutput: string = ''
+  private _setupStartTime = Date.now()
 
   public get buildId() {
     // get deployment ID via fetch since we can't access
     // build artifacts directly
     return this._buildId
   }
 
+  private packNextRuntime() {
+    if (!packNextRuntimePromise) {
+      if (!nextRuntimePacked) {
+        this._deployOutput += this.getTimestampPrefix() + 'Pack Next Runtime ...\n'
+      }
+      packNextRuntimePromise = packNextRuntimeImpl()
+      packNextRuntimePromise.then(() => {
+        nextRuntimePacked = true
+      })
+      if (!nextRuntimePacked) {
+        this._deployOutput += this.getTimestampPrefix() + 'Pack Next Runtime DONE\n'
+      }
+    }
+
+    return packNextRuntimePromise
+  }
+
+  private getTimestampPrefix() {
+    return `[${new Date().toISOString()}] (+${((Date.now() - this._setupStartTime) / 1000).toFixed(3)}s) `
+  }
+
   public async setup(parentSpan: Span) {
     if (process.env.SITE_URL && process.env.BUILD_ID) {
       require('console').log('Using existing deployment: ' + process.env.SITE_URL)
@@ -54,35 +77,36 @@ export class NextDeployInstance extends NextInstance {
       return
     }
 
-    let deployStartTime = Date.now()
-
     this._isCurrentlyDeploying = true
 
-    const setupStartTime = Date.now()
-
+    this._deployOutput += this.getTimestampPrefix() + 'Setting up test dir ...\n'
     // create the test site
     await super.createTestDir({ parentSpan, skipInstall: true })
+    this._deployOutput += this.getTimestampPrefix() + 'Setting up test dir DONE\n'
 
     // If the test fixture has node modules we need to move them aside then merge them in after
 
     const nodeModules = path.join(this.testDir, 'node_modules')
     const nodeModulesBak = `${nodeModules}.bak`
 
     if (fs.existsSync(nodeModules)) {
+      this._deployOutput += this.getTimestampPrefix() + 'Rename node_modules ...\n'
       await fs.rename(nodeModules, nodeModulesBak)
+      this._deployOutput += this.getTimestampPrefix() + 'Rename node_modules DONE\n'
     }
 
-    const { runtimePackageName, runtimePackageTarballPath } = await packNextRuntime()
+    const { runtimePackageName, runtimePackageTarballPath } = await this.packNextRuntime()
 
     const handleOutput = (chunk) => {
-      const timestampPrefix = `[${new Date().toISOString()}] (+${((Date.now() - deployStartTime) / 1000).toFixed(3)}s) `
+      const timestampPrefix = this.getTimestampPrefix()
 
       this._deployOutput +=
         (this._deployOutput === '' || this._deployOutput.endsWith('\n') ? timestampPrefix : '') +
         chunk.toString().replace(/\n(?=.)/gm, `\n${timestampPrefix}`)
     }
 
     // install dependencies
+    this._deployOutput += this.getTimestampPrefix() + 'Install dependencies ...\n'
     const installResPromise = execa('npm', ['i', runtimePackageTarballPath, '--legacy-peer-deps'], {
       cwd: this.testDir,
     })
@@ -91,14 +115,17 @@ export class NextDeployInstance extends NextInstance {
     installResPromise.stderr.on('data', handleOutput)
 
     await installResPromise
+    this._deployOutput += this.getTimestampPrefix() + 'Install dependencies DONE\n'
 
     if (fs.existsSync(nodeModulesBak)) {
       // move the contents of the fixture node_modules into the installed modules
+      this._deployOutput += this.getTimestampPrefix() + 'Move fixture node_modules ...\n'
       for (const file of await fs.readdir(nodeModulesBak)) {
         await fs.move(path.join(nodeModulesBak, file), path.join(nodeModules, file), {
           overwrite: true,
         })
       }
+      this._deployOutput += this.getTimestampPrefix() + 'Move fixture node_modules DONE\n'
     }
 
     // use next runtime package installed by the test runner
@@ -163,11 +190,44 @@ export class NextDeployInstance extends NextInstance {
       },
     )
 
+    this._deployOutput +=
+      this.getTimestampPrefix() + `Started deploy, PID: ${deployResPromise.pid}\n`
+    require('console').log(`Started deploy, PID: ${deployResPromise.pid}`)
+
     deployResPromise.stdout.on('data', handleOutput)
     deployResPromise.stderr.on('data', handleOutput)
 
+    deployResPromise.on('error', (err) => {
+      this._deployOutput += this.getTimestampPrefix() + `Error during deployment: ${err.message}\n`
+      require('console').error(`Error during deployment: ${err.message}`)
+    })
+
+    const deployHeartbeat = setInterval(() => {
+      this._deployOutput +=
+        this.getTimestampPrefix() + 'Waiting for netlify deploy process to finish ...\n'
+    }, 5000)
+
+    deployResPromise
+      .then((result) => {
+        require('console').log(`Netlify deploy process finished.`)
+        this._deployOutput += this.getTimestampPrefix() + 'Netlify deploy process finished.\n'
+      })
+      .catch((err) => {
+        require('console').log(`Netlify deploy process failed. ` + err)
+        this._deployOutput += this.getTimestampPrefix() + 'Netlify deploy process failed. ' + err
+      })
+      .finally(() => {
+        require('console').log(`Netlify deploy process finally.`)
+        this._deployOutput += this.getTimestampPrefix() + 'Netlify deploy process finally.\n'
+        clearInterval(deployHeartbeat)
+      })
+
     const deployRes = await deployResPromise
 
+    clearInterval(deployHeartbeat)
+
+    require('console').log(`Deploy finished. Processing output...`)
+
     if (deployRes.exitCode !== 0) {
       // clear deploy output to avoid printing it again in destroy()
       this._deployOutput = ''
@@ -210,7 +270,7 @@ export class NextDeployInstance extends NextInstance {
     ).trim()
 
     require('console').log(`Got buildId: ${this._buildId}`)
-    require('console').log(`Setup time: ${(Date.now() - setupStartTime) / 1000.0}s`)
+    require('console').log(`Setup time: ${(Date.now() - this._setupStartTime) / 1000.0}s`)
 
     this._isCurrentlyDeploying = false
   }