fix(framework): increase consistency in verbose plugin logs

This commit makes it harder to forget sending verbose logs (mostly tool
output) to both Garden Cloud and to the CLI logs.

To accomplish that, this commit

1. Fixed the type assertions in the PluginEventBroker. Now typescript
   will actually verify the types for the events in `emit` and in `on`
   etc.
2. Added two additional parameters to the `log` event, origin and log.
   Log is supposed to be a LogEntry placeholder with verbose log level.
3. Make sure that we use the `ctx.events.emit` in the plugin
   implementations to stream logs to Garden Cloud and CLI

core/src/actions.ts

@@ -84,7 +84,7 @@ import { RunServiceParams } from "./types/plugin/service/runService"
 import { GetTaskResultParams } from "./types/plugin/task/getTaskResult"
 import { RunTaskParams, RunTaskResult } from "./types/plugin/task/runTask"
 import { ServiceStatus, ServiceStatusMap, ServiceState, GardenService } from "./types/service"
-import { Omit, getNames, uuidv4 } from "./util/util"
+import { Omit, getNames, uuidv4, renderOutputStream } from "./util/util"
 import { DebugInfoMap } from "./types/plugin/provider/getDebugInfo"
 import { PrepareEnvironmentParams, PrepareEnvironmentResult } from "./types/plugin/provider/prepareEnvironment"
 import { GetPortForwardParams } from "./types/plugin/service/getPortForward"
