chore: minor fixes and improvements in logging (#6487)

* chore: fix action config counter

* chore: change log message

* chore: use dot accessor

* refactor: use GraphSolver's logger in most cases

* refactor: remove unused log param from SolveParams

* refactor: remove unused argument

* refactor: lazy messages in silly-logging

core/src/commands/build.ts

@@ -122,7 +122,7 @@ export class BuildCommand extends Command<Args, Opts> {
         })
     )
 
-    const result = await garden.processTasks({ tasks, log })
+    const result = await garden.processTasks({ tasks })
 
     return handleProcessResults(garden, log, "build", result)
   }

core/src/commands/delete.ts

@@ -203,7 +203,7 @@ export class DeleteDeployCommand extends Command<DeleteDeployArgs, DeleteDeployO
       })
     })
 
-    const processed = await garden.processTasks({ tasks, log })
+    const processed = await garden.processTasks({ tasks })
     const result = deletedDeployStatuses(processed.results)
 
     log.success({ msg: "\nDone!", showDuration: false })

core/src/commands/deploy.ts

@@ -337,7 +337,7 @@ export class DeployCommand extends Command<Args, Opts> {
       return task
     })
 
-    const results = await garden.processTasks({ tasks, log })
+    const results = await garden.processTasks({ tasks })
 
     return handleProcessResults(garden, log, "deploy", results)
   }

core/src/commands/publish.ts

@@ -104,7 +104,7 @@ export class PublishCommand extends Command<Args, Opts, ProcessCommandResult> {
       })
     })
 
-    const processed = await garden.processTasks({ tasks, log, throwOnError: true })
+    const processed = await garden.processTasks({ tasks, throwOnError: true })
     return handleProcessResults(garden, log, "publish", processed)
   }
 }

core/src/commands/run.ts

@@ -208,7 +208,7 @@ export class RunCommand extends Command<Args, Opts> {
         })
     )
 
-    const results = await garden.processTasks({ tasks, log })
+    const results = await garden.processTasks({ tasks })
 
     return handleProcessResults(garden, log, "run", results)
   }

core/src/commands/sync/sync-start.ts

@@ -171,7 +171,7 @@ export class SyncStartCommand extends Command<Args, Opts> {
         }
         return task
       })
-      await garden.processTasks({ tasks, log })
+      await garden.processTasks({ tasks })
       log.success({ msg: "\nDone!", showDuration: false })
       return {}
     } else {
@@ -224,7 +224,7 @@ export async function startSyncWithoutDeploy({
     })
   })
 
-  const statusResult = await garden.processTasks({ log, tasks, statusOnly: true })
+  const statusResult = await garden.processTasks({ tasks, statusOnly: true })
   let someSyncStarted = false
 
   const router = await garden.getActionRouter()

core/src/commands/test.ts

@@ -221,7 +221,7 @@ export class TestCommand extends Command<Args, Opts> {
       })
     }
 
-    const results = await garden.processTasks({ tasks, log })
+    const results = await garden.processTasks({ tasks })
 
     return handleProcessResults(garden, log, "test", results)
   }

core/src/garden.ts

@@ -606,8 +606,8 @@ export class Garden {
     return this.solver.solve(params)
   }
 
-  async processTask<T extends Task>(task: T, log: Log, opts: SolveOpts): Promise<GraphResultFromTask<T> | null> {
-    const { results } = await this.solver.solve({ tasks: [task], log, ...opts })
+  async processTask<T extends Task>(task: T, opts: SolveOpts): Promise<GraphResultFromTask<T> | null> {
+    const { results } = await this.solver.solve({ tasks: [task], ...opts })
     return results.getResult(task)
   }
 
@@ -847,7 +847,7 @@ export class Garden {
       })
 
       // Process as many providers in parallel as possible
-      const taskResults = await this.processTasks({ tasks, log, statusOnly })
+      const taskResults = await this.processTasks({ tasks, statusOnly })
 
       const providerResults = Object.values(taskResults.results.getMap())
 
