From b52e9b298f7c59b8210a77edc4c451301daa76e3 Mon Sep 17 00:00:00 2001 From: Steffen Neubauer Date: Tue, 24 Jan 2023 18:50:36 +0100 Subject: [PATCH] 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 | 32 ++++++++++++++++--- core/src/commands/logs.ts | 2 +- core/src/plugin-context.ts | 29 +++++++++++++++-- core/src/plugins/container/build.ts | 12 +++---- core/src/plugins/exec/exec.ts | 12 ++++--- .../kubernetes/container/build/buildkit.ts | 15 ++++----- .../container/build/cluster-docker.ts | 13 ++++---- .../kubernetes/container/build/kaniko.ts | 21 ++++-------- core/src/plugins/kubernetes/helm/run.ts | 7 ++++ core/src/plugins/kubernetes/run.ts | 32 ++++++++++++++++--- core/src/plugins/kubernetes/status/status.ts | 9 +++++- core/src/util/ext-tools.ts | 10 ++++-- plugins/jib/index.ts | 15 ++++++--- 13 files changed, 147 insertions(+), 62 deletions(-) diff --git a/core/src/actions.ts b/core/src/actions.ts index e71ef35dbb..78ead36fd7 100644 --- a/core/src/actions.ts +++ b/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, diff --git a/core/src/commands/logs.ts b/core/src/commands/logs.ts index 98bb1467f7..8ec6f946f6 100644 --- a/core/src/commands/logs.ts +++ b/core/src/commands/logs.ts @@ -135,7 +135,7 @@ export class LogsCommand extends Command { } terminate() { - this.events?.emit("abort", {}) + this.events?.emit("abort") } async action({ garden, log, args, opts }: CommandParams): Promise> { diff --git a/core/src/plugin-context.ts b/core/src/plugin-context.ts index 2e8b4dbe80..5209108190 100644 --- a/core/src/plugin-context.ts +++ b/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 diff --git a/core/src/plugins/container/build.ts b/core/src/plugins/container/build.ts index 1eccd4f3b6..e1d460a895 100644 --- a/core/src/plugins/container/build.ts +++ b/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({ diff --git a/core/src/plugins/exec/exec.ts b/core/src/plugins/exec/exec.ts index ce6f5b3fbf..965569d1f8 100644 --- a/core/src/plugins/exec/exec.ts +++ b/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(" "), [], { diff --git a/core/src/plugins/kubernetes/container/build/buildkit.ts b/core/src/plugins/kubernetes/container/build/buildkit.ts index 05afbd1654..048af42fbc 100644 --- a/core/src/plugins/kubernetes/container/build/buildkit.ts +++ b/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) diff --git a/core/src/plugins/kubernetes/container/build/cluster-docker.ts b/core/src/plugins/kubernetes/container/build/cluster-docker.ts index 66c808cb11..903848de42 100644 --- a/core/src/plugins/kubernetes/container/build/cluster-docker.ts +++ b/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...` }) diff --git a/core/src/plugins/kubernetes/container/build/kaniko.ts b/core/src/plugins/kubernetes/container/build/kaniko.ts index 63ea50d3b4..105c286d44 100644 --- a/core/src/plugins/kubernetes/container/build/kaniko.ts +++ b/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, diff --git a/core/src/plugins/kubernetes/helm/run.ts b/core/src/plugins/kubernetes/helm/run.ts index 6501cd4ece..a8e426da39 100644 --- a/core/src/plugins/kubernetes/helm/run.ts +++ b/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, diff --git a/core/src/plugins/kubernetes/run.ts b/core/src/plugins/kubernetes/run.ts index 1d86c30279..463b1568af 100644 --- a/core/src/plugins/kubernetes/run.ts +++ b/core/src/plugins/kubernetes/run.ts @@ -34,7 +34,7 @@ import { deline, randomString } from "../../util/string" import { ArtifactSpec } from "../../config/validation" import { prepareSecrets } from "./secrets" import { configureVolumes } from "./container/deployment" -import { PluginContext, PluginEventBroker } from "../../plugin-context" +import { PluginContext, PluginEventBroker, PluginEventLogContext } from "../../plugin-context" import { waitForResources, ResourceStatus } from "./status/status" import { RuntimeContext } from "../../runtime-context" import { getResourceRequirements, getSecurityContext } from "./container/util" @@ -42,6 +42,7 @@ import { KUBECTL_DEFAULT_TIMEOUT } from "./kubectl" import { copy } from "fs-extra" import { K8sLogFollower, PodLogEntryConverter, PodLogEntryConverterParams } from "./logs" import { Stream } from "ts-stream" +import { LogLevel } from "../../logger/logger" // Default timeout for individual run/exec operations const defaultTimeout = 600 @@ -202,11 +203,16 @@ export async function runAndCopy({ } if (getArtifacts) { - const outputStream = new PassThrough() + const logEventContext = { + // XXX command cannot be possibly undefined, can it? + origin: command ? command[0] : "unknown command", + log: log.placeholder({ level: LogLevel.verbose }), + } + const outputStream = new PassThrough() outputStream.on("error", () => {}) outputStream.on("data", (data: Buffer) => { - ctx.events.emit("log", { timestamp: new Date().getTime(), data }) + ctx.events.emit("log", { timestamp: new Date().getTime(), data, ...logEventContext }) }) return runWithArtifacts({ @@ -685,6 +691,7 @@ async function runWithArtifacts({ class PodRunnerParams { ctx: PluginContext + logEventContext?: PluginEventLogContext annotations?: { [key: string]: string } api: KubeApi pod: KubernetesPod | KubernetesServerResource @@ -748,6 +755,7 @@ export interface PodErrorDetails { export class PodRunner extends PodRunnerParams { podName: string running: boolean + logEventContext: PluginEventLogContext constructor(params: PodRunnerParams) { super() @@ -763,6 +771,10 @@ export class PodRunner extends PodRunnerParams { Object.assign(this, params) this.podName = this.pod.metadata.name + + if (params.logEventContext !== undefined) { + this.logEventContext + } } getFullCommand() { @@ -775,10 +787,22 @@ export class PodRunner extends PodRunnerParams { private prepareLogsFollower(params: RunParams) { const { log, tty, events } = params + + const logEventContext = this.logEventContext + ? this.logEventContext + : { + origin: this.getFullCommand()[0]!, + log: log.placeholder({ level: LogLevel.verbose }), + } + const stream = new Stream() void stream.forEach((entry) => { const { msg, timestamp } = entry - events.emit("log", { timestamp, data: Buffer.from(msg) }) + events.emit("log", { + timestamp: timestamp?.getTime() || new Date().getTime(), + data: Buffer.from(msg), + ...logEventContext, + }) if (tty) { process.stdout.write(`${entry.msg}\n`) } diff --git a/core/src/plugins/kubernetes/status/status.ts b/core/src/plugins/kubernetes/status/status.ts index db9b4bb096..ae7ea2d523 100644 --- a/core/src/plugins/kubernetes/status/status.ts +++ b/core/src/plugins/kubernetes/status/status.ts @@ -33,6 +33,7 @@ import { checkWorkloadStatus } from "./workload" import { checkWorkloadPodStatus } from "./pod" import { deline, gardenAnnotationKey, stableStringify } from "../../../util/string" import { SyncableResource } from "../hot-reload/hot-reload" +import { LogLevel } from "../../../logger/logger" export interface ResourceStatus { state: ServiceState @@ -186,8 +187,14 @@ export async function waitForResources({ let loops = 0 let lastMessage: string | undefined const startTime = new Date().getTime() + + const logEventContext = { + origin: "kubernetes-plugin", + log: log.placeholder({ level: LogLevel.verbose }), + } + const emitLog = (msg: string) => - ctx.events.emit("log", { timestamp: new Date().getTime(), data: Buffer.from(msg, "utf-8") }) + ctx.events.emit("log", { timestamp: new Date().getTime(), data: Buffer.from(msg, "utf-8"), ...logEventContext }) const waitingMsg = `Waiting for resources to be ready...` const statusLine = log.info({ diff --git a/core/src/util/ext-tools.ts b/core/src/util/ext-tools.ts index 5d7ecc7e54..0c1bb77f89 100644 --- a/core/src/util/ext-tools.ts +++ b/core/src/util/ext-tools.ts @@ -23,6 +23,7 @@ import { PluginToolSpec, ToolBuildSpec } from "../types/plugin/tools" import { parse } from "url" import AsyncLock from "async-lock" import { PluginContext } from "../plugin-context" +import { LogLevel } from "../logger/logger" const toolsPath = join(GARDEN_GLOBAL_PATH, "tools") const lock = new AsyncLock() @@ -150,10 +151,13 @@ export class CliWrapper { }) } + const logEventContext = { + origin: this.name, + log: log.placeholder({ level: LogLevel.verbose }), + } + logStream.on("data", (line: Buffer) => { - ctx.events.emit("log", { timestamp: new Date().getTime(), data: line }) - const lineStr = line.toString() - log.verbose(lineStr) + ctx.events.emit("log", { timestamp: new Date().getTime(), data: line, ...logEventContext }) }) await new Promise((resolve, reject) => { diff --git a/plugins/jib/index.ts b/plugins/jib/index.ts index 71cfa8ae9c..728dd4e7d1 100644 --- a/plugins/jib/index.ts +++ b/plugins/jib/index.ts @@ -28,6 +28,7 @@ import { containerHelpers } from "@garden-io/core/build/src/plugins/container/he import { cloneDeep } from "lodash" import { LogLevel } from "@garden-io/core/build/src/logger/logger" import { detectProjectType, getBuildFlags, JibContainerModule } from "./util" +import { PluginEventLogContext } from "@garden-io/core/src/plugin-context" export interface JibProviderConfig extends GenericProviderConfig {} @@ -233,14 +234,18 @@ export const gardenPlugin = () => statusLine.setState(renderOutputStream(`Detected project type ${projectType}`)) } - const outputStream = split2() let buildLog = "" + const logEventContext: PluginEventLogContext = { + origin: ["maven", "mavend", "gradle"].includes(projectType) ? projectType : "gradle", + log: log.placeholder({ level: LogLevel.verbose }), + } + + const outputStream = split2() outputStream.on("error", () => {}) - outputStream.on("data", (line: Buffer) => { - const str = line.toString() - statusLine.setState({ section: module.name, msg: str }) - buildLog += str + outputStream.on("data", (data: Buffer) => { + ctx.events.emit("log", { timestamp: new Date().getTime(), data, ...logEventContext }) + buildLog += data.toString() }) statusLine.setState({ section: module.name, msg: `Using JAVA_HOME=${openJdkPath}` })