feat(container): output build log while building with debug log level

When using the fancy logger we only show one line at a time, but you
could use the basic logger to get the full log.

This should be helpful when debugging docker builds.

Closes #852

garden-service/src/plugins/container/build.ts

@@ -11,6 +11,9 @@ import { ContainerModule } from "./config"
 import { ConfigurationError } from "../../exceptions"
 import { GetBuildStatusParams } from "../../types/plugin/module/getBuildStatus"
 import { BuildModuleParams } from "../../types/plugin/module/build"
+import chalk from "chalk"
+import { LogLevel } from "../../logger/log-node"
+import split2 = require("split2")
 
 export async function getContainerBuildStatus({ module, log }: GetBuildStatusParams<ContainerModule>) {
   const identifier = await containerHelpers.imageExistsLocally(module)
@@ -61,10 +64,17 @@ export async function buildContainerModule({ module, log }: BuildModuleParams<Co
     cmdOpts.push("--file", containerHelpers.getDockerfileBuildPath(module))
   }
 
-  // TODO: log error if it occurs
-  // TODO: stream output to log if at debug log level
+  // Stream log to a status line
+  const outputStream = split2()
+  const statusLine = log.placeholder(LogLevel.debug)
+
+  outputStream.on("error", () => { })
+  outputStream.on("data", (line: Buffer) => {
+    statusLine.setState(chalk.gray("  → " + line.toString().slice(0, 80)))
+  })
+
   const timeout = module.spec.build.timeout
-  const buildLog = await containerHelpers.dockerCli(module, [...cmdOpts, buildPath], { timeout })
+  const buildLog = await containerHelpers.dockerCli(module, [...cmdOpts, buildPath], { outputStream, timeout })
 
   return { fresh: true, buildLog, details: { identifier } }
 }

garden-service/src/plugins/container/helpers.ts

@@ -12,6 +12,7 @@ import { ConfigurationError, RuntimeError } from "../../exceptions"
 import { splitFirst, spawn, splitLast } from "../../util/util"
 import { ModuleConfig } from "../../config/module"
 import { ContainerModule, ContainerRegistryConfig, defaultTag, defaultNamespace, ContainerModuleConfig } from "./config"
+import { Writable } from "stream"
 
 export const DEFAULT_BUILD_TIMEOUT = 600
 export const minDockerVersion = "17.07.0"