@@ -1493,6 +1493,7 @@ export class Garden {
 
       for (const config of actionsFromTemplates) {
         this.addActionConfig(config)
+        actionsCount++
       }
 
       this.log.debug(
@@ -1545,7 +1546,7 @@ 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 action config for ${config.kind} ${config.name}`)
     const key = actionReferenceToString(config)
     const existing = this.actionConfigs[config.kind][config.name]
 

core/src/graph/actions.ts

@@ -543,7 +543,7 @@ export async function resolveAction<T extends Action>({
     force: true,
   })
 
-  const results = await garden.processTasks({ tasks: [task], log, throwOnError: true })
+  const results = await garden.processTasks({ tasks: [task], throwOnError: true })
 
   log.success({ msg: `Done`, showDuration: false })
 
@@ -581,7 +581,7 @@ export async function resolveActions<T extends Action>({
       })
   )
 
-  const results = await garden.processTasks({ tasks, log, throwOnError: true })
+  const results = await garden.processTasks({ tasks, throwOnError: true })
 
   return <ResolvedActions<T>>(<unknown>mapValues(results.results.getMap(), (r) => r!.result!.outputs.resolvedAction))
 }
@@ -611,7 +611,7 @@ export async function executeAction<T extends Action>({
     force: true,
   })
 
-  const results = await garden.processTasks({ tasks: [task], log, throwOnError: true, statusOnly })
+  const results = await garden.processTasks({ tasks: [task], throwOnError: true, statusOnly })
 
   return <Executed<T>>(<unknown>results.results.getResult(task)!.result!.executedAction)
 }

core/src/graph/solver.ts

@@ -11,7 +11,7 @@ import type { Log } from "../logger/log-entry.js"
 import type { GardenError, GardenErrorParams } from "../exceptions.js"
 import { GraphError, toGardenError } from "../exceptions.js"
 import { uuidv4 } from "../util/random.js"
-import { DependencyGraph, metadataForLog } from "./common.js"
+import { DependencyGraph } from "./common.js"
 import { Profile } from "../util/profiling.js"
 import { TypedEventEmitter } from "../util/events.js"
 import { groupBy, keyBy } from "lodash-es"
@@ -34,7 +34,6 @@ export interface SolveOpts {
 }
 
 export interface SolveParams<T extends BaseTask = BaseTask> extends SolveOpts {
-  log: Log
   tasks: T[]
 }
 
@@ -67,7 +66,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
   ) {
     super()
 
-    this.log = garden.log
+    this.log = garden.log.createLog({ name: "graph-solver" })
     this.inLoop = false
     this.requestedTasks = {}
     this.nodes = {}
@@ -91,18 +90,19 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
   }
 
   async solve(params: SolveParams): Promise<SolveResult> {
-    const { statusOnly, tasks, throwOnError, log } = params
+    const { statusOnly, tasks, throwOnError } = params
 
     const batchId = uuidv4()
     const results = new GraphResults(tasks)
     let aborted = false
 
-    log.silly(`GraphSolver: Starting batch ${batchId} (${tasks.length} tasks)`)
+    this.log.silly(() => `Starting batch ${batchId} (${tasks.length} tasks)`)
 
     if (tasks.length === 0) {
       return { results, error: null }
     }
 
+    const log = this.log
     // TODO-0.13.1+: remove this lock and test with concurrent execution
     return this.lock.acquire("solve", async () => {
       const output = await new Promise<SolveResult>((resolve, reject) => {
@@ -114,7 +114,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
         )
 
         function completeHandler(result: GraphResult) {
-          log.silly(`GraphSolver: Complete handler for batch ${batchId} called with result ${result.key}`)
+          log.silly(() => `Complete handler for batch ${batchId} called with result ${result.key}`)
 
           if (aborted) {
             return
@@ -129,7 +129,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
             return
           }
 
-          log.silly(`GraphSolver: Complete handler for batch ${batchId} matched with request ${request.getKey()}`)
+          log.silly(() => `Complete handler for batch ${batchId} matched with request ${request.getKey()}`)
 
           results.setResult(request.task, result)
 
@@ -148,7 +148,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
 
           if (missing.length > 0) {
             const missingKeys = missing.map((t) => t.getBaseKey())
-            log.silly(`Batch ${batchId} has ${missing.length} result(s) still missing: ${missingKeys.join(", ")}`)
+            log.silly(() => `Batch ${batchId} has ${missing.length} result(s) still missing: ${missingKeys.join(", ")}`)
             // Keep going if any of the expected results are pending
             return
           }
@@ -182,9 +182,9 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
           cleanup({ error: null })
 
           if (error) {
-            log.silly(`Batch ${batchId} failed: ${error.message}`)
+            log.silly(() => `Batch ${batchId} failed: ${error.message}`)
           } else {
-            log.silly(`Batch ${batchId} completed`)
+            log.silly(() => `Batch ${batchId} completed`)
           }
 
           resolve({ error, results })
@@ -380,7 +380,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
       return
     }
 
-    this.logTask(node)
+    this.log.silly(() => `Processing node ${taskStyle(node.getKey())}`)
 
     try {
       const processResult = await node.execute()
@@ -445,7 +445,10 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
     }
 
     const currentlyActive = Object.values(this.inProgress).map((n) => n.describe())
-    this.log.silly(`Task nodes in progress: ${currentlyActive.length > 0 ? currentlyActive.join(", ") : "(none)"}`)
+    this.log.silly(
+      () =>
+        `Task nodes in progress (${currentlyActive.length}): ${currentlyActive.length > 0 ? currentlyActive.join(", ") : "(none)"}`
+    )
   }
 
   private ensurePendingNode(node: TaskNode, dependant: TaskNode) {
@@ -486,28 +489,16 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
   //
   // Logging
   //
-  private logTask(node: TaskNode) {
-    // The task.log instance is of type ActionLog but we want to use a "CoreLog" here.
-    const taskLog = node.task.log.root.createLog({ name: "graph-solver" })
-    taskLog.silly({
-      msg: `Processing node ${taskStyle(node.getKey())}`,
-      metadata: metadataForLog({
-        task: node.task,
-        inputVersion: node.getInputVersion(),
-        status: "active",
-      }),
-    })
-  }
-
   private logTaskError(node: TaskNode, err: Error) {
     const log = node.task.log
     const prefix = `Failed ${node.describe()} ${renderDuration(log.getDuration())}. This is what happened:`
     this.logError(log, err, prefix)
   }
 
   private logInternalError(node: TaskNode, err: Error) {
-    const prefix = `An internal error occurred while ${node.describe()}. This is what happened:`
-    this.logError(node.task.log, err, prefix)
+    const log = node.task.log
+    const prefix = `An internal error occurred while ${node.describe()} ${renderDuration(log.getDuration())}. This is what happened:`
+    this.logError(log, err, prefix)
   }
 
   private logError(log: Log, err: Error, errMessagePrefix: string) {
@@ -519,7 +510,7 @@ export class GraphSolver extends TypedEventEmitter<SolverEvents> {
     })
     log.error({ msg, rawMsg, error, showDuration: false })
     const divider = renderDivider()
-    log.silly(
+    log.silly(() =>
       styles.primary(`Full error with stack trace and wrapped errors:\n${divider}\n${error.toString(true)}\n${divider}`)
     )
   }

core/src/outputs.ts

@@ -94,7 +94,7 @@ export async function resolveProjectOutputs(garden: Garden, log: Log): Promise<O
 
   const { results } =
     graphTasks.length > 0
-      ? await garden.processTasks({ tasks: graphTasks, log, throwOnError: true })
+      ? await garden.processTasks({ tasks: graphTasks, throwOnError: true })
       : { results: new GraphResults([]) }
 
   const configContext = await garden.getOutputConfigContext(log, modules, results)

core/src/plugins/kubernetes/logs.ts

@@ -337,7 +337,7 @@ export class K8sLogFollower<T extends LogEntryBase> {
       }
     } catch (e) {
       if (e instanceof KubernetesError) {
-        this.log.silly(`<Encountered error while fetching Pod status for ${description}. Reason: ${e.message}>`)
+        this.log.silly(() => `<Encountered error while fetching Pod status for ${description}. Reason: ${e.message}>`)
         // retry once if the pod status query returned 404
         if (e.responseStatusCode === 404 && prevStatus === "error") {
           stopRetrying("The pod or the namespace does not exist")

core/src/plugins/kubernetes/namespace.ts

@@ -287,7 +287,7 @@ export async function prepareNamespaces({ ctx, log }: GetEnvironmentStatusParams
     if (!(err instanceof KubernetesError)) {
       throw err
     }
-    log.silly(`Full Kubernetes connect error: ${err.stack}`)
+    log.silly(() => `Full Kubernetes connect error: ${err.stack}`)
 
     throw new DeploymentError({
       message: dedent`

core/src/router/router.ts

@@ -123,7 +123,7 @@ export class ActionRouter extends BaseRouter {
           forceActions: [],
         })
     )
