From 7d5557fc39cdd16ef24815707660f1ef6351a961 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ey=C3=BE=C3=B3r=20Magn=C3=BAsson?= Date: Tue, 21 Nov 2023 10:35:04 -0600 Subject: [PATCH] improvement(logger): better provider resolution lifecycle logs (#5464) This commits add more logging around the provider resolution phase of the Garden initialization. Also ensures that the log context passed to the plugin handlers has the provider name set. --- core/src/cli/cli.ts | 7 ++- core/src/commands/deploy.ts | 5 ++- core/src/garden.ts | 27 +++++++---- .../plugins/kubernetes/ephemeral/config.ts | 12 ++--- core/src/plugins/kubernetes/init.ts | 4 ++ core/src/plugins/kubernetes/local/config.ts | 11 +++-- core/src/tasks/base.ts | 2 +- core/src/tasks/resolve-provider.ts | 45 +++++++++++-------- core/test/unit/src/cli/cli.ts | 10 +++-- plugins/terraform/src/index.ts | 4 +- plugins/terraform/src/init.ts | 7 ++- 11 files changed, 76 insertions(+), 58 deletions(-) diff --git a/core/src/cli/cli.ts b/core/src/cli/cli.ts index 36731b851d..79573fa135 100644 --- a/core/src/cli/cli.ts +++ b/core/src/cli/cli.ts @@ -224,6 +224,7 @@ ${renderCommands(commands)} } = parsedOpts const parsedCliVars = parseCliVarFlags(cliVars) + const gardenLog = log.createLog({ name: "garden" }) // Some commands may set their own logger type so we update the logger config here, // once we've resolved the command. @@ -241,6 +242,7 @@ ${renderCommands(commands)} // Init Cloud API (if applicable) let cloudApi: CloudApi | undefined + gardenLog.info("Initializing...") if (!command.noProject) { const config = await this.getProjectConfig(log, workingDir) const cloudDomain = getGardenCloudDomain(config?.domain) @@ -302,7 +304,6 @@ ${renderCommands(commands)} contextOpts.persistent = persistent // TODO: Link to Cloud namespace page here. - const nsLog = log.createLog({ name: "garden" }) try { if (command.noProject) { @@ -321,9 +322,7 @@ ${renderCommands(commands)} }) } - nsLog.info( - `Running in Garden environment ${styles.highlight(`${garden.environmentName}.${garden.namespace}`)}` - ) + gardenLog.info(`Running in environment ${styles.highlight(`${garden.environmentName}.${garden.namespace}`)}`) if (!cloudApi && garden.projectId) { log.info("") diff --git a/core/src/commands/deploy.ts b/core/src/commands/deploy.ts index b40d083a29..e978a9f958 100644 --- a/core/src/commands/deploy.ts +++ b/core/src/commands/deploy.ts @@ -174,6 +174,7 @@ export class DeployCommand extends Command { const { garden, log, args, opts } = params this.garden = garden + const commandLog = log.createLog({ name: "garden" }) if (opts.watch) { await watchRemovedWarning(garden, log) @@ -206,7 +207,7 @@ export class DeployCommand extends Command { const bold = disabled.map((d) => styles.accent(d)) const msg = disabled.length === 1 ? `Deploy action ${bold} is disabled` : `Deploy actions ${naturalList(bold)} are disabled` - log.info(styles.primary(msg)) + commandLog.info(msg) } const skipRuntimeDependencies = opts["skip-dependencies"] @@ -226,7 +227,7 @@ export class DeployCommand extends Command { deployActions = deployActions.filter((s) => !s.isDisabled() && !skipped.includes(s.name)) if (deployActions.length === 0) { - log.error({ msg: "Nothing to deploy. Aborting." }) + commandLog.error({ msg: "Nothing to deploy. Aborting." }) return { result: { aborted: true, success: true, ...emptyActionResults } } } diff --git a/core/src/garden.ts b/core/src/garden.ts index 618e9e4593..e701423b84 100644 --- a/core/src/garden.ts +++ b/core/src/garden.ts @@ -748,10 +748,12 @@ export class Garden { return } - log.silly(() => `Resolving providers`) - const providerLog = log.createLog({ name: "providers", showDuration: true }) - providerLog.info("Getting status...") + if (this.forceRefresh) { + providerLog.info("Resolving providers (will force refresh statuses)...") + } else { + providerLog.info("Resolving providers...") + } const plugins = keyBy(await this.getAllPlugins(), "name") @@ -830,7 +832,8 @@ export class Garden { providers = providerResults.map((result) => result!.result) - const gotCachedResult = !!providers.find((p) => p.status.cached) + const allCached = providers.every((p) => p.status.cached) + const someCached = providers.some((p) => p.status.cached) await Promise.all( providers.flatMap((provider) => @@ -846,14 +849,18 @@ export class Garden { this.resolvedProviders[provider.name] = provider } - if (gotCachedResult) { - providerLog.success({ msg: "Cached", showDuration: false }) - providerLog.info("Run with --force-refresh to force a refresh of provider statuses.") - } else { - providerLog.success("Done") + providerLog.success("Finished initializing providers") + if (someCached || allCached) { + const msg = allCached ? "All" : "Some" + providerLog.info( + `${msg} provider statuses were cached. Run with --force-refresh to force a refresh of provider statuses.` + ) } providerLog.silly(() => `Resolved providers: ${providers.map((p) => p.name).join(", ")}`) + + // Print a new line after resolving providers + this.log.info("") }) return keyBy(providers, "name") @@ -1156,6 +1163,8 @@ export class Garden { this.events.emit("configGraph", { graph }) graphLog.success("Done") + // Print a new line after resolving graph + this.log.info("") return graph.toConfigGraph() } diff --git a/core/src/plugins/kubernetes/ephemeral/config.ts b/core/src/plugins/kubernetes/ephemeral/config.ts index 26be65a943..afd160fbd3 100644 --- a/core/src/plugins/kubernetes/ephemeral/config.ts +++ b/core/src/plugins/kubernetes/ephemeral/config.ts @@ -47,8 +47,6 @@ export const configSchema = () => export async function configureProvider(params: ConfigureProviderParams) { const { base, log, ctx, config: baseConfig } = params - const providerLog = log.createLog({ name: ctx.provider.name }).info("Configuring provider...") - if (!ctx.cloudApi) { throw new ConfigurationError({ message: `You are not logged in. You must be logged into Garden Cloud in order to use ${EPHEMERAL_KUBERNETES_PROVIDER_NAME} provider.`, @@ -64,31 +62,29 @@ export async function configureProvider(params: ConfigureProviderParams log.warn(w)) } + return result } diff --git a/core/src/plugins/kubernetes/local/config.ts b/core/src/plugins/kubernetes/local/config.ts index 9b15b160cb..3789d87cac 100644 --- a/core/src/plugins/kubernetes/local/config.ts +++ b/core/src/plugins/kubernetes/local/config.ts @@ -57,12 +57,11 @@ export async function configureProvider(params: ConfigureProviderParams c.name) || [] for (const context of availableContexts) { if (isSupportedContext(context)) { config.context = context - providerLog.debug(`Using detected context: ${config.context}`) + log.info(`Using detected context: ${config.context}`) break } } @@ -86,14 +85,14 @@ export async function configureProvider(params: ConfigureProviderParams 0) { config.context = kubeConfig.contexts[0]!.name - providerLog.debug(`No kubectl context auto-detected, using first available: ${config.context}`) + log.info(`No kubectl context auto-detected, using first available: ${config.context}`) } } // TODO: change this in 0.13 to use the current context if (!config.context) { config.context = supportedContexts[0] - providerLog.debug(`No kubectl context configured, using default: ${config.context}`) + log.info(`No kubectl context configured, using default: ${config.context}`) } if (config.context === "minikube") { diff --git a/core/src/tasks/base.ts b/core/src/tasks/base.ts index ad83f924a4..3ab825be24 100644 --- a/core/src/tasks/base.ts +++ b/core/src/tasks/base.ts @@ -480,7 +480,7 @@ export function logAndEmitGetStatusEvents< if (result.state === "ready" && !willRerun) { log.success({ msg: `Already ${logStrings.ready}`, showDuration: false }) } else if (result.state === "ready" && willRerun) { - log.info(`${styledName} is already ${logStrings.ready}, will force ${logStrings.force}`) + log.warn(`${styledName} is already ${logStrings.ready}, will force ${logStrings.force}`) } else { const stateStr = result.detail?.state || displayState(result.state) log.warn(`Status is '${stateStr}', ${styledName} ${logStrings.notReady}`) diff --git a/core/src/tasks/resolve-provider.ts b/core/src/tasks/resolve-provider.ts index ad3c85117f..a408b23da8 100644 --- a/core/src/tasks/resolve-provider.ts +++ b/core/src/tasks/resolve-provider.ts @@ -31,6 +31,20 @@ import { hashString, isNotNull } from "../util/util.js" import { gardenEnv } from "../constants.js" import { stableStringify } from "../util/string.js" import { OtelTraced } from "../util/open-telemetry/decorators.js" +import { LogLevel } from "../logger/logger.js" +import type { Log } from "../logger/log-entry.js" + +/** + * Returns a provider log context with the provider name set. + * + * Also sets the log level to verbose for some built in providers that aren't really + * resolved per se. A bit hacky but this is just a cosmetic change. + */ +function getProviderLog(providerName: string, log: Log) { + const verboseLogProviders = ["exec", "templated", "container"] + const fixLevel = verboseLogProviders.includes(providerName) ? LogLevel.verbose : undefined + return log.createLog({ name: providerName, fixLevel }) +} interface Params extends CommonTaskParams { plugin: GardenPluginSpec @@ -189,8 +203,9 @@ export class ResolveProviderTask extends BaseTask { const source = { yamlDoc, basePath: yamlDocBasePath } let resolvedConfig = resolveTemplateStrings({ value: this.config, context, source }) - const providerName = resolvedConfig.name + const providerLog = getProviderLog(providerName, this.log) + providerLog.info("Configuring provider...") this.log.silly(() => `Validating ${providerName} config`) @@ -236,7 +251,7 @@ export class ResolveProviderTask extends BaseTask { environmentName: this.garden.environmentName, namespace: this.garden.namespace, pluginName: providerName, - log: this.log, + log: providerLog, config: resolvedConfig, configStore: this.garden.localConfigStore, projectName: this.garden.projectName, @@ -275,6 +290,7 @@ export class ResolveProviderTask extends BaseTask { } this.log.silly(() => `Ensuring ${providerName} provider is ready`) + providerLog.success("Provider configured") const tmpProvider = providerFromConfig({ plugin: this.plugin, @@ -361,6 +377,7 @@ export class ResolveProviderTask extends BaseTask { private async ensurePrepared(tmpProvider: Provider) { const pluginName = tmpProvider.name + const providerLog = getProviderLog(pluginName, this.log) const actions = await this.garden.getActionRouter() const ctx = await this.garden.getPluginContext({ provider: tmpProvider, @@ -378,12 +395,11 @@ export class ResolveProviderTask extends BaseTask { ctx.log[level]({ msg, origin }) }) - this.log.silly(() => `Getting status for ${pluginName}`) - // Check for cached provider status const cachedStatus = await this.getCachedStatus(tmpProvider.config) if (cachedStatus) { + providerLog.success(`Provider status cached`) return cachedStatus } @@ -394,20 +410,11 @@ export class ResolveProviderTask extends BaseTask { defaultHandler: async () => defaultEnvironmentStatus, }) - let status = await handler!({ ctx, log: this.log }) - - this.log.silly(() => `${pluginName} status: ${status.ready ? "ready" : "not ready"}`) + let status = await handler!({ ctx, log: providerLog }) if (this.forceInit || !status.ready) { - // Deliberately setting the text on the parent log here - this.log.info(`Preparing environment...`) - - const envLogEntry = this.log - .createLog({ - name: pluginName, - }) - .info("Configuring...") - + const statusMsg = status.ready ? "Ready, will force re-init" : "Not ready, will init" + providerLog.warn(statusMsg) // TODO: avoid calling the handler manually const prepareHandler = await actions.provider["getPluginHandler"]({ handlerType: "prepareEnvironment", @@ -415,18 +422,18 @@ export class ResolveProviderTask extends BaseTask { defaultHandler: async () => ({ status }), }) - const result = await prepareHandler!({ ctx, log: this.log, force: this.forceInit, status }) + const result = await prepareHandler!({ ctx, log: providerLog, force: this.forceInit, status }) status = result.status - - envLogEntry.success("Ready") } if (!status.ready) { + providerLog.error("Failed initializing provider") throw new PluginError({ message: `Provider ${pluginName} reports status as not ready and could not prepare the configured environment.`, }) } + providerLog.success("Provider ready") if (!status.disableCache) { await this.setCachedStatus(tmpProvider.config, status) diff --git a/core/test/unit/src/cli/cli.ts b/core/test/unit/src/cli/cli.ts index 5143a3b32a..dd07c582eb 100644 --- a/core/test/unit/src/cli/cli.ts +++ b/core/test/unit/src/cli/cli.ts @@ -1063,9 +1063,10 @@ describe("cli", () => { const { code } = await cli.run({ args: ["test-command"], exitOnError: false }) - expect(code).to.equal(1) const output = stripAnsi(hook.captured()) + expect(code).to.equal(1) expect(output).to.eql(dedent` + ℹ garden → Initializing... Error message See .garden/error.log for detailed error message\n`) @@ -1092,8 +1093,9 @@ describe("cli", () => { expect(code).to.equal(1) const outputLines = stripAnsi(hook.captured()).split("\n") - const firstSevenLines = outputLines.slice(0, 7).join("\n") - expect(firstSevenLines).to.eql(dedent` + const firstEightLines = outputLines.slice(0, 8).join("\n") + expect(firstEightLines).to.eql(dedent` + ℹ garden → Initializing... Encountered an unexpected Garden error. This is likely a bug 🍂 You can help by reporting this on GitHub: https://github.com/garden-io/garden/issues/new?labels=bug,crash&template=CRASH.md&title=Crash%3A%20Cannot%20read%20property%20foo%20of%20undefined. @@ -1103,7 +1105,7 @@ describe("cli", () => { TypeError: Cannot read property foo of undefined. `) - const firstStackTraceLine = outputLines[7] + const firstStackTraceLine = outputLines[8] expect(firstStackTraceLine).to.contain("at TestCommand.action (") const lastLine = outputLines[outputLines.length - 2] // the last line is empty due to trailing newline diff --git a/plugins/terraform/src/index.ts b/plugins/terraform/src/index.ts index 97634c2500..4656cfb6b4 100644 --- a/plugins/terraform/src/index.ts +++ b/plugins/terraform/src/index.ts @@ -28,6 +28,7 @@ import type { ConvertModuleParams } from "@garden-io/core/build/src/plugin/handl import type { TerraformProvider, TerraformProviderConfig } from "./provider.js" import { terraformProviderConfigSchema } from "./provider.js" import type { PluginContext } from "@garden-io/core/build/src/plugin-context.js" +import { styles } from "@garden-io/core/build/src/logger/styles.js" // Need to make these variables to avoid escaping issues const deployOutputsTemplateString = "${deploys..outputs.}" @@ -51,7 +52,7 @@ export const gardenPlugin = () => prepareEnvironment, cleanupEnvironment, - async configureProvider({ config, projectRoot }) { + async configureProvider({ config, projectRoot, log }) { // Make sure the configured root path exists, if it is set if (config.initRoot) { const absRoot = join(projectRoot, config.initRoot) @@ -62,6 +63,7 @@ export const gardenPlugin = () => message: `Terraform: configured initRoot config directory '${config.initRoot}' does not exist`, }) } + log.info(`Using Terraform root config at path ${styles.highlight(absRoot)}`) } return { config } diff --git a/plugins/terraform/src/init.ts b/plugins/terraform/src/init.ts index 51aea33cfd..0f2b760136 100644 --- a/plugins/terraform/src/init.ts +++ b/plugins/terraform/src/init.ts @@ -76,7 +76,6 @@ export const prepareEnvironment: ProviderHandlers["prepareEnvironment"] = async export const cleanupEnvironment: ProviderHandlers["cleanupEnvironment"] = async ({ ctx, log }) => { const provider = ctx.provider as TerraformProvider - const providerLog = log.createLog({ name: provider.name }) if (!provider.config.initRoot) { // Nothing to do! @@ -84,7 +83,7 @@ export const cleanupEnvironment: ProviderHandlers["cleanupEnvironment"] = async } if (!provider.config.allowDestroy) { - providerLog.warn("allowDestroy is set to false. Not calling terraform destroy for root stack.") + log.warn("allowDestroy is set to false. Not calling terraform destroy for root stack.") return {} } @@ -92,10 +91,10 @@ export const cleanupEnvironment: ProviderHandlers["cleanupEnvironment"] = async const variables = provider.config.variables const workspace = provider.config.workspace || null - await setWorkspace({ ctx, provider, root, log: providerLog, workspace }) + await setWorkspace({ ctx, provider, root, log, workspace }) const args = ["destroy", "-auto-approve", "-input=false", ...(await prepareVariables(root, variables))] - await terraform(ctx, provider).exec({ log: providerLog, args, cwd: root }) + await terraform(ctx, provider).exec({ log, args, cwd: root }) return {} }