@@ -379,7 +379,11 @@ export class ActionRouter implements TypeGuard {
     const startedAt = new Date()
     const moduleName = params.module.name
     const moduleVersion = params.module.version.versionString
-    params.events.on("log", ({ timestamp, data }) => {
+    params.events.on("log", ({ timestamp, data, origin, log }) => {
+      // stream logs to CLI
+      log.setState(renderOutputStream(data.toString(), origin))
+      // stream logs to Garden Cloud
+      // TODO: consider sending origin as well
       this.garden.events.emit("log", {
         timestamp,
         actionUid,
@@ -460,7 +464,14 @@ export class ActionRouter implements TypeGuard {
 
     try {
       // Annotate + emit log output
-      params.events.on("log", ({ timestamp, data }) => {
+      params.events.on("log", ({ timestamp, data, origin, log }) => {
+        if (!params.interactive) {
+          // stream logs to CLI; if interactive is true, the output will already be streamed to process.stdout
+          // TODO: 0.13 make sure that logs of different tests in the same module can be differentiated
+          log.setState(renderOutputStream(data.toString(), origin))
+        }
+        // stream logs to Garden Cloud
+        // TODO: consider sending origin as well
         this.garden.events.emit("log", {
           timestamp,
           actionUid,
@@ -545,7 +556,11 @@ export class ActionRouter implements TypeGuard {
     const serviceName = params.service.name
     const moduleVersion = params.service.module.version.versionString
     const moduleName = params.service.module.name
-    params.events.on("log", ({ timestamp, data }) => {
+    params.events.on("log", ({ timestamp, data, origin, log }) => {
+      // stream logs to CLI
+      log.setState(renderOutputStream(data.toString(), origin))
+      // stream logs to Garden Cloud
+      // TODO: consider sending origin as well
       this.garden.events.emit("log", {
         timestamp,
         actionUid,
@@ -707,7 +722,14 @@ export class ActionRouter implements TypeGuard {
 
     try {
       // Annotate + emit log output
-      params.events.on("log", ({ timestamp, data }) => {
+      params.events.on("log", ({ timestamp, data, origin, log }) => {
+        if (!params.interactive) {
+          // stream logs to CLI; if interactive is true, the output will already be streamed to process.stdout
+          // TODO: 0.13 make sure that logs of different tasks in the same module can be differentiated
+          log.setState(renderOutputStream(data.toString(), origin))
+        }
+        // stream logs to Garden Cloud
+        // TODO: consider sending origin as well
         this.garden.events.emit("log", {
           timestamp,
           actionUid,

core/src/commands/logs.ts

@@ -135,7 +135,7 @@ export class LogsCommand extends Command<Args, Opts> {
   }
 
   terminate() {
-    this.events?.emit("abort", {})
+    this.events?.emit("abort")
   }
 
   async action({ garden, log, args, opts }: CommandParams<Args, Opts>): Promise<CommandResult<ServiceLogEntry[]>> {

core/src/plugin-context.ts

@@ -92,9 +92,32 @@ export const pluginContextSchema = () =>
       cloudApi: joi.any().optional(),
     })
 
-interface PluginEvents {
-  abort: { reason?: string }
-  log: { data: Buffer }
+export type PluginEventLogContext = {
+  /** entity that created the log message, e.g. tool that generated it */
+  origin: string
+
+  /**
+   * LogEntry placeholder to be used to stream the logs to the CLI
+   * It's recommended to pass a verbose placeholder created like this: `log.placeholder({ level: LogLevel.verbose })`
+   *
+   * @todo 0.13 consider removing this once we have the append-only logger (#3254)
+   */
+  log: LogEntry
+}
+
+export type PluginEventLogMessage = PluginEventLogContext & {
+  /** number of milliseconds since the epoch */
+  timestamp: number
+
+  /** log message */
+  data: Buffer
+}
+
+// Define your emitter's types like that:
+// Key: Event name; Value: Listener function signature
+type PluginEvents = {
+  abort: (reason?: string) => void
+  log: (msg: PluginEventLogMessage) => void
 }
 
 type PluginEventType = keyof PluginEvents

core/src/plugins/container/build.ts

@@ -12,7 +12,6 @@ import { ConfigurationError } from "../../exceptions"
 import { GetBuildStatusParams } from "../../types/plugin/module/getBuildStatus"
 import { BuildModuleParams } from "../../types/plugin/module/build"
 import { LogLevel } from "../../logger/logger"
-import { renderOutputStream } from "../../util/util"
 import { PrimitiveMap } from "../../config/common"
 import split2 from "split2"
 
@@ -65,14 +64,15 @@ export async function buildContainerModule({ ctx, module, log }: BuildModulePara
     cmdOpts.push("--file", containerHelpers.getDockerfileBuildPath(module))
   }
 
-  // Stream verbose log to a status line
-  const outputStream = split2()
-  const statusLine = log.placeholder({ level: LogLevel.verbose })
+  const logEventContext = {
+    origin: "local-docker",
+    log: log.placeholder({ level: LogLevel.verbose }),
+  }
 
+  const outputStream = split2()
   outputStream.on("error", () => {})
   outputStream.on("data", (line: Buffer) => {
-    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line })
-    statusLine.setState(renderOutputStream(line.toString(), "local-docker"))
+    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line, ...logEventContext })
   })
   const timeout = module.spec.build.timeout
   const res = await containerHelpers.dockerCli({

core/src/plugins/exec/exec.ts

@@ -26,7 +26,7 @@ import { BuildModuleParams, BuildResult } from "../../types/plugin/module/build"
 import { TestModuleParams } from "../../types/plugin/module/testModule"
 import { TestResult } from "../../types/plugin/module/getTestResult"
 import { RunTaskParams, RunTaskResult } from "../../types/plugin/task/runTask"
-import { exec, ExecOpts, renderOutputStream, runScript, sleep } from "../../util/util"
+import { exec, ExecOpts, runScript, sleep } from "../../util/util"
 import { ConfigurationError, RuntimeError, TimeoutError } from "../../exceptions"
 import { LogEntry } from "../../logger/log-entry"
 import { providerConfigBaseSchema } from "../../config/provider"
@@ -436,13 +436,15 @@ async function run({
   env?: PrimitiveMap
   opts?: ExecOpts
 }) {
-  const outputStream = split2()
+  const logEventContext = {
+    origin: command[0],
+    log,
+  }
 
+  const outputStream = split2()
   outputStream.on("error", () => {})
   outputStream.on("data", (line: Buffer) => {
-    const cmdName = command[0]
-    log.setState(renderOutputStream(line.toString(), cmdName))
-    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line })
+    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line, ...logEventContext })
   })
 
   const res = await exec(command.join(" "), [], {

core/src/plugins/kubernetes/container/build/buildkit.ts

@@ -30,7 +30,7 @@ import {
 } from "./common"
 import { getNamespaceStatus } from "../../namespace"
 import { LogLevel } from "../../../../logger/logger"
-import { renderOutputStream, sleep } from "../../../../util/util"
+import { sleep } from "../../../../util/util"
 import { ContainerModule } from "../../../container/config"
 import { getDockerBuildArgs } from "../../../container/build"
 import { getRunningDeploymentPod, usingInClusterRegistry } from "../../util"
@@ -101,16 +101,15 @@ export const buildkitBuildHandler: BuildHandler = async (params) => {
 
   log.setState(`Building image ${localId}...`)
 
-  let buildLog = ""
+  const logEventContext = {
+    origin: "buildkit",
+    log: log.placeholder({ level: LogLevel.verbose }),
+  }
 
-  // Stream verbose logs to a status line
   const outputStream = split2()
-  const statusLine = log.placeholder({ level: LogLevel.verbose })
-
   outputStream.on("error", () => {})
   outputStream.on("data", (line: Buffer) => {
-    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line })
-    statusLine.setState(renderOutputStream(line.toString(), "buildkit"))
+    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line, ...logEventContext })
   })
 
   const command = [
@@ -154,7 +153,7 @@ export const buildkitBuildHandler: BuildHandler = async (params) => {
     buffer: true,
   })
 
-  buildLog = buildRes.log
+  const buildLog = buildRes.log
 
   log.silly(buildLog)
 

core/src/plugins/kubernetes/container/build/cluster-docker.ts

@@ -25,7 +25,6 @@ import {
 import { posix } from "path"
 import split2 = require("split2")
 import { LogLevel } from "../../../../logger/logger"
-import { renderOutputStream } from "../../../../util/util"
 import { getDockerBuildFlags } from "../../../container/build"
 
 export const getClusterDockerBuildStatus: BuildStatusHandler = async (params) => {
@@ -89,16 +88,16 @@ export const clusterDockerBuild: BuildHandler = async (params) => {
 
   log.setState(`Building image ${localId}...`)
 
-  let buildLog = ""
+  const logEventContext = {
+    origin: "cluster-docker",
+    log: log.placeholder({ level: LogLevel.verbose }),
+  }
 
   // Stream verbose logs to a status line
   const stdout = split2()
-  const statusLine = log.placeholder({ level: LogLevel.verbose })
-
   stdout.on("error", () => {})
   stdout.on("data", (line: Buffer) => {
-    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line })
-    statusLine.setState(renderOutputStream(line.toString(), "cluster-docker"))
+    ctx.events.emit("log", { timestamp: new Date().getTime(), data: line, ...logEventContext })
   })
 
   // Prepare the build command
@@ -134,7 +133,7 @@ export const clusterDockerBuild: BuildHandler = async (params) => {
     buffer: true,
   })
 
-  buildLog = buildRes.log
+  let buildLog = buildRes.log
 
   // Push the image to the registry
   log.info({ msg: `→ Pushing image ${localId} to registry...` })

core/src/plugins/kubernetes/container/build/kaniko.ts

@@ -36,9 +36,7 @@ import {
 } from "./common"
 import { differenceBy, isEmpty } from "lodash"
 import chalk from "chalk"
-import split2 from "split2"
 import { LogLevel } from "../../../../logger/logger"
-import { renderOutputStream } from "../../../../util/util"
 import { getDockerBuildFlags } from "../../../container/build"
 import { stringifyResources } from "../util"
 
@@ -106,17 +104,6 @@ export const kanikoBuild: BuildHandler = async (params) => {
 
   log.setState(`Building image ${localId}...`)
 
-  let buildLog = ""
-
-  // Stream verbose logs to a status line
-  const outputStream = split2()
-  const statusLine = log.placeholder({ level: LogLevel.verbose })
-
-  outputStream.on("error", () => {})
-  outputStream.on("data", (line: Buffer) => {
-    statusLine.setState(renderOutputStream(line.toString(), "kaniko"))
-  })
-
   // Use the project namespace if set to null in config
   // TODO: change in 0.13 to default to project namespace
   let kanikoNamespace =
@@ -169,7 +156,7 @@ export const kanikoBuild: BuildHandler = async (params) => {
     args,
   })
 
-  buildLog = buildRes.log
+  const buildLog = buildRes.log
 
   if (kanikoBuildFailed(buildRes)) {
     throw new BuildError(`Failed building module ${chalk.bold(module.name)}:\n\n${buildLog}`, { buildLog })
@@ -434,8 +421,14 @@ async function runKaniko({
     pod.spec.nodeSelector = provider.config.kaniko?.nodeSelector
   }
 
+  const logEventContext = {
+    origin: "kaniko",
+    log: log.placeholder({ level: LogLevel.verbose }),
+  }
+
   const runner = new PodRunner({
     ctx,
+    logEventContext,
     api,
     pod,
     provider,

core/src/plugins/kubernetes/helm/run.ts

@@ -28,6 +28,7 @@ import { KubeApi } from "../api"
 import { getModuleNamespaceStatus } from "../namespace"
 import { DEFAULT_TASK_TIMEOUT } from "../../../constants"
 import { KubernetesPod } from "../types"
+import { LogLevel } from "../../../logger/logger"
 
 export async function runHelmModule({
   ctx,
@@ -103,8 +104,14 @@ export async function runHelmModule({
     },
   }
 
+  const logEventContext = {
+    origin: "helm",
+    log: log.placeholder({ level: LogLevel.verbose }),
+  }
+
   const runner = new PodRunner({
     ctx,
+    logEventContext,
     api,
     pod,
     provider,