-    const { results } = await this.garden.processTasks({ tasks, log, throwOnError: true, statusOnly: true })
+    const { results } = await this.garden.processTasks({ tasks, throwOnError: true, statusOnly: true })
 
     return getDeployStatuses(results)
   }
@@ -143,7 +143,7 @@ export class ActionRouter extends BaseRouter {
         })
     )
 
-    return this.garden.processTasks({ tasks, log })
+    return this.garden.processTasks({ tasks })
   }
 
   /**
@@ -176,7 +176,7 @@ export class ActionRouter extends BaseRouter {
       })
     })
 
-    const { results } = await this.garden.processTasks({ tasks, log, throwOnError: true })
+    const { results } = await this.garden.processTasks({ tasks, throwOnError: true })
 
     const serviceStatuses = deletedDeployStatuses(results)
 

core/src/util/testing.ts

@@ -31,7 +31,6 @@ import { getRootLogger } from "../logger/logger.js"
 import stripAnsi from "strip-ansi"
 import type { VcsHandler } from "../vcs/vcs.js"
 import type { ConfigGraph } from "../graph/config-graph.js"
-import type { SolveParams } from "../graph/solver.js"
 import type { GraphResults } from "../graph/results.js"
 import { expect } from "chai"
 import type { ActionConfig, ActionConfigMap, ActionKind, ActionStatus } from "../actions/types.js"
@@ -254,10 +253,6 @@ export class TestGarden extends Garden {
     }
   }
 
-  override async processTasks(params: Omit<SolveParams, "log"> & { log?: Log }) {
-    return super.processTasks({ ...params, log: params.log || this.log })
-  }
-
   /**
    * Override to cache the config graph.
    */

