refactor: nicer logging when watching for changes / hot reloading

Closes #402 and #237

garden-service/src/cli/cli.ts

@@ -266,6 +266,10 @@ export class GardenCli {
       // entries (i.e. print new lines).
       const log = logger.placeholder()
 
+      // We pass a separate placeholder to the action method, so that commands can easily have a footer
+      // section in their log output.
+      const logFooter = logger.placeholder()
+
       const contextOpts: GardenOpts = { environmentName: env, log }
       if (command.noProject) {
         contextOpts.config = MOCK_CONFIG
@@ -285,6 +289,7 @@ export class GardenCli {
         result = await command.action({
           garden,
           log,
+          logFooter,
           args: parsedArgs,
           opts: parsedOpts,
         })

garden-service/src/commands/base.ts

@@ -210,6 +210,7 @@ export interface CommandParams<T extends Parameters = {}, U extends Parameters =
   opts: ParameterValues<U>
   garden: Garden
   log: LogEntry
+  logFooter?: LogEntry
 }
 
 export abstract class Command<T extends Parameters = {}, U extends Parameters = {}> {

garden-service/src/commands/build.ts

@@ -63,7 +63,7 @@ export class BuildCommand extends Command<BuildArguments, BuildOptions> {
   }
 
   async action(
-    { args, opts, garden, log }: CommandParams<BuildArguments, BuildOptions>,
+    { args, opts, garden, log, logFooter }: CommandParams<BuildArguments, BuildOptions>,
   ): Promise<CommandResult<TaskResults>> {
     await garden.clearBuilds()
 
@@ -74,6 +74,7 @@ export class BuildCommand extends Command<BuildArguments, BuildOptions> {
     const results = await processModules({
       garden,
       log,
+      logFooter,
       modules,
       watch: opts.watch,
       handler: async (module) => [new BuildTask({ garden, log, module, force: opts.force })],

garden-service/src/commands/deploy.ts

@@ -78,7 +78,7 @@ export class DeployCommand extends Command<Args, Opts> {
     logHeader({ log, emoji: "rocket", command: "Deploy" })
   }
 
-  async action({ garden, log, args, opts }: CommandParams<Args, Opts>): Promise<CommandResult<TaskResults>> {
+  async action({ garden, log, logFooter, args, opts }: CommandParams<Args, Opts>): Promise<CommandResult<TaskResults>> {
     const services = await garden.getServices(args.services)
 
     if (services.length === 0) {
@@ -105,6 +105,7 @@ export class DeployCommand extends Command<Args, Opts> {
     const results = await processServices({
       garden,
       log,
+      logFooter,
       services,
       watch,
       handler: async (module) => getTasksForModule({

garden-service/src/commands/dev.ts

@@ -73,12 +73,13 @@ export class DevCommand extends Command<Args, Opts> {
     log.info(chalk.gray.italic(`\nGood ${getGreetingTime()}! Let's get your environment wired up...\n`))
   }
 
-  async action({ garden, log, opts }: CommandParams<Args, Opts>): Promise<CommandResult> {
+  async action({ garden, log, logFooter, opts }: CommandParams<Args, Opts>): Promise<CommandResult> {
     await garden.actions.prepareEnvironment({ log })
 
     const modules = await garden.getModules()
 
     if (modules.length === 0) {
+      logFooter && logFooter.setState({ msg: "" })
       log.info({ msg: "No modules found in project." })
       log.info({ msg: "Aborting..." })
       return {}
@@ -120,20 +121,19 @@ export class DevCommand extends Command<Args, Opts> {
           includeDependants: watch,
         }))
       }
-
     }
 
     const results = await processModules({
       garden,
       log,
+      logFooter,
       modules,
       watch: true,
       handler: tasksForModule(false),
       changeHandler: tasksForModule(true),
     })
 
     return handleTaskResults(log, "dev", results)
-
   }
 }
 

garden-service/src/commands/helpers.ts

@@ -49,26 +49,26 @@ export async function validateHotReloadOpt(
 }
 
 export async function hotReloadAndLog(garden: Garden, log: LogEntry, module: Module) {
-  log.info({
+  const logEntry = log.info({
     section: module.name,
-    msg: "Hot reloading",
+    msg: "Hot reloading...",
     status: "active",
   })
 
   const serviceDependencyNames = uniq(flatten(module.services.map(s => s.config.dependencies)))
   const runtimeContext = await prepareRuntimeContext(
-    garden, log, module, await garden.getServices(serviceDependencyNames),
+    garden, logEntry, module, await garden.getServices(serviceDependencyNames),
   )
 
   try {
-    await garden.actions.hotReload({ log, module, runtimeContext })
+    await garden.actions.hotReload({ log: logEntry, module, runtimeContext })
   } catch (err) {
     log.setError()
     throw err
   }
 
-  const msec = log.getDuration(5) * 1000
-  log.setSuccess({
+  const msec = logEntry.getDuration(5) * 1000
+  logEntry.setSuccess({
     msg: chalk.green(`Done (took ${msec} ms)`),
     append: true,
   })

garden-service/src/commands/run/task.ts

@@ -76,9 +76,9 @@ export class RunTaskCommand extends Command<Args, Opts> {
 
     printRuntimeContext(log, runtimeContext)
 
-    garden.log.info("")
-    garden.log.info(chalk.white(result.output.output))
-    garden.log.info("")
+    log.info("")
+    log.info(chalk.white(result.output.output))
+    log.info("")
     logHeader({ log, emoji: "heavy_check_mark", command: `Done!` })
 
     return { result }

garden-service/src/commands/serve.ts

@@ -41,8 +41,8 @@ export class ServeCommand extends Command<Args, Opts> {
   arguments = serveArgs
   options = serveOpts
 
-  async action({ garden, opts }: CommandParams<Args, Opts>): Promise<CommandResult<{}>> {
-    await startServer(garden, opts.port)
+  async action({ garden, log, opts }: CommandParams<Args, Opts>): Promise<CommandResult<{}>> {
+    await startServer(garden, log, opts.port)
 
     // The server doesn't block, so we need to loop indefinitely here.
     while (true) {

garden-service/src/commands/test.ts

@@ -80,7 +80,7 @@ export class TestCommand extends Command<Args, Opts> {
     })
   }
 
-  async action({ garden, log, args, opts }: CommandParams<Args, Opts>): Promise<CommandResult<TaskResults>> {
+  async action({ garden, log, logFooter, args, opts }: CommandParams<Args, Opts>): Promise<CommandResult<TaskResults>> {
     const dependencyGraph = await garden.getDependencyGraph()
     let modules: Module[]
     if (args.modules) {
@@ -99,6 +99,7 @@ export class TestCommand extends Command<Args, Opts> {
     const results = await processModules({
       garden,
       log,
+      logFooter,
       modules,
       watch: opts.watch,
       handler: async (module) => getTestTasks({ garden, log, module, name, force, forceBuild }),

garden-service/src/commands/update-remote/all.ts

@@ -33,7 +33,7 @@ export class UpdateRemoteAllCommand extends Command {
         garden update-remote all # update all remote sources and modules in the project
   `
 
-  async action({ garden, log }: CommandParams): Promise<CommandResult<UpdateRemoteAllResult>> {
+  async action({ garden, log, logFooter }: CommandParams): Promise<CommandResult<UpdateRemoteAllResult>> {
     logHeader({ log, emoji: "hammer_and_wrench", command: "update-remote all" })
 
     const sourcesCmd = new UpdateRemoteSourcesCommand()
@@ -42,12 +42,14 @@ export class UpdateRemoteAllCommand extends Command {
     const { result: projectSources } = await sourcesCmd.action({
       garden,
       log,
+      logFooter,
       args: { sources: undefined },
       opts: {},
     })
     const { result: moduleSources } = await modulesCmd.action({
       garden,
       log,
+      logFooter,
       args: { modules: undefined },
       opts: {},
     })

garden-service/src/events.ts

@@ -56,6 +56,12 @@ export interface Events {
   },
   taskComplete: TaskResult,
   taskError: TaskResult,
+  taskGraphProcessing: {
+    startedAt: Date,
+  },
+  taskGraphComplete: {
+    completedAt: Date,
+  },
 }
 
 export type EventName = keyof Events

garden-service/src/process.ts

@@ -26,6 +26,7 @@ export type ProcessHandler = (module: Module) => Promise<BaseTask[]>
 interface ProcessParams {
   garden: Garden
   log: LogEntry
+  logFooter?: LogEntry
   watch: boolean
   handler: ProcessHandler
   // use this if the behavior should be different on watcher changes than on initial processing
@@ -46,7 +47,7 @@ export interface ProcessResults {
 }
 
 export async function processServices(
-  { garden, log, services, watch, handler, changeHandler }: ProcessServicesParams,
+  { garden, log, logFooter, services, watch, handler, changeHandler }: ProcessServicesParams,
 ): Promise<ProcessResults> {
 
   const modules = Array.from(new Set(services.map(s => s.module)))
@@ -55,14 +56,15 @@ export async function processServices(
     modules,
     garden,
     log,
+    logFooter,
     watch,
     handler,
     changeHandler,
   })
 }
 
 export async function processModules(
-  { garden, log, modules, watch, handler, changeHandler }: ProcessModulesParams,
+  { garden, log, logFooter, modules, watch, handler, changeHandler }: ProcessModulesParams,
 ): Promise<ProcessResults> {
 
   log.debug("Starting processModules")
@@ -85,6 +87,19 @@ export async function processModules(
     await Bluebird.map(tasks, t => garden.addTask(t))
   }
 
+  if (watch && !!logFooter) {
+    logFooter.info("")
+    const statusLine = logFooter.placeholder()
+
+    garden.events.on("taskGraphProcessing", () => {
+      statusLine.setState({ emoji: "hourglass_flowing_sand", msg: "Processing..." })
+    })
+
+    garden.events.on("taskGraphComplete", () => {
+      statusLine.setState({ emoji: "clock2", msg: chalk.gray("Waiting for code changes") })
+    })
+  }
+
   const results = await garden.processTasks()
 
   if (!watch) {
@@ -104,7 +119,11 @@ export async function processModules(
     await watcher.watchModules(modules,
       async (changedModule: Module | null, configChanged: boolean) => {
         if (configChanged) {
-          log.debug({ msg: `Config changed, reloading.` })
+          if (changedModule) {
+            log.info({ emoji: "gear", section: changedModule.name, msg: `Module configuration changed, reloading...` })
+          } else {
+            log.info({ emoji: "gear", msg: `Project configuration changed, reloading...` })
+          }
           resolve()
           return
         }
@@ -125,7 +144,7 @@ export async function processModules(
 
   // Experimental HTTP API and dashboard server.
   if (process.env.GARDEN_ENABLE_SERVER === "1") {
-    await startServer(garden)
+    await startServer(garden, log)
   }
 
   await restartPromise

garden-service/src/server/commands.ts

@@ -14,6 +14,7 @@ import { coreCommands } from "../commands/commands"
 import { mapValues, omitBy } from "lodash"
 import { Garden } from "../garden"
 import { LogLevel } from "../logger/log-node"
+import { LogEntry } from "../logger/log-entry"
 
 export interface CommandMap {
   [key: string]: {
@@ -40,7 +41,7 @@ const baseRequestSchema = Joi.object()
  * Validate and map a request body to a Command, execute its action, and return its result.
  */
 export async function resolveRequest(
-  ctx: Koa.Context, garden: Garden, commands: CommandMap, request: any,
+  ctx: Koa.Context, garden: Garden, log: LogEntry, commands: CommandMap, request: any,
 ) {
   // Perform basic validation and find command.
   try {
@@ -70,12 +71,18 @@ export async function resolveRequest(
   const cmdGarden = await Garden.factory(garden.projectRoot, garden.opts)
 
   // We generally don't want actions to log anything in the server.
-  const cmdLog = garden.log.placeholder(LogLevel.silly)
+  const cmdLog = log.placeholder(LogLevel.silly)
 
   const cmdArgs = mapParams(ctx, request.parameters, command.arguments)
   const cmdOpts = mapParams(ctx, request.parameters, command.options)
 
-  return command.action({ garden: cmdGarden, log: cmdLog, args: cmdArgs, opts: cmdOpts })
+  return command.action({
+    garden: cmdGarden,
+    log: cmdLog,
+    logFooter: cmdLog,
+    args: cmdArgs,
+    opts: cmdOpts,
+  })
   // TODO: validate result schema
 }
 

garden-service/src/server/server.ts

@@ -18,6 +18,7 @@ import { Garden } from "../garden"
 import { addWebsocketEndpoint } from "./websocket"
 import { prepareCommands, resolveRequest } from "./commands"
 import { isPkg } from "../constants"
+import { LogEntry } from "../logger/log-entry"
 
 export const DASHBOARD_BUILD_PATH = resolve(
   isPkg ? process.execPath : __dirname, "..", "..", "..", "garden-dashboard", "build",
@@ -32,8 +33,10 @@ export const DASHBOARD_BUILD_PATH = resolve(
  * If `port` is not specified, a random free port is chosen. This is done so that a process can always create its
  * own server, but we won't need that functionality once we run a shared service across commands.
  */
-export async function startServer(garden: Garden, port?: number) {
-  const app = await createApp(garden)
+export async function startServer(garden: Garden, log: LogEntry, port?: number) {
+  log = log.placeholder()
+
+  const app = await createApp(garden, log)
 
   // TODO: remove this once we stop running a server per CLI command
   if (!port) {
@@ -45,17 +48,15 @@ export async function startServer(garden: Garden, port?: number) {
 
   const url = `http://localhost:${port}`
 
-  garden.log.info({
+  log.info({
     emoji: "sunflower",
     msg: chalk.cyan("Garden dashboard and API server running on ") + url,
   })
 
   return server
 }
 
-export async function createApp(garden: Garden) {
-  const log = garden.log.placeholder()
-
+export async function createApp(garden: Garden, log: LogEntry) {
   // prepare request-command map
   const commands = await prepareCommands()
 
@@ -71,7 +72,7 @@ export async function createApp(garden: Garden) {
    */
   http.post("/api", async (ctx) => {
     // TODO: set response code when errors are in result object?
-    const result = await resolveRequest(ctx, garden, commands, ctx.request.body)
+    const result = await resolveRequest(ctx, garden, log, commands, ctx.request.body)
 
     ctx.status = 200
     ctx.response.body = result

garden-service/src/server/websocket.ts

@@ -72,7 +72,7 @@ export function addWebsocketEndpoint(app: websockify.App, garden: Garden, log: L
       }
 
       if (request.type === "command") {
-        resolveRequest(ctx, garden, commands, omit(request, ["id", "type"]))
+        resolveRequest(ctx, garden, log, commands, omit(request, ["id", "type"]))
           .then(result => {
             send("commandResult", { requestId, result: result.result, errors: result.errors })
           })

garden-service/src/task-graph.ts

@@ -136,10 +136,13 @@ export class TaskGraph {
     const _this = this
     const results: TaskResults = {}
 
+    this.garden.events.emit("taskGraphProcessing", { startedAt: new Date() })
+
     const loop = async () => {
       if (_this.index.length === 0) {
         // done!
         this.logEntryMap.counter && this.logEntryMap.counter.setDone({ symbol: "info" })
+        this.garden.events.emit("taskGraphComplete", { completedAt: new Date() })
         return
       }