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

@@ -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
     }
 

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)
 

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) {

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) {

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<string | undefined> {
     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<T>(path: string, params: ApiFetchParams): Promise<ApiFetchResponse<T>> {
     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 = {

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
       }

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.")

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,

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

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