core/src/vcs/git-sub-tree.ts

@@ -195,7 +195,7 @@ export class GitSubTreeHandler extends AbstractGitHandler {
     const submodules = await this.getSubmodules(path)
     const submodulePaths = submodules.map((s) => join(gitRoot, s.path))
     if (submodules.length > 0) {
-      gitLog.silly(`Submodules listed at ${submodules.map((s) => `${s.path} (${s.url})`).join(", ")}`)
+      gitLog.silly(() => `Submodules listed at ${submodules.map((s) => `${s.path} (${s.url})`).join(", ")}`)
     }
 
     let submoduleFiles: Promise<VcsFile[]>[] = []

core/src/vcs/git.ts

@@ -59,7 +59,7 @@ function gitCliExecutor({ log, cwd, failOnPrompt = false }: GitCliParams): GitCl
    * @throws ChildProcessError
    */
   return async (...args: string[]) => {
-    log.silly(`Calling git with args '${args.join(" ")}' in ${cwd}`)
+    log.silly(() => `Calling git with args '${args.join(" ")}' in ${cwd}`)
     const { stdout } = await exec("git", args, {
       cwd,
       maxBuffer: 100 * 1024 * 1024,
@@ -135,7 +135,7 @@ export class GitCli {
       output.originUrl = await this.getOriginUrl()
     } catch (err) {
       // Just ignore if not available
-      this.log.silly(`Tried to retrieve git remote.origin.url but encountered an error: ${err}`)
+      this.log.silly(() => `Tried to retrieve git remote.origin.url but encountered an error: ${err}`)
     }
 
     return output

core/test/integ/src/plugins/kubernetes/commands/exec.ts

@@ -31,7 +31,7 @@ describe("runExecCommand", () => {
       force: true,
       forceBuild: false,
     })
-    await garden.processTasks({ tasks: [deployTask], log: garden.log, throwOnError: true })
+    await garden.processTasks({ tasks: [deployTask], throwOnError: true })
   })
 
   async function resolveDeployAction(name: string) {