@@ -251,14 +252,14 @@ const helpers = {
 
   async dockerCli(
     module: ContainerModule, args: string[],
-    { timeout = DEFAULT_BUILD_TIMEOUT }: { timeout?: number } = {},
+    { outputStream, timeout = DEFAULT_BUILD_TIMEOUT }: { outputStream?: Writable, timeout?: number } = {},
   ) {
     await helpers.checkDockerVersion()
 
     const cwd = module.buildPath
 
     try {
-      const res = await spawn("docker", args, { cwd, timeout })
+      const res = await spawn("docker", args, { cwd, outputStream, timeout })
       return res.output || ""
     } catch (err) {
       throw new RuntimeError(

garden-service/src/plugins/kubernetes/container/build.ts

@@ -7,6 +7,7 @@
  */
 
 import pRetry from "p-retry"
+import split2 = require("split2")
 import { ContainerModule } from "../../container/config"
 import { containerHelpers } from "../../container/helpers"
 import { buildContainerModule, getContainerBuildStatus, getDockerBuildFlags } from "../../container/build"
@@ -27,6 +28,9 @@ import { getRegistryHostname } from "../init"
 import { getManifestFromRegistry } from "./util"
 import { normalizeLocalRsyncPath } from "../../../util/fs"
 import { getPortForward } from "../port-forward"
+import chalk from "chalk"
+import { Writable } from "stream"
+import { LogLevel } from "../../../logger/log-node"
 
 const dockerDaemonDeploymentName = "garden-docker-daemon"
 const dockerDaemonContainerName = "docker-daemon"
@@ -160,6 +164,15 @@ const remoteBuild: BuildHandler = async (params) => {
 
   let buildLog = ""
 
+  // Stream debug log to a status line
+  const outputStream = split2()
+  const statusLine = log.placeholder(LogLevel.debug)
+
+  outputStream.on("error", () => { })
+  outputStream.on("data", (line: Buffer) => {
+    statusLine.setState(chalk.gray("  → " + line.toString().slice(0, 80)))
+  })
+
   if (provider.config.buildMode === "cluster-docker") {
     // Prepare the build command
     const dockerfilePath = posix.join(contextPath, dockerfile)
@@ -175,7 +188,8 @@ const remoteBuild: BuildHandler = async (params) => {
     // Execute the build
     const podName = await getBuilderPodName(provider, log)
     const buildTimeout = module.spec.build.timeout
-    const buildRes = await execInBuilder({ provider, log, args, timeout: buildTimeout, podName })
+
+    const buildRes = await execInBuilder({ provider, log, args, timeout: buildTimeout, podName, outputStream })
     buildLog = buildRes.stdout + buildRes.stderr
 
     // Push the image to the registry
@@ -184,7 +198,7 @@ const remoteBuild: BuildHandler = async (params) => {
     const dockerCmd = ["docker", "push", deploymentImageId]
     const pushArgs = ["/bin/sh", "-c", dockerCmd.join(" ")]
 
-    const pushRes = await execInBuilder({ provider, log, args: pushArgs, timeout: 300, podName })
+    const pushRes = await execInBuilder({ provider, log, args: pushArgs, timeout: 300, podName, outputStream })
     buildLog += pushRes.stdout + pushRes.stderr
 
   } else {
@@ -201,7 +215,7 @@ const remoteBuild: BuildHandler = async (params) => {
     ]
 
     // Execute the build
-    const buildRes = await runKaniko(provider, log, module, args)
+    const buildRes = await runKaniko({ provider, log, module, args, outputStream })
     buildLog = buildRes.log
   }
 
@@ -221,6 +235,7 @@ export interface BuilderExecParams {
   args: string[],
   timeout: number,
   podName: string,
+  outputStream?: Writable
 }
 
 const buildHandlers: { [mode in ContainerBuildMode]: BuildHandler } = {
@@ -230,7 +245,7 @@ const buildHandlers: { [mode in ContainerBuildMode]: BuildHandler } = {
 }
 
 // TODO: we should make a simple service around this instead of execing into containers
-export async function execInBuilder({ provider, log, args, timeout, podName }: BuilderExecParams) {
+export async function execInBuilder({ provider, log, args, timeout, podName, outputStream }: BuilderExecParams) {
   const execCmd = ["exec", "-i", podName, "-c", dockerDaemonContainerName, "--", ...args]
 
   log.verbose(`Running: kubectl ${execCmd.join(" ")}`)
@@ -241,6 +256,7 @@ export async function execInBuilder({ provider, log, args, timeout, podName }: B
     log,
     namespace: systemNamespace,
     timeout,
+    outputStream,
   })
 }
 
@@ -261,7 +277,15 @@ export async function getBuilderPodName(provider: KubernetesProvider, log: LogEn
   return builderPods[0].metadata.name
 }
 
-async function runKaniko(provider: KubernetesProvider, log: LogEntry, module: ContainerModule, args: string[]) {
+interface RunKanikoParams {
+  provider: KubernetesProvider
+  log: LogEntry
+  module: ContainerModule
+  args: string[]
+  outputStream: Writable
+}
+
+async function runKaniko({ provider, log, module, args, outputStream }: RunKanikoParams) {
   const podName = `kaniko-${module.name}-${Math.round(new Date().getTime())}`
   const registryHostname = getRegistryHostname()
 
@@ -325,5 +349,6 @@ async function runKaniko(provider: KubernetesProvider, log: LogEntry, module: Co
     },
     podName,
     timeout: module.spec.build.timeout,
+    outputStream,
   })
 }

garden-service/src/plugins/kubernetes/run.ts

@@ -13,6 +13,7 @@ import { LogEntry } from "../../logger/log-entry"
 import { V1PodSpec } from "@kubernetes/client-node"
 import { PluginError } from "../../exceptions"
 import { KubernetesProvider } from "./config"
+import { Writable } from "stream"
 
 interface RunPodParams {
   provider: KubernetesProvider,
@@ -24,6 +25,7 @@ interface RunPodParams {
   namespace: string,
   annotations?: { [key: string]: string }
   spec: V1PodSpec,
+  outputStream?: Writable,
   podName?: string,
   timeout?: number,
 }
@@ -39,6 +41,7 @@ export async function runPod(
     namespace,
     annotations,
     spec,
+    outputStream,
     podName,
     timeout,
   }: RunPodParams,
@@ -98,6 +101,7 @@ export async function runPod(
     namespace,
     ignoreError,
     args: kubecmd,
+    outputStream,
     timeout,
     tty: interactive,
   })

garden-service/src/util/ext-tools.ts

@@ -21,6 +21,7 @@ import { createHash } from "crypto"
 import * as uuid from "uuid"
 import * as crossSpawn from "cross-spawn"
 import { spawn } from "./util"
+import { Writable } from "stream"
 const AsyncLock = require("async-lock")
 
 const toolsPath = join(GARDEN_GLOBAL_PATH, "tools")
@@ -218,6 +219,7 @@ export interface ExecParams {
   timeout?: number
   input?: Buffer | string
   ignoreError?: boolean
+  outputStream?: Writable
 }
 
 export interface SpawnParams extends ExecParams {
@@ -255,7 +257,7 @@ export class BinaryCmd extends Library {
     return path
   }
 
-  async exec({ args, cwd, env, log, timeout, input, ignoreError }: ExecParams) {
+  async exec({ args, cwd, env, log, timeout, input, ignoreError, outputStream }: ExecParams) {
     const path = await this.getPath(log)
 
     if (!args) {
@@ -264,13 +266,20 @@ export class BinaryCmd extends Library {
 
     log.verbose(`Execing ${path} ${args.join(" ")}`)
 
-    return execa(path, args, {
+    const proc = execa(path, args, {
       cwd: cwd || dirname(path),
       timeout: this.getTimeout(timeout) * 1000,
       env,
       input,
       reject: !ignoreError,
     })
+
+    if (outputStream) {
+      proc.stdout && proc.stdout.pipe(outputStream)
+      proc.stderr && proc.stderr.pipe(outputStream)
+    }
+
+    return proc
   }
 
   async stdout(params: ExecParams) {
@@ -288,13 +297,14 @@ export class BinaryCmd extends Library {
     return crossSpawn(path, args || [], { cwd: cwd || dirname(path), env })
   }
 
-  async spawnAndWait({ args, cwd, env, log, ignoreError, timeout, tty }: SpawnParams) {
+  async spawnAndWait({ args, cwd, env, log, ignoreError, outputStream, timeout, tty }: SpawnParams) {
     const path = await this.getPath(log)
     return spawn(path, args || [], {
       cwd: cwd || dirname(path),
       timeout: this.getTimeout(timeout),
       ignoreError,
       env,
+      outputStream,
       tty,
     })
   }

garden-service/src/util/util.ts

@@ -21,6 +21,7 @@ import chalk from "chalk"
 import { safeDump } from "js-yaml"
 import { createHash } from "crypto"
 import { tailString } from "./string"
+import { Writable } from "stream"
 
 // shim to allow async generator functions
 if (typeof (Symbol as any).asyncIterator === "undefined") {
@@ -76,6 +77,7 @@ export interface SpawnOpts {
   data?: Buffer
   ignoreError?: boolean
   env?: { [key: string]: string | undefined }
+  outputStream?: Writable
   tty?: boolean
   wait?: boolean
 }
@@ -90,7 +92,7 @@ export interface SpawnOutput {
 
 // TODO Dump output to a log file if it exceeds the MAX_BUFFER_SIZE
 export function spawn(cmd: string, args: string[], opts: SpawnOpts = {}) {
-  const { timeout = 0, cwd, data, ignoreError = false, env, tty, wait = true } = opts
+  const { timeout = 0, cwd, data, ignoreError = false, env, outputStream, tty, wait = true } = opts
 
   const stdio = tty ? "inherit" : "pipe"
   const proc = _spawn(cmd, args, { cwd, env, stdio })
@@ -126,6 +128,11 @@ export function spawn(cmd: string, args: string[], opts: SpawnOpts = {}) {
       result.stderr! = tailString(result.stderr! + s, MAX_BUFFER_SIZE, true)
     })
 
+    if (outputStream) {
+      proc.stdout!.pipe(outputStream)
+      proc.stderr!.pipe(outputStream)
+    }
+
     if (data) {
       // This may happen if the spawned process errors while we're still writing data.
       proc.stdin!.on("error", () => { })

garden-service/test/unit/src/plugins/container/container.ts

@@ -540,7 +540,7 @@ describe("plugins.container", () => {
       })
 
       const cmdArgs = ["build", "-t", "some/image", module.buildPath]
-      td.verify(dockerCli(module, cmdArgs, { timeout: DEFAULT_BUILD_TIMEOUT }))
+      td.verify(dockerCli(module, cmdArgs), { ignoreExtraArgs: true })
     })
 
     it("should set build target image parameter if configured", async () => {
@@ -564,7 +564,7 @@ describe("plugins.container", () => {
       })
 
       const cmdArgs = ["build", "-t", "some/image", "--target", "foo", module.buildPath]
-      td.verify(dockerCli(module, cmdArgs, { timeout: DEFAULT_BUILD_TIMEOUT }))
+      td.verify(dockerCli(module, cmdArgs), { ignoreExtraArgs: true })
     })
 
     it("should build image using the user specified Dockerfile path", async () => {
@@ -596,7 +596,7 @@ describe("plugins.container", () => {
         join(module.buildPath, relDockerfilePath),
         module.buildPath,
       ]
-      td.verify(dockerCli(module, cmdArgs, { timeout: DEFAULT_BUILD_TIMEOUT }))
+      td.verify(dockerCli(module, cmdArgs), { ignoreExtraArgs: true })
     })
   })