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

@@ -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("")

core/src/commands/deploy.ts

@@ -174,6 +174,7 @@ export class DeployCommand extends Command<Args, Opts> {
     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<Args, Opts> {
       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<Args, Opts> {
     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 } }
     }
 

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()
   }

core/src/plugins/kubernetes/ephemeral/config.ts

@@ -47,8 +47,6 @@ export const configSchema = () =>
 export async function configureProvider(params: ConfigureProviderParams<KubernetesConfig>) {
   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<Kubernet
   const ephemeralClusterDirPath = join(ctx.gardenDirPath, "ephemeral-kubernetes")
   await mkdirp(ephemeralClusterDirPath)
 
-  providerLog.info("Getting cluster info...")
+  log.info("Getting cluster info...")
   const createEphemeralClusterResponse = await ctx.cloudApi.createEphemeralCluster()
   const clusterId = createEphemeralClusterResponse.instanceMetadata.instanceId
 
   const deadlineDateTime = moment(createEphemeralClusterResponse.instanceMetadata.deadline)
   const diffInNowAndDeadline = moment.duration(deadlineDateTime.diff(moment())).asMinutes().toFixed(1)
-  providerLog.info(
+  log.info(
     `Cluster will be destroyed in ${styles.highlight(diffInNowAndDeadline)} minutes (at ${deadlineDateTime.format(
       "YYYY-MM-DD HH:mm:ss"
     )})`
   )
 
-  providerLog.info("Getting kubeconfig...")
+  log.info("Getting kubeconfig...")
   const kubeConfig = await ctx.cloudApi.getKubeConfigForCluster(clusterId)
   const kubeconfigFileName = `${clusterId}-kubeconfig.yaml`
   const kubeConfigPath = join(ctx.gardenDirPath, "ephemeral-kubernetes", kubeconfigFileName)
   await writeFile(kubeConfigPath, kubeConfig)
-  providerLog.info(`Kubeconfig saved at local path: ${styles.highlight(kubeConfigPath)}`)
+  log.info(`Kubeconfig saved at local path: ${styles.highlight(kubeConfigPath)}`)
 
   const parsedKubeConfig: any = load(kubeConfig)
   baseConfig.context = parsedKubeConfig["current-context"]
   baseConfig.kubeconfig = kubeConfigPath
 
-  providerLog.success("Done")
-
   // set deployment registry
   baseConfig.deploymentRegistry = {
     hostname: createEphemeralClusterResponse.registry.endpointAddress,

core/src/plugins/kubernetes/init.ts

@@ -40,6 +40,7 @@ import { mapValues } from "lodash-es"
 import { getIngressApiVersion, supportedIngressApiVersions } from "./container/ingress.js"
 import type { Log } from "../../logger/log-entry.js"
 import { ingressControllerInstall, ingressControllerReady } from "./nginx/ingress-controller.js"
+import { styles } from "../../logger/styles.js"
 
 const dockerAuthSecretType = "kubernetes.io/dockerconfigjson"
 const dockerAuthDocsLink = `
@@ -92,9 +93,11 @@ export async function getEnvironmentStatus({
   }
 
   if (provider.config.setupIngressController === "nginx") {
+    log.info(`Ensuring ${styles.highlight("nginx")} Ingress Controller...`)
     const ingressControllerReadiness = await ingressControllerReady(ctx, log)
     result.ready = ingressControllerReadiness
     detail.systemReady = ingressControllerReadiness
+    log.info(`${styles.highlight("nginx")} Ingress Controller ready`)
   } else {
     // We only need to warn about missing ingress classes if we're not using garden installed nginx
     const ingressApiVersion = await getIngressApiVersion(log, api, supportedIngressApiVersions)
@@ -106,6 +109,7 @@ export async function getEnvironmentStatus({
     )
     ingressWarnings.forEach((w) => log.warn(w))
   }
+
   return result
 }
 

core/src/plugins/kubernetes/local/config.ts

@@ -57,12 +57,11 @@ export async function configureProvider(params: ConfigureProviderParams<LocalKub
   const { base, log, projectName, ctx } = params
 
   const { config } = await base!(params)
-  const providerLog = log.createLog({ name: config.name })
 
   const provider = ctx.provider as KubernetesProvider
   provider.config = config
 
-  const kubeConfig: any = await getKubeConfig(providerLog, ctx, provider)
+  const kubeConfig: any = await getKubeConfig(log, ctx, provider)
 
   const currentContext = kubeConfig["current-context"]!
 
@@ -71,29 +70,29 @@ export async function configureProvider(params: ConfigureProviderParams<LocalKub
     if (currentContext && isSupportedContext(currentContext)) {
       // prefer current context if set and supported
       config.context = currentContext
-      providerLog.debug(`Using current context: ${config.context}`)
+      log.info(`Using current context: ${config.context}`)
     } else {
       const availableContexts = kubeConfig.contexts?.map((c: any) => 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
         }
       }
     }
 
     if (!config.context && kubeConfig.contexts?.length > 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") {

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}`)

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<Provider> {
     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<Provider> {
       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<Provider> {
     }
 
     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<Provider> {
 
   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<Provider> {
       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,39 +410,30 @@ export class ResolveProviderTask extends BaseTask<Provider> {
       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",
         pluginName,
         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)

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