From 01957967bcab86ae7d361f6e5a15533e8521003d Mon Sep 17 00:00:00 2001 From: Eythor Magnusson Date: Tue, 21 Nov 2023 14:58:42 +0100 Subject: [PATCH] improvement(logger): better provider resolution lifecycle logs 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 {} }