From 14e713bff431924cd9b171cc982578774684c385 Mon Sep 17 00:00:00 2001 From: Tim Beyer Date: Thu, 16 Nov 2023 10:33:05 +0100 Subject: [PATCH] perf: do not compute log message until required (#5410) * perf: enable logging pipeline to defer resolving log messages until needed The idea is that sometimes we do heavy operations for silly logs, but we then discard just the log output. Instead, we can pass a callback and if the log is never needed for display, it won't actually call the heavy operations. * perf: convert heavy silly logs into deferred logs * perf: add memoization to log callback There might be multiple loggers resolving the message eventually. Wrap it in `memoize` so that it only gets resolved once. * fix: resolve messages in logs toString method * test: fix log warning test --- core/src/build-staging/build-staging.ts | 2 +- core/src/cache.ts | 14 ++--- core/src/cli/autocomplete.ts | 2 +- core/src/cli/helpers.ts | 2 +- core/src/cloud/api.ts | 6 +-- core/src/cloud/buffered-event-stream.ts | 18 +++---- core/src/commands/base.ts | 6 +-- core/src/config/workflow.ts | 4 +- core/src/garden.ts | 32 ++++++------ core/src/graph/actions.ts | 12 ++--- core/src/graph/nodes.ts | 4 +- core/src/graph/solver.ts | 12 ++--- core/src/logger/log-entry.ts | 52 +++++++++++++------ core/src/logger/renderers.ts | 12 +++-- core/src/monitors/manager.ts | 6 +-- core/src/mutagen.ts | 7 ++- core/src/plugins.ts | 8 +-- core/src/plugins/kubernetes/api.ts | 10 ++-- .../kubernetes/container/build/buildkit.ts | 2 +- .../kubernetes/container/build/kaniko.ts | 2 +- core/src/plugins/kubernetes/helm/common.ts | 2 +- .../src/plugins/kubernetes/helm/deployment.ts | 4 +- core/src/plugins/kubernetes/helm/logs.ts | 2 +- core/src/plugins/kubernetes/helm/status.ts | 2 +- core/src/plugins/kubernetes/logs.ts | 10 ++-- core/src/plugins/kubernetes/port-forward.ts | 6 +-- core/src/plugins/kubernetes/status/status.ts | 2 +- .../plugins/otel-collector/otel-collector.ts | 2 +- core/src/proxy.ts | 2 +- core/src/resolve-module.ts | 24 +++++---- core/src/router/base.ts | 6 +-- core/src/router/module.ts | 6 +-- core/src/router/provider.ts | 12 ++--- core/src/router/router.ts | 2 +- core/src/server/server.ts | 2 +- core/src/tasks/resolve-action.ts | 2 +- core/src/tasks/resolve-provider.ts | 26 +++++----- core/src/template-string/template-string.ts | 2 +- core/src/util/ext-tools.ts | 2 +- core/src/util/sync.ts | 4 +- core/src/util/testing.ts | 6 +-- core/src/vcs/git-repo.ts | 12 ++--- core/src/vcs/git.ts | 2 +- core/src/vcs/vcs.ts | 4 +- core/src/watch.ts | 2 +- .../src/plugins/kubernetes/helm/common.ts | 18 ++++--- .../kubernetes/kubernetes-type/common.ts | 5 +- core/test/unit/src/analytics/analytics.ts | 5 +- core/test/unit/src/commands/helpers.ts | 5 +- core/test/unit/src/commands/logs.ts | 4 +- core/test/unit/src/commands/workflow.ts | 4 +- core/test/unit/src/garden.ts | 21 +++++--- plugins/pulumi/src/helpers.ts | 2 +- 53 files changed, 233 insertions(+), 190 deletions(-) diff --git a/core/src/build-staging/build-staging.ts b/core/src/build-staging/build-staging.ts index 9fa18f28ae..4aedf8e292 100644 --- a/core/src/build-staging/build-staging.ts +++ b/core/src/build-staging/build-staging.ts @@ -57,7 +57,7 @@ export class BuildStaging { async syncFromSrc({ action, log, withDelete = true }: { action: BuildAction; log: Log; withDelete?: boolean }) { // We don't sync local exec modules to the build dir if (action.getConfig("buildAtSource")) { - log.silly(`Skipping syncing from source, action ${action.longDescription()} has buildAtSource set to true`) + log.silly(() => `Skipping syncing from source, action ${action.longDescription()} has buildAtSource set to true`) return } diff --git a/core/src/cache.ts b/core/src/cache.ts index 8cd680f682..5ea0411885 100644 --- a/core/src/cache.ts +++ b/core/src/cache.ts @@ -91,7 +91,7 @@ export class TreeCache { const stringKey = stringifyKey(key) - log.silly(`TreeCache: Setting value for key ${stringKey}`) + log.silly(() => `TreeCache: Setting value for key ${stringKey}`) let entry = this.cache.get(stringKey) @@ -137,10 +137,10 @@ export class TreeCache { const entry = this.cache.get(stringKey) if (entry) { - log.silly(`TreeCache: Found cached value for key ${stringKey}`) + log.silly(() => `TreeCache: Found cached value for key ${stringKey}`) return entry.value } else { - log.silly(`TreeCache: No cached value for key ${stringKey}`) + log.silly(() => `TreeCache: No cached value for key ${stringKey}`) return } } @@ -177,7 +177,7 @@ export class TreeCache { * Delete a specific entry from the cache. */ delete(log: Log, key: CacheKey) { - log.silly(`TreeCache: Deleting key ${stringifyKey(key)}`) + log.silly(() => `TreeCache: Deleting key ${stringifyKey(key)}`) const stringKey = stringifyKey(key) const entry = this.cache.get(stringKey) @@ -199,7 +199,7 @@ export class TreeCache { * Invalidates all cache entries whose context equals `context` */ invalidate(log: Log, context: CacheContext) { - log.silly(`TreeCache: Invalidating all caches for context ${stringifyKey(context)}`) + log.silly(() => `TreeCache: Invalidating all caches for context ${stringifyKey(context)}`) const node = this.getNode(context) @@ -214,7 +214,7 @@ export class TreeCache { * (i.e. the whole path from the tree root down to the context leaf) */ invalidateUp(log: Log, context: CacheContext) { - log.silly(`TreeCache: Invalidating caches up from context ${stringifyKey(context)}`) + log.silly(() => `TreeCache: Invalidating caches up from context ${stringifyKey(context)}`) let node = this.contextTree @@ -232,7 +232,7 @@ export class TreeCache { * (i.e. the context node and the whole tree below it) */ invalidateDown(log: Log, context: CacheContext) { - log.silly(`TreeCache: Invalidating caches down from context ${stringifyKey(context)}`) + log.silly(() => `TreeCache: Invalidating caches down from context ${stringifyKey(context)}`) const node = this.getNode(context) diff --git a/core/src/cli/autocomplete.ts b/core/src/cli/autocomplete.ts index 8efa120535..7cf74a41fe 100644 --- a/core/src/cli/autocomplete.ts +++ b/core/src/cli/autocomplete.ts @@ -113,7 +113,7 @@ export class Autocompleter { } private debug(msg: any) { - this.enableDebug && this.log.silly(typeof msg === "string" ? msg : stringify(msg)) + this.enableDebug && this.log.silly(() => (typeof msg === "string" ? msg : stringify(msg))) } private matchCommandNames(commands: Command[], input: string) { diff --git a/core/src/cli/helpers.ts b/core/src/cli/helpers.ts index 14a53cf191..4080ebe455 100644 --- a/core/src/cli/helpers.ts +++ b/core/src/cli/helpers.ts @@ -556,7 +556,7 @@ export function renderCommandErrors(logger: Logger, errors: Error[], log?: Log) error, }) // Output error details to console when log level is silly - errorLog.silly(error.toString(true)) + errorLog.silly(() => error.toString(true)) } if (logger.getWriters().file.length > 0) { diff --git a/core/src/cloud/api.ts b/core/src/cloud/api.ts index 44210d479e..686ded70ab 100644 --- a/core/src/cloud/api.ts +++ b/core/src/cloud/api.ts @@ -305,7 +305,7 @@ export class CloudApi { * token and deletes all others. */ static async getStoredAuthToken(log: Log, globalConfigStore: GlobalConfigStore, domain: string) { - log.silly(`Retrieving client auth token from config store`) + log.silly(() => `Retrieving client auth token from config store`) return globalConfigStore.get("clientAuthTokens", domain) } @@ -323,7 +323,7 @@ export class CloudApi { ): Promise { const tokenFromEnv = gardenEnv.GARDEN_AUTH_TOKEN if (tokenFromEnv) { - log.silly("Read client auth token from env") + log.silly(() => "Read client auth token from env") return tokenFromEnv } return (await CloudApi.getStoredAuthToken(log, globalConfigStore, domain))?.token @@ -480,7 +480,7 @@ export class CloudApi { private async apiFetch(path: string, params: ApiFetchParams): Promise> { const { method, headers, retry, retryDescription } = params - this.log.silly({ msg: `Calling Cloud API with ${method} ${path}` }) + this.log.silly(() => `Calling Cloud API with ${method} ${path}`) const token = await CloudApi.getAuthToken(this.log, this.globalConfigStore, this.domain) // TODO add more logging details const requestObj = { diff --git a/core/src/cloud/buffered-event-stream.ts b/core/src/cloud/buffered-event-stream.ts index 44c0fe9643..ea85e79ffc 100644 --- a/core/src/cloud/buffered-event-stream.ts +++ b/core/src/cloud/buffered-event-stream.ts @@ -181,7 +181,7 @@ export class BufferedEventStream { } this.garden.events.onAny(this.eventListener) - this.log.silly("BufferedEventStream: Connected") + this.log.silly(() => "BufferedEventStream: Connected") this.startInterval() } @@ -303,7 +303,7 @@ export class BufferedEventStream { private async postToTargets(description: string, path: string, data: ApiEventBatch | ApiLogBatch) { if (this.getTargets().length === 0) { - this.log.silly("No targets to send events to. Dropping them.") + this.log.silly(() => "No targets to send events to. Dropping them.") } try { @@ -321,10 +321,10 @@ export class BufferedEventStream { }) as any } const targetUrl = `${target.host}/${path}` - this.log.silly(`Flushing ${description} to ${targetUrl}`) - this.log.silly(`--------`) - this.log.silly(`data: ${stringify(data)}`) - this.log.silly(`--------`) + this.log.silly(() => `Flushing ${description} to ${targetUrl}`) + this.log.silly(() => `--------`) + this.log.silly(() => `data: ${stringify(data)}`) + this.log.silly(() => `--------`) const headers = makeAuthHeader(target.clientAuthToken || "") return got.post(`${targetUrl}`, { json: data, headers }) @@ -348,7 +348,7 @@ export class BufferedEventStream { return } - this.log.silly(`Flushing all remaining events and log entries`) + this.log.silly(() => `Flushing all remaining events and log entries`) const eventBatches = this.makeBatches(this.bufferedEvents) const logBatches = this.makeBatches(this.bufferedLogEntries) @@ -358,7 +358,7 @@ export class BufferedEventStream { ...logBatches.map((batch) => this.flushLogEntries(batch)), ]) - this.log.silly(`All events and log entries flushed`) + this.log.silly(() => `All events and log entries flushed`) } async flushBuffered() { @@ -397,7 +397,7 @@ export class BufferedEventStream { if (nextRecordBytes > this.maxBatchBytes) { this.log.error(`Event or log entry too large to flush (${nextRecordBytes} bytes), dropping it.`) // Note: This must be a silly log to avoid recursion - this.log.silly(stringify(buffered[0])) + this.log.silly(() => stringify(buffered[0])) buffered.shift() // Drop first record. continue } diff --git a/core/src/commands/base.ts b/core/src/commands/base.ts index a12d89bbdd..afe14920d2 100644 --- a/core/src/commands/base.ts +++ b/core/src/commands/base.ts @@ -358,7 +358,7 @@ export abstract class Command< try { if (cloudSession && this.streamEvents) { - log.silly(`Connecting Garden instance events to Cloud API`) + log.silly(() => `Connecting Garden instance events to Cloud API`) garden.events.emit("commandInfo", { ...commandInfo, environmentName: garden.environmentName, @@ -381,7 +381,7 @@ export abstract class Command< // FIXME: use file watching to be more surgical here, this is suboptimal garden.treeCache.invalidateDown(log, ["path"]) - log.silly(`Starting command '${this.getFullName()}' action`) + log.silly(() => `Starting command '${this.getFullName()}' action`) result = await this.action({ garden, cli, @@ -391,7 +391,7 @@ export abstract class Command< commandLine, parentCommand, }) - log.silly(`Completed command '${this.getFullName()}' action successfully`) + log.silly(() => `Completed command '${this.getFullName()}' action successfully`) } else { // The command is protected and the user decided to not continue with the execution. log.info("\nCommand aborted.") diff --git a/core/src/config/workflow.ts b/core/src/config/workflow.ts index 69dae02204..2a9a674367 100644 --- a/core/src/config/workflow.ts +++ b/core/src/config/workflow.ts @@ -348,7 +348,7 @@ export function resolveWorkflowConfig(garden: Garden, config: WorkflowConfig) { const log = garden.log const context = new WorkflowConfigContext(garden, garden.variables) - log.silly(`Resolving template strings for workflow ${config.name}`) + log.silly(() => `Resolving template strings for workflow ${config.name}`) const partialConfig = { // Don't allow templating in names and triggers @@ -380,7 +380,7 @@ export function resolveWorkflowConfig(garden: Garden, config: WorkflowConfig) { }) } - log.silly(`Validating config for workflow ${config.name}`) + log.silly(() => `Validating config for workflow ${config.name}`) resolvedPartialConfig = validateConfig({ config: resolvedPartialConfig, diff --git a/core/src/garden.ts b/core/src/garden.ts index 60820d13de..95dbfbb162 100644 --- a/core/src/garden.ts +++ b/core/src/garden.ts @@ -365,7 +365,7 @@ export class Garden { const buildDirCls = legacyBuildSync ? BuildStagingRsync : BuildStaging if (legacyBuildSync) { - this.log.silly(`Using rsync build staging mode`) + this.log.silly(() => `Using rsync build staging mode`) } this.buildStaging = new buildDirCls(params.projectRoot, params.gardenDirPath) @@ -428,7 +428,7 @@ export class Garden { }) if (!hasOtelCollectorProvider) { - this.log.silly("No OTEL collector configured, setting no-op exporter") + this.log.silly(() => "No OTEL collector configured, setting no-op exporter") configureNoOpExporter() } } @@ -635,7 +635,7 @@ export class Garden { return this.loadedPlugins } - this.log.silly(`Loading plugins`) + this.log.silly(() => `Loading plugins`) const rawConfigs = this.getRawProviderConfigs() this.loadedPlugins = await loadAndResolvePlugins(this.log, this.projectRoot, this.registeredPlugins, rawConfigs) @@ -707,7 +707,7 @@ export class Garden { return cloneDeep(this.resolvedProviders[name]) } - this.log.silly(`Resolving provider ${name}`) + this.log.silly(() => `Resolving provider ${name}`) const providers = await this.resolveProviders(log, false, [name]) const provider = providers[name] @@ -748,7 +748,7 @@ export class Garden { return } - log.silly(`Resolving providers`) + log.silly(() => `Resolving providers`) const providerLog = log.createLog({ name: "providers", showDuration: true }) providerLog.info("Getting status...") @@ -853,7 +853,7 @@ export class Garden { providerLog.success("Done") } - providerLog.silly(`Resolved providers: ${providers.map((p) => p.name).join(", ")}`) + providerLog.silly(() => `Resolved providers: ${providers.map((p) => p.name).join(", ")}`) }) return keyBy(providers, "name") @@ -1221,7 +1221,7 @@ export class Garden { } } - log.silly(`Resolving version for module ${moduleName}`) + log.silly(() => `Resolving version for module ${moduleName}`) const cacheContexts = [...moduleDependencies, moduleConfig].map((c: ModuleConfig) => getModuleCacheContext(c)) @@ -1261,7 +1261,7 @@ export class Garden { name: "scanForConfigs", }) async scanForConfigs(log: Log, path: string) { - log.silly(`Scanning for configs in ${path}`) + log.silly(() => `Scanning for configs in ${path}`) return findConfigPathsInPath({ vcs: this.vcs, @@ -1288,7 +1288,7 @@ export class Garden { return } - this.log.silly(`Scanning for configs (force=${force})`) + this.log.silly(() => `Scanning for configs (force=${force})`) // Add external sources that are defined at the project level. External sources are either kept in // the .garden/sources dir (and cloned there if needed), or they're linked to a local path via the link command. @@ -1419,13 +1419,15 @@ export class Garden { * Add an action config to the context, after validating and calling the appropriate configure plugin handler. */ protected addActionConfig(config: BaseActionConfig) { - this.log.silly(`Adding ${config.kind} action ${config.name}`) + this.log.silly(() => `Adding ${config.kind} action ${config.name}`) const key = actionReferenceToString(config) const existing = this.actionConfigs[config.kind][config.name] if (existing) { if (actionIsDisabled(config, this.environmentName)) { - this.log.silly(`Skipping action ${key} because it is disabled and another action with the same key exists`) + this.log.silly( + () => `Skipping action ${key} because it is disabled and another action with the same key exists` + ) return } else if (!actionIsDisabled(existing, this.environmentName)) { const paths = [ @@ -1448,7 +1450,7 @@ export class Garden { */ private addModuleConfig(config: ModuleConfig) { const key = config.name - this.log.silly(`Adding module ${key}`) + this.log.silly(() => `Adding module ${key}`) const existing = this.moduleConfigs[key] if (existing) { @@ -1470,7 +1472,7 @@ export class Garden { */ private addWorkflow(config: WorkflowConfig) { const key = config.name - this.log.silly(`Adding workflow ${key}`) + this.log.silly(() => `Adding workflow ${key}`) const existing = this.workflowConfigs[key] @@ -1496,9 +1498,9 @@ export class Garden { }) private async loadResources(configPath: string): Promise<(GardenResource | ModuleConfig)[]> { configPath = resolve(this.projectRoot, configPath) - this.log.silly(`Load configs from ${configPath}`) + this.log.silly(() => `Load configs from ${configPath}`) const resources = await loadConfigResources(this.log, this.projectRoot, configPath) - this.log.silly(`Loaded configs from ${configPath}`) + this.log.silly(() => `Loaded configs from ${configPath}`) return resources.filter((r) => r.kind && r.kind !== "Project") } diff --git a/core/src/graph/actions.ts b/core/src/graph/actions.ts index 53ecae9648..6a4f2d86f7 100644 --- a/core/src/graph/actions.ts +++ b/core/src/graph/actions.ts @@ -101,10 +101,10 @@ export const actionConfigsToGraph = profileAsync(async function actionConfigsToG if (existing) { if (actionIsDisabled(config, environmentName)) { - log.silly(`Skipping disabled action ${key} in favor of other action with same key`) + log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`) return } else if (actionIsDisabled(existing, environmentName)) { - log.silly(`Skipping disabled action ${key} in favor of other action with same key`) + log.silly(() => `Skipping disabled action ${key} in favor of other action with same key`) configsByKey[key] = config return } else { @@ -218,11 +218,11 @@ function getActionMode(config: ActionConfig, actionModes: ActionModeMap, log: Lo if (key === pattern) { explicitMode = true mode = "sync" - log.silly(`Action ${key} set to ${mode} mode, matched on exact key`) + log.silly(() => `Action ${key} set to ${mode} mode, matched on exact key`) break } else if (minimatch(key, pattern)) { mode = "sync" - log.silly(`Action ${key} set to ${mode} mode, matched with pattern '${pattern}'`) + log.silly(() => `Action ${key} set to ${mode} mode, matched with pattern '${pattern}'`) break } } @@ -233,11 +233,11 @@ function getActionMode(config: ActionConfig, actionModes: ActionModeMap, log: Lo if (key === pattern) { explicitMode = true mode = "local" - log.silly(`Action ${key} set to ${mode} mode, matched on exact key`) + log.silly(() => `Action ${key} set to ${mode} mode, matched on exact key`) break } else if (minimatch(key, pattern)) { mode = "local" - log.silly(`Action ${key} set to ${mode} mode, matched with pattern '${pattern}'`) + log.silly(() => `Action ${key} set to ${mode} mode, matched with pattern '${pattern}'`) break } } diff --git a/core/src/graph/nodes.ts b/core/src/graph/nodes.ts index e6cde57a0a..3f5993beb0 100644 --- a/core/src/graph/nodes.ts +++ b/core/src/graph/nodes.ts @@ -269,7 +269,7 @@ export class ProcessTaskNode extends TaskNode { } async execute() { - this.task.log.silly(`Executing node ${styles.underline(this.getKey())}`) + this.task.log.silly(() => `Executing node ${styles.underline(this.getKey())}`) const statusTask = this.getNode("status", this.task) // TODO: make this more type-safe @@ -323,7 +323,7 @@ export class StatusTaskNode extends TaskNode { } async execute() { - this.task.log.silly(`Executing node ${styles.underline(this.getKey())}`) + this.task.log.silly(() => `Executing node ${styles.underline(this.getKey())}`) const dependencyResults = this.getDependencyResults() try { diff --git a/core/src/graph/solver.ts b/core/src/graph/solver.ts index 42eca6e973..94401b8069 100644 --- a/core/src/graph/solver.ts +++ b/core/src/graph/solver.ts @@ -406,28 +406,28 @@ export class GraphSolver extends TypedEventEmitter { if (status?.aborted || status?.error) { // Status is either aborted or failed - this.log.silly(`Request ${request.getKey()} status: ${resultToString(status)}`) + this.log.silly(() => `Request ${request.getKey()} status: ${resultToString(status)}`) this.completeTask({ ...status, node: request }) } else if (request.statusOnly && status !== undefined) { // Status is resolved, and that's all we need - this.log.silly(`Request ${request.getKey()} is statusOnly and the status is available. Completing.`) + this.log.silly(() => `Request ${request.getKey()} is statusOnly and the status is available. Completing.`) this.completeTask({ ...status, node: request }) } else if (status === undefined) { // We're not forcing, and we don't have the status yet, so we ensure that's pending - this.log.silly(`Request ${request.getKey()} is missing its status.`) + this.log.silly(() => `Request ${request.getKey()} is missing its status.`) this.ensurePendingNode(statusNode, request) } else if (status.result?.state === "ready" && !task.force) { - this.log.silly(`Request ${request.getKey()} has ready status and force=false, no need to process.`) + this.log.silly(() => `Request ${request.getKey()} has ready status and force=false, no need to process.`) this.completeTask({ ...status, node: request }) } else { const processNode = this.getNode({ type: "process", task, statusOnly: request.statusOnly }) const result = this.getPendingResult(processNode) if (result) { - this.log.silly(`Request ${request.getKey()} has been processed.`) + this.log.silly(() => `Request ${request.getKey()} has been processed.`) this.completeTask({ ...result, node: request }) } else { - this.log.silly(`Request ${request.getKey()} should be processed. Status: ${resultToString(status)}`) + this.log.silly(() => `Request ${request.getKey()} should be processed. Status: ${resultToString(status)}`) this.ensurePendingNode(processNode, request) } } diff --git a/core/src/logger/log-entry.ts b/core/src/logger/log-entry.ts index dbc3b08776..5437fe741a 100644 --- a/core/src/logger/log-entry.ts +++ b/core/src/logger/log-entry.ts @@ -8,7 +8,7 @@ import type logSymbols from "log-symbols" import cloneDeep from "fast-copy" -import { round } from "lodash-es" +import { round, memoize } from "lodash-es" import { LogLevel } from "./logger.js" import type { Omit } from "../util/util.js" @@ -132,6 +132,19 @@ interface CreateCoreLogParams origin?: string } +export type Msg = string | (() => string) + +export function resolveMsg(logEntry: LogEntry): string | undefined { + return typeof logEntry.msg === "function" ? logEntry.msg() : logEntry.msg +} + +export function transformMsg(msg: Msg, transformer: (input: string) => string): Msg { + if (typeof msg === "function") { + return () => transformer(msg()) + } + return transformer(msg) +} + export interface LogEntry extends Pick, "key" | "timestamp" | "metadata" | "context"> { /** @@ -142,7 +155,7 @@ export interface LogEntry /** * The actual text of the log message. */ - msg?: string + msg?: Msg /** * A "raw" version of the log line. This field is preferred over 'msg' if set when rendering * log entries in the web dashboard. @@ -150,7 +163,7 @@ export interface LogEntry * Use this if the entry has a msg that doesn't render well in the UI. In that case you * can set terminal log line via the 'msg' field and a web friendly version via this field. */ - rawMsg?: string + rawMsg?: Msg /** * A symbol that's printed with the log message to indicate it's type (e.g. "error" or "success"). */ @@ -246,6 +259,11 @@ export abstract class Log implements LogConf metadata = { ...cloneDeep(this.metadata || {}), ...(params.metadata || {}) } } + let msg = params.msg + if (typeof msg === "function") { + msg = memoize(msg) + } + return { ...params, parentLogKey: this.key, @@ -257,6 +275,7 @@ export abstract class Log implements LogConf timestamp: new Date().toISOString(), metadata, key: uniqid(), + msg, } } @@ -302,14 +321,17 @@ export abstract class Log implements LogConf // log line in question). const showDuration = params.showDuration !== undefined ? params.showDuration : this.showDuration if (showDuration && params.msg) { - return `${params.msg} ${renderDuration(this.getDuration(1))}` + const duration = this.getDuration(1) + return transformMsg(params.msg, (msg) => { + return `${msg} ${renderDuration(duration)}` + }) } return params.msg } - private resolveCreateParams(level: LogLevel, params: string | LogParams): CreateLogEntryParams { - if (typeof params === "string") { + private resolveCreateParams(level: LogLevel, params: string | (() => string) | LogParams): CreateLogEntryParams { + if (typeof params === "string" || typeof params === "function") { return { msg: params, level } } return { ...params, level } @@ -318,7 +340,7 @@ export abstract class Log implements LogConf /** * Render a log entry at the silly level. This is the highest verbosity. */ - silly(params: string | LogParams) { + silly(params: Msg | LogParams) { return this.log(this.resolveCreateParams(LogLevel.silly, params)) } @@ -326,7 +348,7 @@ export abstract class Log implements LogConf * Render a log entry at the debug level. Intended for internal information * which can be useful for debugging. */ - debug(params: string | LogParams) { + debug(params: Msg | LogParams) { return this.log(this.resolveCreateParams(LogLevel.debug, params)) } @@ -334,7 +356,7 @@ export abstract class Log implements LogConf * Render a log entry at the verbose level. Intended for logs generated when * actions are executed. E.g. logs from Kubernetes. */ - verbose(params: string | LogParams) { + verbose(params: Msg | LogParams) { return this.log(this.resolveCreateParams(LogLevel.verbose, params)) } @@ -342,14 +364,14 @@ export abstract class Log implements LogConf * Render a log entry at the info level. Intended for framework level logs * such as information about the action being executed. */ - info(params: string | (LogParams & { symbol?: Extract })) { + info(params: Msg | (LogParams & { symbol?: Extract })) { return this.log(this.resolveCreateParams(LogLevel.info, params)) } /** * Render a log entry at the warning level. */ - warn(params: string | Omit) { + warn(params: Msg | Omit) { return this.log({ ...this.resolveCreateParams(LogLevel.warn, params), symbol: "warning" as LogSymbol, @@ -360,7 +382,7 @@ export abstract class Log implements LogConf * Render a log entry at the error level. * Appends the duration to the message if showDuration=true. */ - error(params: string | Omit) { + error(params: Msg | Omit) { const resolved = { ...this.resolveCreateParams(LogLevel.error, params), symbol: "error" as LogSymbol, @@ -379,7 +401,7 @@ export abstract class Log implements LogConf * TODO @eysi: This should really happen in the renderer and the parent log context * timestamp, the log entry timestamp, and showDuration should just be fields on the entry. */ - success(params: string | Omit) { + success(params: Msg | Omit) { const resolved = { ...this.resolveCreateParams(LogLevel.info, params), symbol: "success" as LogSymbol, @@ -388,7 +410,7 @@ export abstract class Log implements LogConf const style = resolved.level === LogLevel.info ? styles.success : getStyle(resolved.level) return this.log({ ...resolved, - msg: style(this.getMsgWithDuration(resolved) || ""), + msg: transformMsg(this.getMsgWithDuration(resolved) || "", (msg) => style(msg)), }) } @@ -432,7 +454,7 @@ export abstract class Log implements LogConf toString(filter?: (log: LogEntry) => boolean) { return this.getLogEntries() .filter((entry) => (filter ? filter(entry) : true)) - .map((entry) => entry.msg) + .map((entry) => resolveMsg(entry)) .join("\n") } diff --git a/core/src/logger/renderers.ts b/core/src/logger/renderers.ts index 9675ac949b..d643bc36ee 100644 --- a/core/src/logger/renderers.ts +++ b/core/src/logger/renderers.ts @@ -12,7 +12,7 @@ import stripAnsi from "strip-ansi" import { isArray, repeat, trim } from "lodash-es" import stringWidth from "string-width" import format from "date-fns/format/index.js" -import type { LogEntry } from "./log-entry.js" +import { resolveMsg, type LogEntry } from "./log-entry.js" import type { JsonLogEntry } from "./writers/json-terminal-writer.js" import { highlightYaml, safeDumpYaml } from "../util/serialization.js" import type { Logger } from "./logger.js" @@ -38,7 +38,8 @@ export function combineRenders(entry: LogEntry, logger: Logger, renderers: Rende } export function renderError(entry: LogEntry): string { - const { error, msg } = entry + const { error } = entry + const msg = resolveMsg(entry) let out = "" @@ -114,7 +115,8 @@ export function getSection(entry: LogEntry): string | null { } export function renderMsg(entry: LogEntry): string { - const { context, level, msg } = entry + const { context, level } = entry + const msg = resolveMsg(entry) const { origin } = context const style = getStyle(level) @@ -210,12 +212,12 @@ export function cleanWhitespace(str: string) { // TODO: Include individual message states with timestamp export function formatForJson(entry: LogEntry): JsonLogEntry { - const { msg, metadata, timestamp } = entry + const { metadata, timestamp } = entry const errorDetail = entry.error && entry ? toGardenError(entry.error).toString(true) : undefined const section = renderSection(entry) const jsonLogEntry: JsonLogEntry = { - msg: cleanForJSON(msg), + msg: cleanForJSON(resolveMsg(entry)), data: entry.data, metadata, // TODO @eysi: Should we include the section here or rather just show the context? diff --git a/core/src/monitors/manager.ts b/core/src/monitors/manager.ts index d6435a313f..e978d403b8 100644 --- a/core/src/monitors/manager.ts +++ b/core/src/monitors/manager.ts @@ -112,7 +112,7 @@ export class MonitorManager extends TypedEventEmitter { const status = this.getStatus(monitor) if (status !== "stopped" && status !== "stopping") { - this.log.silly(`${monitor.description()} already ${status}.`) + this.log.silly(() => `${monitor.description()} already ${status}.`) return } @@ -127,7 +127,7 @@ export class MonitorManager extends TypedEventEmitter { // NOTE: Consider calling this.stop() in that case to guarantee the actual monitors stops (would assume stopping is idempotent). const currentStatus = this.getStatus(monitor) if (currentStatus === "starting") { - this.log.silly(`${monitor.description} started successfully`) + this.log.silly(() => `${monitor.description} started successfully`) this.setStatus(monitor, "started") } else { this.log.silly( @@ -159,7 +159,7 @@ export class MonitorManager extends TypedEventEmitter { if (currentStatus === "stopping") { this.setStatus(monitor, "stopped") this.removeAllListeners() - log.silly(`${monitor.description()} stopped.`) + log.silly(() => `${monitor.description()} stopped.`) } else { this.log.silly( `${monitor.description} status changed from 'stopping' to ${currentStatus} while being stopped. Will not set status to 'stopped'.` diff --git a/core/src/mutagen.ts b/core/src/mutagen.ts index c11704dd79..348add8873 100644 --- a/core/src/mutagen.ts +++ b/core/src/mutagen.ts @@ -208,7 +208,7 @@ class _MutagenMonitor extends TypedEventEmitter { await ensureDataDir(dataDir) const mutagenOpts = [mutagenPath, "sync", "monitor", "--template", "{{ json . }}", "--long"] - log.silly(`Spawning mutagen using respawn: "${mutagenOpts.join(" ")}"`) + log.silly(() => `Spawning mutagen using respawn: "${mutagenOpts.join(" ")}"`) const proc = respawn(mutagenOpts, { cwd: dataDir, @@ -246,7 +246,10 @@ class _MutagenMonitor extends TypedEventEmitter { // Make sure we don't spam with repeated messages lastDaemonError = msg } else { - log.silly({ symbol: "empty", msg }) + log.silly({ + symbol: "empty", + msg, + }) } } diff --git a/core/src/plugins.ts b/core/src/plugins.ts index f0818ce983..93fb3c24d5 100644 --- a/core/src/plugins.ts +++ b/core/src/plugins.ts @@ -66,7 +66,7 @@ export function resolvePlugins( return initializedPlugins[name] } - log.silly(`Validating plugin ${name}`) + log.silly(() => `Validating plugin ${name}`) let plugin = loadedPlugins[name] if (!plugin) { @@ -125,7 +125,7 @@ export function resolvePlugins( } } - log.silly(`Done loading plugin ${name}`) + log.silly(() => `Done loading plugin ${name}`) return plugin } @@ -188,7 +188,7 @@ function validateOutputSchemas( export async function loadPlugin(log: Log, projectRoot: string, nameOrPlugin: RegisterPluginParam) { let plugin: GardenPluginSpec - log.silly(`Loading plugin ${isString(nameOrPlugin) ? nameOrPlugin : nameOrPlugin.name}`) + log.silly(() => `Loading plugin ${isString(nameOrPlugin) ? nameOrPlugin : nameOrPlugin.name}`) if (isString(nameOrPlugin)) { let moduleNameOrLocation = nameOrPlugin @@ -227,7 +227,7 @@ export async function loadPlugin(log: Log, projectRoot: string, nameOrPlugin: Re plugin = nameOrPlugin } - log.silly(`Loaded plugin ${plugin.name}`) + log.silly(() => `Loaded plugin ${plugin.name}`) return plugin } diff --git a/core/src/plugins/kubernetes/api.ts b/core/src/plugins/kubernetes/api.ts index 4d605df9b4..fc24b845c9 100644 --- a/core/src/plugins/kubernetes/api.ts +++ b/core/src/plugins/kubernetes/api.ts @@ -461,7 +461,7 @@ export class KubeApi { fetchOptions.agent = await createProxyAgent(fetchOptions.agent) try { - log.silly(`${requestOptions.method.toUpperCase()} ${url}`) + log.silly(() => `${requestOptions.method.toUpperCase()} ${url}`) const response = await fetch(url, fetchOptions) if (response.status >= 400) { @@ -509,7 +509,7 @@ export class KubeApi { * Fetch the specified resource from the cluster. */ async read({ log, namespace, apiVersion, kind, name }: ReadParams): Promise { - log.silly(`Fetching Kubernetes resource ${apiVersion}/${kind}/${name}`) + log.silly(() => `Fetching Kubernetes resource ${apiVersion}/${kind}/${name}`) const typePath = await this.getResourceTypeApiPath({ log, @@ -533,7 +533,7 @@ export class KubeApi { * Given a manifest, attempt to read the matching resource from the cluster. */ async readBySpec({ log, namespace, manifest }: ReadBySpecParams): Promise { - log.silly(`Fetching Kubernetes resource ${manifest.apiVersion}/${manifest.kind}/${manifest.metadata.name}`) + log.silly(() => `Fetching Kubernetes resource ${manifest.apiVersion}/${manifest.kind}/${manifest.metadata.name}`) const apiPath = await this.getResourceApiPathFromManifest({ manifest, log, namespace }) @@ -635,7 +635,7 @@ export class KubeApi { } async replace({ log, resource, namespace }: { log: Log; resource: KubernetesServerResource; namespace?: string }) { - log.silly(`Replacing Kubernetes resource ${resource.apiVersion}/${resource.kind}/${resource.metadata.name}`) + log.silly(() => `Replacing Kubernetes resource ${resource.apiVersion}/${resource.kind}/${resource.metadata.name}`) const apiPath = await this.getResourceApiPathFromManifest({ manifest: resource, log, namespace }) @@ -663,7 +663,7 @@ export class KubeApi { } async deleteBySpec({ namespace, manifest, log }: { namespace: string; manifest: KubernetesResource; log: Log }) { - log.silly(`Deleting Kubernetes resource ${manifest.apiVersion}/${manifest.kind}/${manifest.metadata.name}`) + log.silly(() => `Deleting Kubernetes resource ${manifest.apiVersion}/${manifest.kind}/${manifest.metadata.name}`) const apiPath = await this.getResourceApiPathFromManifest({ manifest, log, namespace }) diff --git a/core/src/plugins/kubernetes/container/build/buildkit.ts b/core/src/plugins/kubernetes/container/build/buildkit.ts index c07de229fb..31f01d1075 100644 --- a/core/src/plugins/kubernetes/container/build/buildkit.ts +++ b/core/src/plugins/kubernetes/container/build/buildkit.ts @@ -163,7 +163,7 @@ export const buildkitBuildHandler: BuildHandler = async (params) => { const buildLog = buildRes.log - log.silly(buildLog) + log.silly(() => buildLog) return { state: "ready", diff --git a/core/src/plugins/kubernetes/container/build/kaniko.ts b/core/src/plugins/kubernetes/container/build/kaniko.ts index 2dddfda7c4..0b18dd082d 100644 --- a/core/src/plugins/kubernetes/container/build/kaniko.ts +++ b/core/src/plugins/kubernetes/container/build/kaniko.ts @@ -189,7 +189,7 @@ export const kanikoBuild: BuildHandler = async (params) => { }) } - log.silly(buildLog) + log.silly(() => buildLog) return { state: "ready", diff --git a/core/src/plugins/kubernetes/helm/common.ts b/core/src/plugins/kubernetes/helm/common.ts index 313c97132e..c037564a91 100644 --- a/core/src/plugins/kubernetes/helm/common.ts +++ b/core/src/plugins/kubernetes/helm/common.ts @@ -102,7 +102,7 @@ export async function prepareTemplates({ ctx, action, log }: PrepareTemplatesPar } const valuesPath = await temporaryWrite(safeDumpYaml(values)) - log.silly(`Wrote chart values to ${valuesPath}`) + log.silly(() => `Wrote chart values to ${valuesPath}`) const releaseName = getReleaseName(action) const namespace = await getActionNamespace({ diff --git a/core/src/plugins/kubernetes/helm/deployment.ts b/core/src/plugins/kubernetes/helm/deployment.ts index 0e02641fbc..146c59c249 100644 --- a/core/src/plugins/kubernetes/helm/deployment.ts +++ b/core/src/plugins/kubernetes/helm/deployment.ts @@ -65,14 +65,14 @@ export const helmDeploy: DeployActionHandler<"deploy", HelmDeployAction> = async } if (releaseStatus.state === "missing") { - log.silly(`Installing Helm release ${releaseName}`) + log.silly(() => `Installing Helm release ${releaseName}`) const installArgs = ["install", releaseName, ...reference, ...commonArgs] if (force && !ctx.production) { installArgs.push("--replace") } await helm({ ctx: k8sCtx, namespace, log, args: [...installArgs], emitLogEvents: true }) } else { - log.silly(`Upgrading Helm release ${releaseName}`) + log.silly(() => `Upgrading Helm release ${releaseName}`) const upgradeArgs = ["upgrade", releaseName, ...reference, "--install", ...commonArgs] await helm({ ctx: k8sCtx, namespace, log, args: [...upgradeArgs], emitLogEvents: true }) diff --git a/core/src/plugins/kubernetes/helm/logs.ts b/core/src/plugins/kubernetes/helm/logs.ts index eb7307798f..09e7bc1ddf 100644 --- a/core/src/plugins/kubernetes/helm/logs.ts +++ b/core/src/plugins/kubernetes/helm/logs.ts @@ -42,7 +42,7 @@ export const getHelmDeployLogs: DeployActionHandler<"getLogs", HelmDeployAction> break } catch (err) { log.debug(`Failed getting deployed resources. Retrying...`) - log.silly(String(err)) + log.silly(() => String(err)) } await sleep(2000) } diff --git a/core/src/plugins/kubernetes/helm/status.ts b/core/src/plugins/kubernetes/helm/status.ts index 4dfa3f1ba5..fedd6299f7 100644 --- a/core/src/plugins/kubernetes/helm/status.ts +++ b/core/src/plugins/kubernetes/helm/status.ts @@ -179,7 +179,7 @@ export async function getReleaseStatus({ log: Log }): Promise { try { - log.silly(`Getting the release status for ${releaseName}`) + log.silly(() => `Getting the release status for ${releaseName}`) const namespace = await getActionNamespace({ ctx, log, diff --git a/core/src/plugins/kubernetes/logs.ts b/core/src/plugins/kubernetes/logs.ts index 9bc384612b..633abdb171 100644 --- a/core/src/plugins/kubernetes/logs.ts +++ b/core/src/plugins/kubernetes/logs.ts @@ -303,7 +303,7 @@ export class K8sLogFollower { if (error instanceof KubernetesError) { reason = `HTTP request failed with status ${error.code}` } - this.log.silly(``) + this.log.silly(() => ``) } /** @@ -314,7 +314,7 @@ export class K8sLogFollower { * the user runs `garden deploy`. */ const stopRetrying = (why: string) => { - this.log.silly(``) + this.log.silly(() => ``) connection.shouldRetry = false } @@ -333,7 +333,7 @@ export class K8sLogFollower { if (["Succeeded", "Failed"].includes(phase) && !wasError) { stopRetrying(`The Pod phase is terminal (${phase})`) } else { - this.log.silly(``) + this.log.silly(() => ``) } } catch (e) { if (e instanceof KubernetesError) { @@ -427,7 +427,7 @@ export class K8sLogFollower { `Encountered a log message without timestamp. This is probably an error message from the Kubernetes API: ${line}` ) } else if (this.isDuplicate({ connection, timestamp, msg })) { - this.log.silly(`Dropping duplicate log message: ${line}`) + this.log.silly(() => `Dropping duplicate log message: ${line}`) } else { this.updateLastLogEntries({ connection, timestamp, msg }) this.write({ @@ -451,7 +451,7 @@ export class K8sLogFollower { since, sinceOnRetry, }) - this.log.silly(``) + this.log.silly(() => ``) } catch (err) { await this.handleConnectionClose(connection, "error", toKubernetesError(err, context)) return diff --git a/core/src/plugins/kubernetes/port-forward.ts b/core/src/plugins/kubernetes/port-forward.ts index b5887e641b..67a86189e0 100644 --- a/core/src/plugins/kubernetes/port-forward.ts +++ b/core/src/plugins/kubernetes/port-forward.ts @@ -114,7 +114,7 @@ export async function getPortForward({ log, }) - log.silly(`Running 'kubectl ${portForwardArgs.join(" ")}'`) + log.silly(() => `Running 'kubectl ${portForwardArgs.join(" ")}'`) // Need to use execa directly to use its cleanup mechanism, otherwise processes can linger on Windows const kubectlPath = await kubectl(k8sCtx, k8sCtx.provider).ensurePath(log) @@ -153,7 +153,7 @@ export async function getPortForward({ } // This is unfortunately the best indication that we have that the connection is up... - log.silly(`[${targetResource} port forwarder] ${line}`) + log.silly(() => `[${targetResource} port forwarder] ${line}`) output += line if (line.toString().includes("Forwarding from ")) { @@ -166,7 +166,7 @@ export async function getPortForward({ }) proc.stderr!.on("data", (line) => { - log.silly(`[${targetResource} port forwarder] ${line}`) + log.silly(() => `[${targetResource} port forwarder] ${line}`) output += line // Following this: https://github.com/nkubala/skaffold/blob/0d52436f792b862e06311c42065afd8e2363771c/pkg/skaffold/kubernetes/portforward/kubectl_forwarder.go#L177 // Note: It'd be much more robust to avoid kubectl here, but it's more work to implement. diff --git a/core/src/plugins/kubernetes/status/status.ts b/core/src/plugins/kubernetes/status/status.ts index 4a0db3679b..43abea9c63 100644 --- a/core/src/plugins/kubernetes/status/status.ts +++ b/core/src/plugins/kubernetes/status/status.ts @@ -545,7 +545,7 @@ export async function compareDeployedResources({ if (!isSubset(deployedResource, manifest)) { if (manifest) { log.debug(`Resource ${manifest.metadata.name} is not a superset of deployed resource`) - log.silly(diffString(deployedResource, manifest)) + log.silly(() => diffString(deployedResource, manifest)) } result.state = "outdated" return result diff --git a/core/src/plugins/otel-collector/otel-collector.ts b/core/src/plugins/otel-collector/otel-collector.ts index c0dd718bbc..ee73fcbb63 100644 --- a/core/src/plugins/otel-collector/otel-collector.ts +++ b/core/src/plugins/otel-collector/otel-collector.ts @@ -158,7 +158,7 @@ provider.addHandler("prepareEnvironment", async ({ ctx, log }) => { scopedLog.debug(`Creating temporary config in ${configPath}`) await writeFile(configPath, configFileYaml) - scopedLog.silly("Starting collector process") + scopedLog.silly(() => "Starting collector process") const collectorProcess = await wrapActiveSpan("fetchAndRun", () => ctx.tools["otel-collector.otel-collector"].spawn({ log, diff --git a/core/src/proxy.ts b/core/src/proxy.ts index 5312c61234..774d89b2d3 100644 --- a/core/src/proxy.ts +++ b/core/src/proxy.ts @@ -128,7 +128,7 @@ async function createProxy({ garden, graph, log, action, spec, events }: StartPo log.warn(`→ Could not start port forward to ${key} (will retry): ${msg}`) lastPrintedError = msg } else { - log.silly(`→ Could not start port forward to ${key} (will retry): ${msg}`) + log.silly(() => `→ Could not start port forward to ${key} (will retry): ${msg}`) } } diff --git a/core/src/resolve-module.ts b/core/src/resolve-module.ts index 964e8e4a75..de8e61b6fa 100644 --- a/core/src/resolve-module.ts +++ b/core/src/resolve-module.ts @@ -139,7 +139,7 @@ export class ModuleResolver { return } - this.log.silly(`ModuleResolver: Process node ${moduleKey}`) + this.log.silly(() => `ModuleResolver: Process node ${moduleKey}`) inFlight.add(moduleKey) // Resolve configuration, unless previously resolved. @@ -153,7 +153,7 @@ export class ModuleResolver { if (!resolvedConfig) { const rawConfig = this.rawConfigsByKey[moduleKey] - this.log.silly(`ModuleResolver: Resolve config ${moduleKey}`) + this.log.silly(() => `ModuleResolver: Resolve config ${moduleKey}`) resolvedConfig = resolvedConfigs[moduleKey] = await this.resolveModuleConfig(rawConfig, resolvedDependencies) // Check if any new build dependencies were added by the configure handler @@ -161,7 +161,7 @@ export class ModuleResolver { const depKey = dep.name if (!dependencyNames.includes(depKey)) { - this.log.silly(`ModuleResolver: Found new dependency ${depKey} when resolving ${moduleKey}`) + this.log.silly(() => `ModuleResolver: Found new dependency ${depKey} when resolving ${moduleKey}`) // We throw if the build dependency can't be found at all if (!fullGraph.hasNode(depKey)) { @@ -173,7 +173,9 @@ export class ModuleResolver { // The dependency may already have been processed, we don't want to add it to the graph in that case if (processingGraph.hasNode(depKey)) { - this.log.silly(`ModuleResolver: Need to re-resolve ${moduleKey} after processing new dependencies`) + this.log.silly( + () => `ModuleResolver: Need to re-resolve ${moduleKey} after processing new dependencies` + ) processingGraph.addDependency(moduleKey, depKey) } } @@ -191,11 +193,11 @@ export class ModuleResolver { dependencies: resolvedDependencies, repoRoot: minimalRoots[resolvedConfig.path], }) - this.log.silly(`ModuleResolver: Module ${moduleKey} resolved`) + this.log.silly(() => `ModuleResolver: Module ${moduleKey} resolved`) processingGraph.removeNode(moduleKey) } } catch (err) { - this.log.silly(`ModuleResolver: Node ${moduleKey} failed: ${err}`) + this.log.silly(() => `ModuleResolver: Node ${moduleKey} failed: ${err}`) errors[moduleKey] = toGardenError(err) } @@ -230,7 +232,7 @@ export class ModuleResolver { throw err } - this.log.silly(`ModuleResolver: Process ${batch.length} leaves`) + this.log.silly(() => `ModuleResolver: Process ${batch.length} leaves`) if (batch.length === 0) { return @@ -250,7 +252,7 @@ export class ModuleResolver { let i = 0 while (processingGraph.size() > 0) { - this.log.silly(`ModuleResolver: Loop ${++i}`) + this.log.silly(() => `ModuleResolver: Loop ${++i}`) await processLeaves() } @@ -487,7 +489,7 @@ export class ModuleResolver { for (const base of bases) { if (base.schema) { - garden.log.silly(`Validating '${config.name}' config against '${base.name}' schema`) + garden.log.silly(() => `Validating '${config.name}' config against '${base.name}' schema`) config.spec = validateWithPath({ config: config.spec, @@ -528,7 +530,7 @@ export class ModuleResolver { dependencies: GardenModule[] repoRoot: string }) { - this.log.silly(`Resolving module ${resolvedConfig.name}`) + this.log.silly(() => `Resolving module ${resolvedConfig.name}`) // Write module files const configContext = new ModuleConfigContext({ @@ -635,7 +637,7 @@ export class ModuleResolver { for (const base of bases) { if (base.moduleOutputsSchema) { - this.log.silly(`Validating '${module.name}' module outputs against '${base.name}' schema`) + this.log.silly(() => `Validating '${module.name}' module outputs against '${base.name}' schema`) module.outputs = validateWithPath({ config: module.outputs, diff --git a/core/src/router/base.ts b/core/src/router/base.ts index 37a0c2ba7c..e870331b38 100644 --- a/core/src/router/base.ts +++ b/core/src/router/base.ts @@ -212,7 +212,7 @@ export abstract class BaseActionRouter extends BaseRouter for (const plugin of params.configuredPlugins) { const created = plugin.createActionTypes[kind] || [] for (const spec of created) { - garden.log.silly(`Registering ${kind} type ${spec.name}`) + garden.log.silly(() => `Registering ${kind} type ${spec.name}`) this.definitions[spec.name] = spec for (const handlerType of handlerNames) { const handler = spec.handlers[handlerType] @@ -276,7 +276,7 @@ export abstract class BaseActionRouter extends BaseRouter }): Promise[T]>>> { const { action, pluginName, log, graph } = params - log.silly(`Getting '${String(handlerType)}' handler for ${action.longDescription()}`) + log.silly(() => `Getting '${String(handlerType)}' handler for ${action.longDescription()}`) if (action.kind !== this.kind) { throw new InternalError({ @@ -320,7 +320,7 @@ export abstract class BaseActionRouter extends BaseRouter ...params, } - log.silly(`Calling ${String(handlerType)} handler for action ${action.longDescription()}`) + log.silly(() => `Calling ${String(handlerType)} handler for action ${action.longDescription()}`) const result: GetActionTypeResults[T]> = await handler(handlerParams) diff --git a/core/src/router/module.ts b/core/src/router/module.ts index b88dc96ca8..47d064625f 100644 --- a/core/src/router/module.ts +++ b/core/src/router/module.ts @@ -84,7 +84,7 @@ export class ModuleRouter extends BaseRouter { const { log, moduleConfig: config } = params const moduleType = config.type - this.garden.log.silly(`Calling configure handler for ${moduleType} module '${config.name}'`) + this.garden.log.silly(() => `Calling configure handler for ${moduleType} module '${config.name}'`) const handler = await this.getModuleHandler({ handlerType: "configure", @@ -111,7 +111,7 @@ export class ModuleRouter extends BaseRouter { } result.moduleConfig.build.dependencies = Object.values(buildDeps) - this.garden.log.silly(`Called configure handler for ${moduleType} module '${config.name}'`) + this.garden.log.silly(() => `Called configure handler for ${moduleType} module '${config.name}'`) return result } @@ -240,7 +240,7 @@ export class ModuleRouter extends BaseRouter { if (handlers.length === 0 && spec.base && !pluginName) { // No handler found but module type has a base. Check if the base type has the handler we're looking for. - this.garden.log.silly(`No ${handlerType} handler found for ${moduleType}. Trying ${spec.base} base.`) + this.garden.log.silly(() => `No ${handlerType} handler found for ${moduleType}. Trying ${spec.base} base.`) return this.getModuleHandler({ handlerType, diff --git a/core/src/router/provider.ts b/core/src/router/provider.ts index c68e68e711..88d9ba6c84 100644 --- a/core/src/router/provider.ts +++ b/core/src/router/provider.ts @@ -82,7 +82,7 @@ export class ProviderRouter extends BaseRouter { async configureProvider(params: ConfigureProviderParams & { pluginName: string }): Promise { const pluginName = params.pluginName - this.garden.log.silly(`Calling 'configureProvider' handler on '${pluginName}'`) + this.garden.log.silly(() => `Calling 'configureProvider' handler on '${pluginName}'`) const handler = await this.getPluginHandler({ handlerType: "configureProvider", @@ -97,7 +97,7 @@ export class ProviderRouter extends BaseRouter { const result = await (handler)(handlerParams) - this.garden.log.silly(`Called 'configureProvider' handler on '${pluginName}'`) + this.garden.log.silly(() => `Called 'configureProvider' handler on '${pluginName}'`) return result } @@ -216,7 +216,7 @@ export class ProviderRouter extends BaseRouter { pluginName: string defaultHandler?: ProviderHandlers[T] }): Promise { - this.garden.log.silly(`Calling ${handlerType} handler on plugin '${pluginName}'`) + this.garden.log.silly(() => `Calling ${handlerType} handler on plugin '${pluginName}'`) const handler = await this.getPluginHandler({ handlerType, @@ -231,7 +231,7 @@ export class ProviderRouter extends BaseRouter { const result = await (handler)(handlerParams) - this.garden.log.silly(`Called ${handlerType} handler on plugin '${pluginName}'`) + this.garden.log.silly(() => `Called ${handlerType} handler on plugin '${pluginName}'`) return result } @@ -296,10 +296,10 @@ export class ProviderRouter extends BaseRouter { // Since we only allow retrieving by plugin name, the length is always either 0 or 1 if (handlers.length) { - this.garden.log.silly(`Found '${handlerType}' handler on '${pluginName}'`) + this.garden.log.silly(() => `Found '${handlerType}' handler on '${pluginName}'`) return handlers[handlers.length - 1] } else if (defaultHandler) { - this.garden.log.silly(`Returned default '${handlerType}' handler for '${pluginName}'`) + this.garden.log.silly(() => `Returned default '${handlerType}' handler for '${pluginName}'`) return Object.assign( // TODO: figure out why we need the cast here defaultHandler, diff --git a/core/src/router/router.ts b/core/src/router/router.ts index 08a1a4cdf1..94355e1b56 100644 --- a/core/src/router/router.ts +++ b/core/src/router/router.ts @@ -67,7 +67,7 @@ export class ActionRouter extends BaseRouter { this.run = runRouter(baseParams) this.test = testRouter(baseParams) - garden.log.silly(`Creating ActionRouter with ${configuredPlugins.length} configured providers`) + garden.log.silly(() => `Creating ActionRouter with ${configuredPlugins.length} configured providers`) } //=========================================================================== diff --git a/core/src/server/server.ts b/core/src/server/server.ts index 5fd86ddd17..290700b4a6 100644 --- a/core/src/server/server.ts +++ b/core/src/server/server.ts @@ -674,7 +674,7 @@ export class GardenServer extends EventEmitter { }) { let request: any - this.log.silly("Got request: " + msg) + this.log.silly(() => "Got request: " + msg) try { request = JSON.parse(msg.toString()) diff --git a/core/src/tasks/resolve-action.ts b/core/src/tasks/resolve-action.ts index dbdb009e09..29f3a1db8d 100644 --- a/core/src/tasks/resolve-action.ts +++ b/core/src/tasks/resolve-action.ts @@ -283,7 +283,7 @@ export class ResolveActionTask extends BaseActionTask `Validating ${description} spec against '${base.name}' schema`) spec = validateWithPath({ config: spec, diff --git a/core/src/tasks/resolve-provider.ts b/core/src/tasks/resolve-provider.ts index 4f95940736..ad3c85117f 100644 --- a/core/src/tasks/resolve-provider.ts +++ b/core/src/tasks/resolve-provider.ts @@ -170,7 +170,7 @@ export class ResolveProviderTask extends BaseTask { const context = new ProviderConfigContext(this.garden, resolvedProviders, this.garden.variables) - this.log.silly(`Resolving template strings for provider ${this.config.name}`) + this.log.silly(() => `Resolving template strings for provider ${this.config.name}`) const projectConfig = this.garden.getProjectConfig() const yamlDoc = projectConfig.internal.yamlDoc @@ -192,7 +192,7 @@ export class ResolveProviderTask extends BaseTask { const providerName = resolvedConfig.name - this.log.silly(`Validating ${providerName} config`) + this.log.silly(() => `Validating ${providerName} config`) const validateConfig = (config: GenericProviderConfig) => { return validateWithPath({ @@ -211,7 +211,7 @@ export class ResolveProviderTask extends BaseTask { let moduleConfigs: ModuleConfig[] = [] - this.log.silly(`Calling configureProvider on ${providerName}`) + this.log.silly(() => `Calling configureProvider on ${providerName}`) const actions = await this.garden.getActionRouter() @@ -244,7 +244,7 @@ export class ResolveProviderTask extends BaseTask { dependencies: resolvedProviders, }) - this.log.silly(`Validating ${providerName} config returned from configureProvider handler`) + this.log.silly(() => `Validating ${providerName} config returned from configureProvider handler`) resolvedConfig = validateConfig(configureOutput.config) resolvedConfig.path = this.garden.projectRoot @@ -261,7 +261,7 @@ export class ResolveProviderTask extends BaseTask { continue } - this.log.silly(`Validating '${providerName}' config against '${base.name}' schema`) + this.log.silly(() => `Validating '${providerName}' config against '${base.name}' schema`) resolvedConfig = validateWithPath({ config: omit(resolvedConfig, "path"), @@ -274,7 +274,7 @@ export class ResolveProviderTask extends BaseTask { }) } - this.log.silly(`Ensuring ${providerName} provider is ready`) + this.log.silly(() => `Ensuring ${providerName} provider is ready`) const tmpProvider = providerFromConfig({ plugin: this.plugin, @@ -308,7 +308,7 @@ export class ResolveProviderTask extends BaseTask { private async getCachedStatus(config: GenericProviderConfig): Promise { const cachePath = this.getCachePath() - this.log.silly(`Checking provider status cache for ${this.plugin.name} at ${cachePath}`) + this.log.silly(() => `Checking provider status cache for ${this.plugin.name} at ${cachePath}`) let cachedStatus: CachedStatus | null = null @@ -318,7 +318,7 @@ export class ResolveProviderTask extends BaseTask { cachedStatus = validateSchema(cachedData, cachedStatusSchema) } catch (err) { // Can't find or read a cached status - this.log.silly(`Unable to find or read provider status from ${cachePath}: ${err}`) + this.log.silly(() => `Unable to find or read provider status from ${cachePath}: ${err}`) } } @@ -329,7 +329,7 @@ export class ResolveProviderTask extends BaseTask { const configHash = this.hashConfig(config) if (cachedStatus.configHash !== configHash) { - this.log.silly(`Cached provider status at ${cachePath} does not match the current config`) + this.log.silly(() => `Cached provider status at ${cachePath} does not match the current config`) return null } @@ -337,7 +337,7 @@ export class ResolveProviderTask extends BaseTask { const cacheAge = (new Date().getTime() - cachedStatus?.resolvedAt.getTime()) / 1000 if (cacheAge > ttl) { - this.log.silly(`Cached provider status at ${cachePath} is out of date`) + this.log.silly(() => `Cached provider status at ${cachePath} is out of date`) return null } @@ -346,7 +346,7 @@ export class ResolveProviderTask extends BaseTask { private async setCachedStatus(config: GenericProviderConfig, status: EnvironmentStatus) { const cachePath = this.getCachePath() - this.log.silly(`Caching provider status for ${this.plugin.name} at ${cachePath}`) + this.log.silly(() => `Caching provider status for ${this.plugin.name} at ${cachePath}`) const cachedStatus: CachedStatus = { ...status, @@ -378,7 +378,7 @@ export class ResolveProviderTask extends BaseTask { ctx.log[level]({ msg, origin }) }) - this.log.silly(`Getting status for ${pluginName}`) + this.log.silly(() => `Getting status for ${pluginName}`) // Check for cached provider status const cachedStatus = await this.getCachedStatus(tmpProvider.config) @@ -396,7 +396,7 @@ export class ResolveProviderTask extends BaseTask { let status = await handler!({ ctx, log: this.log }) - this.log.silly(`${pluginName} status: ${status.ready ? "ready" : "not ready"}`) + this.log.silly(() => `${pluginName} status: ${status.ready ? "ready" : "not ready"}`) if (this.forceInit || !status.ready) { // Deliberately setting the text on the parent log here diff --git a/core/src/template-string/template-string.ts b/core/src/template-string/template-string.ts index 58ec61acf1..3ee157fc89 100644 --- a/core/src/template-string/template-string.ts +++ b/core/src/template-string/template-string.ts @@ -780,7 +780,7 @@ export function throwOnMissingSecretKeys(configs: ObjectWithName[], secrets: Str ${footer} ` if (log) { - log.silly(errMsg) + log.silly(() => errMsg) } // throw new ConfigurationError(errMsg, { // loadedSecretKeys: loadedKeys, diff --git a/core/src/util/ext-tools.ts b/core/src/util/ext-tools.ts index ef5830a898..4442ea8581 100644 --- a/core/src/util/ext-tools.ts +++ b/core/src/util/ext-tools.ts @@ -75,7 +75,7 @@ export class CliWrapper { cwd = dirname(path) } - log.silly(`Execing '${path} ${args.join(" ")}' in ${cwd}`) + log.silly(() => `Execing '${path} ${args!.join(" ")}' in ${cwd}`) return exec(path, args, { cwd, diff --git a/core/src/util/sync.ts b/core/src/util/sync.ts index a923b349e1..41ceb474ed 100644 --- a/core/src/util/sync.ts +++ b/core/src/util/sync.ts @@ -69,8 +69,8 @@ export async function syncWithOptions({ // Avoid rendering the full file list except when at the silly log level if (log.root.level === LogLevel.silly) { - log.silly(`File list: ${JSON.stringify(files)}`) - log.silly(`Rsync args: ${[...opts, sourcePath, destinationPath].join(" ")}`) + log.silly(() => `File list: ${JSON.stringify(files)}`) + log.silly(() => `Rsync args: ${[...opts, sourcePath, destinationPath].join(" ")}`) } await exec("rsync", [...opts, sourcePath, destinationPath], { input }) diff --git a/core/src/util/testing.ts b/core/src/util/testing.ts index 20b6de3392..c581de7a6a 100644 --- a/core/src/util/testing.ts +++ b/core/src/util/testing.ts @@ -15,7 +15,7 @@ import { Garden, resolveGardenParams } from "../garden.js" import type { DeepPrimitiveMap, StringMap } from "../config/common.js" import type { ModuleConfig } from "../config/module.js" import type { WorkflowConfig } from "../config/workflow.js" -import type { Log, LogEntry } from "../logger/log-entry.js" +import { resolveMsg, type Log, type LogEntry } from "../logger/log-entry.js" import type { GardenModule } from "../types/module.js" import { findByName, getNames } from "./util.js" import { GardenError, InternalError } from "../exceptions.js" @@ -66,7 +66,7 @@ export function getLogMessages(log: Log, filter?: (log: LogEntry) => boolean) { return log .getLogEntries() .filter((entry) => (filter ? filter(entry) : true)) - .map((entry) => stripAnsi(entry.msg || "")) + .map((entry) => stripAnsi(resolveMsg(entry) || "")) } /** @@ -77,7 +77,7 @@ export function getRootLogMessages(log: Log, filter?: (log: LogEntry) => boolean return log .getAllLogEntries() .filter((entry) => (filter ? filter(entry) : true)) - .map((entry) => stripAnsi(entry.msg || "")) + .map((entry) => stripAnsi(resolveMsg(entry) || "")) } type PartialActionConfig = Partial & { kind: ActionKind; type: string; name: string } diff --git a/core/src/vcs/git-repo.ts b/core/src/vcs/git-repo.ts index 7d8645e64c..44c911d757 100644 --- a/core/src/vcs/git-repo.ts +++ b/core/src/vcs/git-repo.ts @@ -70,8 +70,8 @@ export class GitRepoHandler extends GitHandler { log.debug( `Found ${moduleFiles.length} files in module path, filtering by ${include.length} include and ${exclude.length} exclude globs` ) - log.silly(`Include globs: ${include.join(", ")}`) - log.silly(exclude.length > 0 ? `Exclude globs: ${exclude.join(", ")}` : "No exclude globs") + log.silly(() => `Include globs: ${include.join(", ")}`) + log.silly(() => (exclude.length > 0 ? `Exclude globs: ${exclude.join(", ")}` : "No exclude globs")) const filtered = moduleFiles.filter(({ path: p }) => { if (filter && !filter(p)) { @@ -82,7 +82,7 @@ export class GitRepoHandler extends GitHandler { // Previously we prepended the module path to the globs // but that caused issues with the glob matching on windows due to backslashes const relativePath = p.replace(`${path}${sep}`, "") - log.silly(`Checking if ${relativePath} matches include/exclude globs`) + log.silly(() => `Checking if ${relativePath} matches include/exclude globs`) return matchPath(relativePath, include, exclude) }) @@ -102,7 +102,7 @@ export class GitRepoHandler extends GitHandler { let existing = this.cache.get(log, key) as FileTree if (existing) { - params.log.silly(`Found cached repository match at ${path}`) + params.log.silly(() => `Found cached repository match at ${path}`) return existing } @@ -110,11 +110,11 @@ export class GitRepoHandler extends GitHandler { existing = this.cache.get(log, key) if (existing) { - log.silly(`Found cached repository match at ${path}`) + log.silly(() => `Found cached repository match at ${path}`) return existing } - log.silly(`Scanning repository at ${path}`) + log.silly(() => `Scanning repository at ${path}`) const files = await super.getFiles({ ...params, scanRoot: undefined }) const fileTree = FileTree.fromFiles(files) diff --git a/core/src/vcs/git.ts b/core/src/vcs/git.ts index a14bc6219a..150eaa49a5 100644 --- a/core/src/vcs/git.ts +++ b/core/src/vcs/git.ts @@ -428,7 +428,7 @@ export class GitHandler extends VcsHandler { args.push(...(include || [])) // Start git process - gitLog.silly(`Calling git with args '${args.join(" ")}' in ${path}`) + gitLog.silly(() => `Calling git with args '${args.join(" ")}' in ${path}`) const processEnded = defer() const proc = execa("git", args, { cwd: path, buffer: false }) diff --git a/core/src/vcs/vcs.ts b/core/src/vcs/vcs.ts index f8d3161011..764b58cc9b 100644 --- a/core/src/vcs/vcs.ts +++ b/core/src/vcs/vcs.ts @@ -192,7 +192,7 @@ export abstract class VcsHandler { if (!force) { const cached = this.cache.get(log, cacheKey) if (cached) { - log.silly(`Got cached tree version for ${description} (key ${cacheKey})`) + log.silly(() => `Got cached tree version for ${description} (key ${cacheKey})`) return cached } } @@ -207,7 +207,7 @@ export abstract class VcsHandler { if (!force) { const cached = this.cache.get(log, cacheKey) if (cached) { - log.silly(`Got cached tree version for ${description} (key ${cacheKey})`) + log.silly(() => `Got cached tree version for ${description} (key ${cacheKey})`) result = cached return } diff --git a/core/src/watch.ts b/core/src/watch.ts index 9eb7dd281b..14c8487bc5 100644 --- a/core/src/watch.ts +++ b/core/src/watch.ts @@ -72,7 +72,7 @@ export class Watcher extends EventEmitter2.EventEmitter2 { this.ready = true }) .on("all", (name, path, payload) => { - this.log.silly(`FSWatcher event: ${name} ${path} ${stringify(payload)}`) + this.log.silly(() => `FSWatcher event: ${name} ${path} ${stringify(payload)}`) this.routeEvent(name, path, payload) }) } diff --git a/core/test/integ/src/plugins/kubernetes/helm/common.ts b/core/test/integ/src/plugins/kubernetes/helm/common.ts index 5c59471900..234b56d03a 100644 --- a/core/test/integ/src/plugins/kubernetes/helm/common.ts +++ b/core/test/integ/src/plugins/kubernetes/helm/common.ts @@ -20,7 +20,7 @@ import { prepareTemplates, renderTemplates, } from "../../../../../../src/plugins/kubernetes/helm/common.js" -import type { Log } from "../../../../../../src/logger/log-entry.js" +import { resolveMsg, type Log } from "../../../../../../src/logger/log-entry.js" import { BuildTask } from "../../../../../../src/tasks/build.js" import { dedent, deline } from "../../../../../../src/util/string.js" import type { ConfigGraph } from "../../../../../../src/graph/config-graph.js" @@ -682,10 +682,12 @@ ${expectedIngressOutput} await prepareTemplates({ ctx, log, action }) - const helmDependencyUpdateLogLine = log.entries.find( - ({ msg }) => + const helmDependencyUpdateLogLine = log.entries.find((entry) => { + const msg = resolveMsg(entry) + return ( msg?.includes("helm") && msg?.includes("dependency update") && msg.includes("chart-with-dependency-module") - ) + ) + }) expect(helmDependencyUpdateLogLine).to.exist }) @@ -701,10 +703,12 @@ ${expectedIngressOutput} await prepareTemplates({ ctx, log, action }) - const helmDependencyUpdateLogLine = log.entries.find( - ({ msg }) => + const helmDependencyUpdateLogLine = log.entries.find((entry) => { + const msg = resolveMsg(entry) + return ( msg?.includes("helm") && msg?.includes("dependency update") && msg.includes("chart-with-dependency-action") - ) + ) + }) expect(helmDependencyUpdateLogLine).to.exist }) diff --git a/core/test/integ/src/plugins/kubernetes/kubernetes-type/common.ts b/core/test/integ/src/plugins/kubernetes/kubernetes-type/common.ts index e40e52dd13..befb7a7def 100644 --- a/core/test/integ/src/plugins/kubernetes/kubernetes-type/common.ts +++ b/core/test/integ/src/plugins/kubernetes/kubernetes-type/common.ts @@ -20,6 +20,7 @@ import { KubeApi } from "../../../../../../src/plugins/kubernetes/api.js" import type { KubernetesProvider } from "../../../../../../src/plugins/kubernetes/config.js" import dedent from "dedent" import { dirname, join } from "path" +import { resolveMsg } from "../../../../../../src/logger/log-entry.js" let kubernetesTestGarden: TestGarden @@ -645,8 +646,8 @@ describe("getManifests", () => { await getManifests({ ctx, api, action: resolvedAction, log: garden.log, defaultNamespace }) - const logMsgs = garden.log.root.getLogEntries().map((e) => e.msg) - const unMatched = logMsgs.find((msg) => msg?.includes("A patch is defined")) + const logEntries = garden.log.root.getLogEntries() + const unMatched = resolveMsg(logEntries.find((entry) => resolveMsg(entry)?.includes("A patch is defined"))!) expect(unMatched).to.exist expect(unMatched).to.eql( diff --git a/core/test/unit/src/analytics/analytics.ts b/core/test/unit/src/analytics/analytics.ts index 644e098693..a9d717e905 100644 --- a/core/test/unit/src/analytics/analytics.ts +++ b/core/test/unit/src/analytics/analytics.ts @@ -27,6 +27,7 @@ import type { AnalyticsGlobalConfig } from "../../../../src/config-store/global. import { QuietWriter } from "../../../../src/logger/writers/quiet-writer.js" import timekeeper from "timekeeper" import { ConfigurationError, DeploymentError, RuntimeError } from "../../../../src/exceptions.js" +import { resolveMsg } from "../../../../src/logger/log-entry.js" const host = "https://api.segment.io" // The codenamize version + the sha512 hash of "test-project-a" @@ -134,7 +135,7 @@ describe("AnalyticsHandler", () => { it("should print an info message if first Garden run", async () => { await garden.globalConfigStore.set("analytics", {}) analytics = await AnalyticsHandler.factory({ garden, log: garden.log, ciInfo }) - const msgs = garden.log.root.getLogEntries().map((l) => l.msg) + const msgs = garden.log.root.getLogEntries().map((l) => resolveMsg(l)) const infoMsg = msgs.find((msg) => msg?.includes("Thanks for installing Garden!")) expect(infoMsg).to.exist @@ -143,7 +144,7 @@ describe("AnalyticsHandler", () => { // The existens of base config suggests it's not the first run await garden.globalConfigStore.set("analytics", basicConfig) analytics = await AnalyticsHandler.factory({ garden, log: garden.log, ciInfo }) - const msgs = garden.log.root.getLogEntries().map((l) => l.msg) + const msgs = garden.log.root.getLogEntries().map((l) => resolveMsg(l)) const infoMsg = msgs.find((msg) => msg?.includes("Thanks for installing Garden!")) expect(infoMsg).not.to.exist diff --git a/core/test/unit/src/commands/helpers.ts b/core/test/unit/src/commands/helpers.ts index e8b6041650..8eafca35c5 100644 --- a/core/test/unit/src/commands/helpers.ts +++ b/core/test/unit/src/commands/helpers.ts @@ -11,6 +11,7 @@ import { validateActionSearchResults } from "../../../../src/commands/helpers.js import { getRootLogger } from "../../../../src/logger/logger.js" import { initTestLogger } from "../../../helpers.js" import { expectError } from "../../../helpers.js" +import { resolveMsg } from "../../../../src/logger/log-entry.js" describe("command helpers", () => { initTestLogger() @@ -97,7 +98,7 @@ describe("command helpers", () => { names: undefined, }) - expect(log.entries[0].msg?.includes("No Build actions were found. Aborting.")).to.eql(true) + expect(resolveMsg(log.entries[0])?.includes("No Build actions were found. Aborting.")).to.eql(true) log = logger.createLog() validateActionSearchResults({ @@ -108,7 +109,7 @@ describe("command helpers", () => { names: [], }) - expect(log.entries[0].msg?.includes("No Build actions were found. Aborting.")).to.eql(true) + expect(resolveMsg(log.entries[0])?.includes("No Build actions were found. Aborting.")).to.eql(true) }) }) }) diff --git a/core/test/unit/src/commands/logs.ts b/core/test/unit/src/commands/logs.ts index d6f80f7339..3450f9843c 100644 --- a/core/test/unit/src/commands/logs.ts +++ b/core/test/unit/src/commands/logs.ts @@ -22,7 +22,7 @@ import { } from "../../../helpers.js" import { DEFAULT_DEPLOY_TIMEOUT_SEC, GardenApiVersion } from "../../../../src/constants.js" import { formatForTerminal } from "../../../../src/logger/renderers.js" -import type { LogEntry } from "../../../../src/logger/log-entry.js" +import { resolveMsg, type LogEntry } from "../../../../src/logger/log-entry.js" import { LogLevel } from "../../../../src/logger/logger.js" import type { DeployLogEntry } from "../../../../src/types/service.js" import type { GetDeployLogs } from "../../../../src/plugin/handlers/Deploy/get-logs.js" @@ -87,7 +87,7 @@ function getLogOutput(garden: TestGarden, msg: string, extraFilter: (e: LogEntry const entries = garden.log .getLogEntries() .filter(extraFilter) - .filter((e) => e.msg?.includes(msg))! + .filter((e) => resolveMsg(e)?.includes(msg))! return entries.map((e) => formatForTerminal(e, garden.log.root).trim()) } diff --git a/core/test/unit/src/commands/workflow.ts b/core/test/unit/src/commands/workflow.ts index 8788817e88..aa1bdd906c 100644 --- a/core/test/unit/src/commands/workflow.ts +++ b/core/test/unit/src/commands/workflow.ts @@ -28,7 +28,7 @@ import { join } from "path" import fsExtra from "fs-extra" const { remove, readFile, pathExists } = fsExtra import { dedent } from "../../../../src/util/string.js" -import type { LogEntry } from "../../../../src/logger/log-entry.js" +import { resolveMsg, type LogEntry } from "../../../../src/logger/log-entry.js" import type { WorkflowStepSpec } from "../../../../src/config/workflow.js" import { defaultWorkflowResources } from "../../../../src/config/workflow.js" import { TestGardenCli } from "../../../helpers/cli.js" @@ -171,7 +171,7 @@ describe("RunWorkflowCommand", () => { }) function filterLogEntries(entries: LogEntry[], msgRegex: RegExp): LogEntry[] { - return entries.filter((e) => msgRegex.test(e.msg || "")) + return entries.filter((e) => msgRegex.test(resolveMsg(e) || "")) } it("should collect log outputs from a command step", async () => { diff --git a/core/test/unit/src/garden.ts b/core/test/unit/src/garden.ts index 9036ddbc3f..a8fa2d4817 100644 --- a/core/test/unit/src/garden.ts +++ b/core/test/unit/src/garden.ts @@ -74,6 +74,7 @@ import { GlobalConfigStore } from "../../../src/config-store/global.js" import { getRootLogger } from "../../../src/logger/logger.js" import { uuidv4 } from "../../../src/util/random.js" import { fileURLToPath } from "node:url" +import { resolveMsg } from "../../../src/logger/log-entry.js" const moduleDirName = dirname(fileURLToPath(import.meta.url)) @@ -730,11 +731,13 @@ describe("Garden", () => { cloudApi, }) - const expectedLog = log.root.getLogEntries().filter((l) => l.msg?.includes(`Logged in to ${fakeCloudDomain}`)) + const expectedLog = log.root + .getLogEntries() + .filter((l) => resolveMsg(l)?.includes(`Logged in to ${fakeCloudDomain}`)) expect(expectedLog.length).to.eql(1) expect(expectedLog[0].level).to.eql(1) - const cleanMsg = stripAnsi(expectedLog[0].msg || "").replace("\n", " ") + const cleanMsg = stripAnsi(resolveMsg(expectedLog[0]) || "").replace("\n", " ") const expected = `Logged in to ${fakeCloudDomain}, but could not find remote project '${projectName}'. Command results for this command run will not be available in Garden Enterprise.` expect(cleanMsg).to.eql(expected) expect(garden.cloudDomain).to.eql(fakeCloudDomain) @@ -762,11 +765,13 @@ describe("Garden", () => { } } - const expectedLog = log.root.getLogEntries().filter((l) => l.msg?.includes(`Fetching project with ID=`)) + const expectedLog = log.root + .getLogEntries() + .filter((l) => resolveMsg(l)?.includes(`Fetching project with ID=`)) expect(expectedLog.length).to.eql(1) expect(expectedLog[0].level).to.eql(0) - const cleanMsg = stripAnsi(expectedLog[0].msg || "").replace("\n", " ") + const cleanMsg = stripAnsi(resolveMsg(expectedLog[0]) || "").replace("\n", " ") expect(cleanMsg).to.eql( `Fetching project with ID=${projectId} failed with error: HTTPError: Response code 500 (Internal Server Error)` ) @@ -795,11 +800,11 @@ describe("Garden", () => { } } - const expectedLog = log.root.getLogEntries().filter((l) => l.msg?.includes(`Project with ID=`)) + const expectedLog = log.root.getLogEntries().filter((l) => resolveMsg(l)?.includes(`Project with ID=`)) expect(expectedLog.length).to.eql(1) expect(expectedLog[0].level).to.eql(0) - const cleanMsg = stripAnsi(expectedLog[0].msg || "") + const cleanMsg = stripAnsi(resolveMsg(expectedLog[0]) || "") expect(cleanMsg).to.eql(dedent` Project with ID=${projectId} was not found in Garden Enterprise @@ -908,11 +913,11 @@ describe("Garden", () => { } } - const expectedLog = log.root.getLogEntries().filter((l) => l.msg?.includes(`failed with error`)) + const expectedLog = log.root.getLogEntries().filter((l) => resolveMsg(l)?.includes(`failed with error`)) expect(expectedLog.length).to.eql(1) expect(expectedLog[0].level).to.eql(0) - const cleanMsg = stripAnsi(expectedLog[0].msg || "").replace("\n", " ") + const cleanMsg = stripAnsi(resolveMsg(expectedLog[0]) || "").replace("\n", " ") expect(cleanMsg).to.eql( `Fetching or creating project ${projectName} from ${DEFAULT_GARDEN_CLOUD_DOMAIN} failed with error: HTTPError: Response code 500 (Internal Server Error)` ) diff --git a/plugins/pulumi/src/helpers.ts b/plugins/pulumi/src/helpers.ts index 2783bffd5f..0178f076a7 100644 --- a/plugins/pulumi/src/helpers.ts +++ b/plugins/pulumi/src/helpers.ts @@ -169,7 +169,7 @@ export async function getDeployment({ log, ctx, provider, action }: PulumiParams env: ensureEnv({ log, ctx, provider, action }), cwd: getActionStackRoot(action), }) - log.silly(`stack export for ${action.name}: ${JSON.stringify(res, null, 2)}`) + log.silly(() => `stack export for ${action.name}: ${JSON.stringify(res, null, 2)}`) return res }