Fix issues surrounding initial web server load. (#4509)

- Clean up watcher behaviors.

ci/dev/watch.ts

@@ -1,140 +1,207 @@
-import * as cp from "child_process"
+import { spawn, fork, ChildProcess } from "child_process"
+import del from "del"
+import { promises as fs } from "fs"
 import * as path from "path"
-import { onLine } from "../../src/node/util"
+import { CompilationStats, onLine, OnLineCallback, VSCodeCompileStatus } from "../../src/node/util"
+
+interface DevelopmentCompilers {
+  [key: string]: ChildProcess | undefined
+  vscode: ChildProcess
+  vscodeWebExtensions: ChildProcess
+  codeServer: ChildProcess
+  plugins: ChildProcess | undefined
+}
+
+class Watcher {
+  private rootPath = path.resolve(process.cwd())
+  private readonly paths = {
+    /** Path to uncompiled VS Code source. */
+    vscodeDir: path.join(this.rootPath, "vendor", "modules", "code-oss-dev"),
+    compilationStatsFile: path.join(this.rootPath, "out", "watcher.json"),
+    pluginDir: process.env.PLUGIN_DIR,
+  }
+
+  //#region Web Server
+
+  /** Development web server. */
+  private webServer: ChildProcess | undefined
+
+  private reloadWebServer = (): void => {
+    if (this.webServer) {
+      this.webServer.kill()
+    }
+
+    // Pass CLI args, save for `node` and the initial script name.
+    const args = process.argv.slice(2)
+    this.webServer = fork(path.join(this.rootPath, "out/node/entry.js"), args)
+    const { pid } = this.webServer
+
+    this.webServer.on("exit", () => console.log("[Code Server]", `Web process ${pid} exited`))
+
+    console.log("\n[Code Server]", `Spawned web server process ${pid}`)
+  }
+
+  //#endregion
+
+  //#region Compilers
+
+  private readonly compilers: DevelopmentCompilers = {
+    codeServer: spawn("tsc", ["--watch", "--pretty", "--preserveWatchOutput"], { cwd: this.rootPath }),
+    vscode: spawn("yarn", ["watch"], { cwd: this.paths.vscodeDir }),
+    vscodeWebExtensions: spawn("yarn", ["watch-web"], { cwd: this.paths.vscodeDir }),
+    plugins: this.paths.pluginDir ? spawn("yarn", ["build", "--watch"], { cwd: this.paths.pluginDir }) : undefined,
+  }
+
+  private vscodeCompileStatus = VSCodeCompileStatus.Loading
+
+  public async initialize(): Promise<void> {
+    for (const event of ["SIGINT", "SIGTERM"]) {
+      process.on(event, () => this.dispose(0))
+    }
+
+    if (!this.hasVerboseLogging) {
+      console.log("\n[Watcher]", "Compiler logs will be minimal. Pass --log to show all output.")
+    }
+
+    this.cleanFiles()
+
+    for (const [processName, devProcess] of Object.entries(this.compilers)) {
+      if (!devProcess) continue
+
+      devProcess.on("exit", (code) => {
+        this.log(`[${processName}]`, "Terminated unexpectedly")
+        this.dispose(code)
+      })
+
+      if (devProcess.stderr) {
+        devProcess.stderr.on("data", (d: string | Uint8Array) => process.stderr.write(d))
+      }
+    }
+
+    onLine(this.compilers.vscode, this.parseVSCodeLine)
+    onLine(this.compilers.codeServer, this.parseCodeServerLine)
+
+    if (this.compilers.plugins) {
+      onLine(this.compilers.plugins, this.parsePluginLine)
+    }
+  }
+
+  //#endregion
+
+  //#region Line Parsers
+
+  private parseVSCodeLine: OnLineCallback = (strippedLine, originalLine) => {
+    if (!strippedLine.includes("watch-extensions") || this.hasVerboseLogging) {
+      console.log("[VS Code]", originalLine)
+    }
+
+    switch (this.vscodeCompileStatus) {
+      case VSCodeCompileStatus.Loading:
+        // Wait for watch-client since "Finished compilation" will appear multiple
+        // times before the client starts building.
+        if (strippedLine.includes("Starting 'watch-client'")) {
+          console.log("[VS Code] 🚧 Compiling 🚧", "(This may take a moment!)")
+          this.vscodeCompileStatus = VSCodeCompileStatus.Compiling
+        }
+        break
+      case VSCodeCompileStatus.Compiling:
+        if (strippedLine.includes("Finished compilation")) {
+          console.log("[VS Code] ✨ Finished compiling! ✨", "(Refresh your web browser ♻️)")
+          this.vscodeCompileStatus = VSCodeCompileStatus.Compiled
+
+          this.emitCompilationStats()
+          this.reloadWebServer()
+        }
+        break
+      case VSCodeCompileStatus.Compiled:
+        console.log("[VS Code] 🔔 Finished recompiling! 🔔", "(Refresh your web browser ♻️)")
+        this.emitCompilationStats()
+        this.reloadWebServer()
+        break
+    }
+  }
+
+  private parseCodeServerLine: OnLineCallback = (strippedLine, originalLine) => {
+    if (!strippedLine.length) return
+
+    console.log("[Compiler][Code Server]", originalLine)
+
+    if (strippedLine.includes("Watching for file changes")) {
+      console.log("[Compiler][Code Server]", "Finished compiling!", "(Refresh your web browser ♻️)")
+
+      this.reloadWebServer()
+    }
+  }
+
+  private parsePluginLine: OnLineCallback = (strippedLine, originalLine) => {
+    if (!strippedLine.length) return
+
+    console.log("[Compiler][Plugin]", originalLine)
+
+    if (strippedLine.includes("Watching for file changes...")) {
+      this.reloadWebServer()
+    }
+  }
+
+  //#endregion
+
+  //#region Utilities
+
+  /**
+   * Cleans files from previous builds.
+   */
+  private cleanFiles(): Promise<string[]> {
+    console.log("[Watcher]", "Cleaning files from previous builds...")
+
+    return del([
+      "out/**/*",
+      // Included because the cache can sometimes enter bad state when debugging compiled files.
+      ".cache/**/*",
+    ])
+  }
+
+  /**
+   * Emits a file containing compilation data.
+   * This is especially useful when Express needs to determine if VS Code is still compiling.
+   */
+  private emitCompilationStats(): Promise<void> {
+    const stats: CompilationStats = {
+      status: this.vscodeCompileStatus,
+      lastCompiledAt: new Date(),
+    }
+
+    this.log("Writing watcher stats...")
+    return fs.writeFile(this.paths.compilationStatsFile, JSON.stringify(stats, null, 2))
+  }
+
+  private log(...entries: string[]) {
+    process.stdout.write(entries.join(" "))
+  }
+
+  private dispose(code: number | null): void {
+    for (const [processName, devProcess] of Object.entries(this.compilers)) {
+      this.log(`[${processName}]`, "Killing...\n")
+      devProcess?.removeAllListeners()
+      devProcess?.kill()
+    }
+    process.exit(typeof code === "number" ? code : 0)
+  }
+
+  private get hasVerboseLogging() {
+    return process.argv.includes("--log")
+  }
+
+  //#endregion
+}
 
 async function main(): Promise<void> {
   try {
     const watcher = new Watcher()
-    await watcher.watch()
+    await watcher.initialize()
   } catch (error: any) {
     console.error(error.message)
     process.exit(1)
   }
 }
 
-class Watcher {
-  private readonly rootPath = path.resolve(__dirname, "../..")
-  private readonly vscodeSourcePath = path.join(this.rootPath, "vendor/modules/code-oss-dev")
-
-  private static log(message: string, skipNewline = false): void {
-    process.stdout.write(message)
-    if (!skipNewline) {
-      process.stdout.write("\n")
-    }
-  }
-
-  public async watch(): Promise<void> {
-    let server: cp.ChildProcess | undefined
-    const restartServer = (): void => {
-      if (server) {
-        server.kill()
-      }
-      const s = cp.fork(path.join(this.rootPath, "out/node/entry.js"), process.argv.slice(2))
-      console.log(`[server] spawned process ${s.pid}`)
-      s.on("exit", () => console.log(`[server] process ${s.pid} exited`))
-      server = s
-    }
-
-    const vscode = cp.spawn("yarn", ["watch"], { cwd: this.vscodeSourcePath })
-
-    const vscodeWebExtensions = cp.spawn("yarn", ["watch-web"], { cwd: this.vscodeSourcePath })
-
-    const tsc = cp.spawn("tsc", ["--watch", "--pretty", "--preserveWatchOutput"], { cwd: this.rootPath })
-    const plugin = process.env.PLUGIN_DIR
-      ? cp.spawn("yarn", ["build", "--watch"], { cwd: process.env.PLUGIN_DIR })
-      : undefined
-
-    const cleanup = (code?: number | null): void => {
-      Watcher.log("killing vs code watcher")
-      vscode.removeAllListeners()
-      vscode.kill()
-
-      Watcher.log("killing vs code web extension watcher")
-      vscodeWebExtensions.removeAllListeners()
-      vscodeWebExtensions.kill()
-
-      Watcher.log("killing tsc")
-      tsc.removeAllListeners()
-      tsc.kill()
-
-      if (plugin) {
-        Watcher.log("killing plugin")
-        plugin.removeAllListeners()
-        plugin.kill()
-      }
-
-      if (server) {
-        Watcher.log("killing server")
-        server.removeAllListeners()
-        server.kill()
-      }
-
-      Watcher.log("killing watch")
-      process.exit(code || 0)
-    }
-
-    process.on("SIGINT", () => cleanup())
-    process.on("SIGTERM", () => cleanup())
-
-    vscode.on("exit", (code) => {
-      Watcher.log("vs code watcher terminated unexpectedly")
-      cleanup(code)
-    })
-
-    vscodeWebExtensions.on("exit", (code) => {
-      Watcher.log("vs code extension watcher terminated unexpectedly")
-      cleanup(code)
-    })
-
-    tsc.on("exit", (code) => {
-      Watcher.log("tsc terminated unexpectedly")
-      cleanup(code)
-    })
-
-    if (plugin) {
-      plugin.on("exit", (code) => {
-        Watcher.log("plugin terminated unexpectedly")
-        cleanup(code)
-      })
-    }
-
-    vscodeWebExtensions.stderr.on("data", (d) => process.stderr.write(d))
-    vscode.stderr.on("data", (d) => process.stderr.write(d))
-    tsc.stderr.on("data", (d) => process.stderr.write(d))
-
-    if (plugin) {
-      plugin.stderr.on("data", (d) => process.stderr.write(d))
-    }
-
-    onLine(vscode, (line, original) => {
-      console.log("[vscode]", original)
-      if (line.includes("Finished compilation")) {
-        restartServer()
-      }
-    })
-
-    onLine(tsc, (line, original) => {
-      // tsc outputs blank lines; skip them.
-      if (line !== "") {
-        console.log("[tsc]", original)
-      }
-      if (line.includes("Watching for file changes")) {
-        restartServer()
-      }
-    })
-
-    if (plugin) {
-      onLine(plugin, (line, original) => {
-        // tsc outputs blank lines; skip them.
-        if (line !== "") {
-          console.log("[plugin]", original)
-        }
-        if (line.includes("Watching for file changes")) {
-          restartServer()
-        }
-      })
-    }
-  }
-}
-
 main()

package.json

@@ -52,6 +52,7 @@
     "@typescript-eslint/parser": "^5.0.0",
     "audit-ci": "^5.0.0",
     "codecov": "^3.8.3",
+    "del": "^6.0.0",
     "doctoc": "^2.0.0",
     "eslint": "^7.7.0",
     "eslint-config-prettier": "^8.1.0",

src/node/routes/vscode.ts

@@ -4,7 +4,7 @@ import { WebsocketRequest } from "../../../typings/pluginapi"
 import { logError } from "../../common/util"
 import { isDevMode } from "../constants"
 import { ensureAuthenticated, authenticated, redirect } from "../http"
-import { loadAMDModule } from "../util"
+import { loadAMDModule, readCompilationStats } from "../util"
 import { Router as WsRouter } from "../wsRouter"
 import { errorHandler } from "./errors"
 
@@ -40,7 +40,6 @@ export class CodeServerRouteWrapper {
       if (error instanceof Error && ["EntryNotFound", "FileNotFound", "HttpError"].includes(error.message)) {
         next()
       }
-
       errorHandler(error, req, res, next)
     }
 
@@ -62,9 +61,21 @@ export class CodeServerRouteWrapper {
    */
   private ensureCodeServerLoaded: express.Handler = async (req, _res, next) => {
     if (this._codeServerMain) {
+      // Already loaded...
       return next()
     }
 
+    if (isDevMode) {
+      // Is the development mode file watcher still busy?
+      const compileStats = await readCompilationStats()
+
+      if (!compileStats || !compileStats.lastCompiledAt) {
+        return next(new Error("VS Code may still be compiling..."))
+      }
+    }
+
+    // Create the server...
+
     const { args } = req
 
     /**
@@ -84,10 +95,7 @@ export class CodeServerRouteWrapper {
       })
     } catch (createServerError) {
       logError(logger, "CodeServerRouteWrapper", createServerError)
-
+      return next(createServerError)
-      const loggedError = isDevMode ? new Error("VS Code may still be compiling...") : createServerError
-
-      return next(loggedError)
     }
 
     return next()

src/node/util.ts

@@ -3,14 +3,15 @@ import * as argon2 from "argon2"
 import * as cp from "child_process"
 import * as crypto from "crypto"
 import envPaths from "env-paths"
-import { promises as fs } from "fs"
+import { promises as fs, Stats } from "fs"
 import * as net from "net"
 import * as os from "os"
 import * as path from "path"
 import safeCompare from "safe-compare"
 import * as util from "util"
 import xdgBasedir from "xdg-basedir"
-import { vsRootPath } from "./constants"
+import { logError } from "../common/util"
+import { isDevMode, rootPath, vsRootPath } from "./constants"
 
 export interface Paths {
   data: string
@@ -25,10 +26,11 @@ const pattern = [
 ].join("|")
 const re = new RegExp(pattern, "g")
 
+export type OnLineCallback = (strippedLine: string, originalLine: string) => void
 /**
  * Split stdout on newlines and strip ANSI codes.
  */
-export const onLine = (proc: cp.ChildProcess, callback: (strippedLine: string, originalLine: string) => void): void => {
+export const onLine = (proc: cp.ChildProcess, callback: OnLineCallback): void => {
   let buffer = ""
   if (!proc.stdout) {
     throw new Error("no stdout")
@@ -521,3 +523,41 @@ export const loadAMDModule = async <T>(amdPath: string, exportName: string): Pro
 
   return module[exportName] as T
 }
+
+export const enum VSCodeCompileStatus {
+  Loading = "Loading",
+  Compiling = "Compiling",
+  Compiled = "Compiled",
+}
+
+export interface CompilationStats {
+  status: VSCodeCompileStatus
+  lastCompiledAt: Date
+}
+
+export const readCompilationStats = async (): Promise<null | CompilationStats> => {
+  if (!isDevMode) {
+    throw new Error("Compilation stats are only present in development")
+  }
+
+  const filePath = path.join(rootPath, "out/watcher.json")
+  let stat: Stats
+  try {
+    stat = await fs.stat(filePath)
+  } catch (error) {
+    return null
+  }
+
+  if (!stat.isFile()) {
+    return null
+  }
+
+  try {
+    const file = await fs.readFile(filePath)
+    return JSON.parse(file.toString("utf-8"))
+  } catch (error) {
+    logError(logger, "VS Code", error)
+  }
+
+  return null
+}

yarn.lock

@@ -615,6 +615,14 @@ agent-base@6, agent-base@^6.0.0, agent-base@^6.0.2:
   dependencies:
     debug "4"
 
+aggregate-error@^3.0.0:
+  version "3.1.0"
+  resolved "https://registry.yarnpkg.com/aggregate-error/-/aggregate-error-3.1.0.tgz#92670ff50f5359bdb7a3e0d40d0ec30c5737687a"
+  integrity sha512-4I7Td01quW/RpocfNayFdFVk1qSuoh0E7JrbRJ16nH01HhKFQ88INq9Sd+nd72zqRySlr9BmDA8xlEJ6vJMrYA==
+  dependencies:
+    clean-stack "^2.0.0"
+    indent-string "^4.0.0"
+
 ajv@^6.10.0, ajv@^6.12.4:
   version "6.12.6"
   resolved "https://registry.yarnpkg.com/ajv/-/ajv-6.12.6.tgz#baf5a62e802b07d977034586f8c3baf5adf26df4"
@@ -969,6 +977,11 @@ chownr@^2.0.0:
   resolved "https://registry.yarnpkg.com/chownr/-/chownr-2.0.0.tgz#15bfbe53d2eab4cf70f18a8cd68ebe5b3cb1dece"
   integrity sha512-bIomtDF5KGpdogkLd9VspvFzk9KfpyyGlS8YFVZl7TGPBHL5snIOnxeshwVgPteQ9b4Eydl+pVbIyE1DcvCWgQ==
 
+clean-stack@^2.0.0:
+  version "2.2.0"
+  resolved "https://registry.yarnpkg.com/clean-stack/-/clean-stack-2.2.0.tgz#ee8472dbb129e727b31e8a10a427dee9dfe4008b"
+  integrity sha512-4diC9HaTE+KRAMWhDhrGOECgWZxoevMc5TlkObMqNSsVU62PYzXZ/SMTjzyGAFF1YusgxGcSWTEXBhp0CPwQ1A==
+
 cliui@^7.0.2:
   version "7.0.4"
   resolved "https://registry.yarnpkg.com/cliui/-/cliui-7.0.4.tgz#a0265ee655476fc807aea9df3df8df7783808b4f"
@@ -1222,6 +1235,20 @@ degenerator@^3.0.1:
     esprima "^4.0.0"
     vm2 "^3.9.3"
 
+del@^6.0.0:
+  version "6.0.0"
+  resolved "https://registry.yarnpkg.com/del/-/del-6.0.0.tgz#0b40d0332cea743f1614f818be4feb717714c952"
+  integrity sha512-1shh9DQ23L16oXSZKB2JxpL7iMy2E0S9d517ptA1P8iw0alkPtQcrKH7ru31rYtKwF499HkTu+DRzq3TCKDFRQ==
+  dependencies:
+    globby "^11.0.1"
+    graceful-fs "^4.2.4"
+    is-glob "^4.0.1"
+    is-path-cwd "^2.2.0"
+    is-path-inside "^3.0.2"
+    p-map "^4.0.0"
+    rimraf "^3.0.2"
+    slash "^3.0.0"
+
 delegates@^1.0.0:
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/delegates/-/delegates-1.0.0.tgz#84c6e159b81904fdca59a0ef44cd870d31250f9a"
@@ -2037,10 +2064,10 @@ globals@^13.6.0, globals@^13.9.0:
   dependencies:
     type-fest "^0.20.2"
 
-globby@^11.0.3:
+globby@^11.0.1, globby@^11.0.4:
-  version "11.0.3"
+  version "11.0.4"
-  resolved "https://registry.yarnpkg.com/globby/-/globby-11.0.3.tgz#9b1f0cb523e171dd1ad8c7b2a9fb4b644b9593cb"
+  resolved "https://registry.yarnpkg.com/globby/-/globby-11.0.4.tgz#2cbaff77c2f2a62e71e9b2813a67b97a3a3001a5"
-  integrity sha512-ffdmosjA807y7+lA1NM0jELARVmYul/715xiILEjo3hBLPTcirgQNnXECn5g3mtR8TOLCVbkfua1Hpen25/Xcg==
+  integrity sha512-9O4MVG9ioZJ08ffbcyVYyLOJLk5JQ688pJ4eMGLpdWLHq/Wr1D9BlriLQyL0E+jbkuePVZXYFj47QM/v093wHg==
   dependencies:
     array-union "^2.1.0"
     dir-glob "^3.0.1"
@@ -2049,10 +2076,10 @@ globby@^11.0.3:
     merge2 "^1.3.0"
     slash "^3.0.0"
 
-globby@^11.0.4:
+globby@^11.0.3:
-  version "11.0.4"
+  version "11.0.3"
-  resolved "https://registry.yarnpkg.com/globby/-/globby-11.0.4.tgz#2cbaff77c2f2a62e71e9b2813a67b97a3a3001a5"
+  resolved "https://registry.yarnpkg.com/globby/-/globby-11.0.3.tgz#9b1f0cb523e171dd1ad8c7b2a9fb4b644b9593cb"
-  integrity sha512-9O4MVG9ioZJ08ffbcyVYyLOJLk5JQ688pJ4eMGLpdWLHq/Wr1D9BlriLQyL0E+jbkuePVZXYFj47QM/v093wHg==
+  integrity sha512-ffdmosjA807y7+lA1NM0jELARVmYul/715xiILEjo3hBLPTcirgQNnXECn5g3mtR8TOLCVbkfua1Hpen25/Xcg==
   dependencies:
     array-union "^2.1.0"
     dir-glob "^3.0.1"
@@ -2078,7 +2105,7 @@ graceful-fs@^4.1.2:
   resolved "https://registry.yarnpkg.com/graceful-fs/-/graceful-fs-4.2.6.tgz#ff040b2b0853b23c3d31027523706f1885d76bee"
   integrity sha512-nTnJ528pbqxYanhpDYsi4Rd8MAeaBA67+RZ10CM1m3bTAVFEDcd5AuA4a6W5YkGZ1iNXHzZz8T6TBKLeBuNriQ==
 
-graceful-fs@^4.1.6, graceful-fs@^4.2.0:
+graceful-fs@^4.1.6, graceful-fs@^4.2.0, graceful-fs@^4.2.4:
   version "4.2.8"
   resolved "https://registry.yarnpkg.com/graceful-fs/-/graceful-fs-4.2.8.tgz#e412b8d33f5e006593cbd3cee6df9f2cebbe802a"
   integrity sha512-qkIilPUYcNhJpd33n0GBXTB1MMPp14TxEsEs0pTrsSVucApsYzW5V+Q8Qxhik6KU3evy+qkAAowTByymK0avdg==
@@ -2426,6 +2453,16 @@ is-number@^7.0.0:
   resolved "https://registry.yarnpkg.com/is-number/-/is-number-7.0.0.tgz#7535345b896734d5f80c4d06c50955527a14f12b"
   integrity sha512-41Cifkg6e8TylSpdtTpeLVMqvSBEVzTttHvERD741+pnZ8ANv0004MRL43QKPDlK9cGvNp6NZWZUBlbGXYxxng==
 
+is-path-cwd@^2.2.0:
+  version "2.2.0"
+  resolved "https://registry.yarnpkg.com/is-path-cwd/-/is-path-cwd-2.2.0.tgz#67d43b82664a7b5191fd9119127eb300048a9fdb"
+  integrity sha512-w942bTcih8fdJPJmQHFzkS76NEP8Kzzvmw92cXsazb8intwLqPibPPdXf4ANdKV3rYMuuQYGIWtvz9JilB3NFQ==
+
+is-path-inside@^3.0.2:
+  version "3.0.3"
+  resolved "https://registry.yarnpkg.com/is-path-inside/-/is-path-inside-3.0.3.tgz#d231362e53a07ff2b0e0ea7fed049161ffd16283"
+  integrity sha512-Fd4gABb+ycGAmKou8eMftCupSir5lRxqf4aD/vd0cD2qc4HL07OjCeuHMr8Ro4CoMaeCKDB0/ECBOVWjTwUvPQ==
+
 is-plain-obj@^1.1.0:
   version "1.1.0"
   resolved "https://registry.yarnpkg.com/is-plain-obj/-/is-plain-obj-1.1.0.tgz#71a50c8429dfca773c92a390a4a03b39fcd51d3e"
@@ -3131,6 +3168,13 @@ p-locate@^4.1.0:
   dependencies:
     p-limit "^2.2.0"
 
+p-map@^4.0.0:
+  version "4.0.0"
+  resolved "https://registry.yarnpkg.com/p-map/-/p-map-4.0.0.tgz#bb2f95a5eda2ec168ec9274e06a747c3e2904d2b"
+  integrity sha512-/bjOqmgETBYB5BoEeGVea8dmvHb2m9GLy1E9W43yeyfP6QQCZGFNa+XRceJEuDB6zqr+gKpIAmlLebMpykw/MQ==
+  dependencies:
+    aggregate-error "^3.0.0"
+
 p-try@^1.0.0:
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/p-try/-/p-try-1.0.0.tgz#cbc79cdbaf8fd4228e13f621f2b1a237c1b207b3"