Misc log fixes (#5330)

* fix(log): ensure action log inherits fixLevel

Before this fix, action log entries created from an input log with
'fixLevel' set, would not inherit that level but instead default to the
info level.

This was only really noticeable around some edge in the web dashboard
were logs that should've been verbose were rendered at the info level.

This fixes that and adds corresponding tests.

* improvement(server): log internal command requests at debug level

Before this fix, requests for internal commands like
_get-deploy-statuses weren't logged at all.

Now we log them at the debug level which is useful for, well, debugging
but also makes them visible in the web dashboard (if the appropriate
level is set) where they originate from.

* fix(cloud): correctly send error messages to server

Before this fix, we'd "render" error logs before sending them to
the server which meant that the "error" part was kept but the "msg" part
was dropped.

The user still sees the error but the message can be a bit chopped. This
fixes that by sending the "msg" field as is and adding an "error" field
to the payload as well that cloud handles separately.

core/src/cloud/buffered-event-stream.ts

@@ -15,9 +15,10 @@ import { got } from "../util/http"
 import type { LogLevel } from "../logger/logger"
 import type { Garden } from "../garden"
 import type { CloudSession } from "./api"
-import { getSection, renderError } from "../logger/renderers"
+import { getSection } from "../logger/renderers"
 import { registerCleanupFunction } from "../util/util"
 import { makeAuthHeader } from "./auth"
+import { toGardenError } from "../exceptions"
 
 const maxFlushFail = 10 // How many consecutive failures to flush events on a loop before stopping entirely
 /**
@@ -35,6 +36,7 @@ export type StreamEvent = {
 
 type LogEntryMessage = Pick<LogEntry, "msg" | "rawMsg" | "symbol" | "data" | "dataFormat"> & {
   section: string
+  error: string
 }
 
 export interface LogEntryEventPayload {
@@ -50,7 +52,7 @@ export interface LogEntryEventPayload {
 export function formatLogEntryForEventStream(entry: LogEntry): LogEntryEventPayload {
   // TODO @eysi: We're sending the section for backwards compatibility but it shouldn't really be needed.
   const section = getSection(entry) || ""
-  const msg = entry.error ? renderError(entry) : entry.msg
+  const error = entry.error ? toGardenError(entry.error).explain() : ""
   return {
     key: entry.key,
     metadata: entry.metadata,
@@ -59,7 +61,8 @@ export function formatLogEntryForEventStream(entry: LogEntry): LogEntryEventPayl
     context: entry.context,
     message: {
       section,
-      msg,
+      msg: entry.msg,
+      error,
       rawMsg: entry.rawMsg,
       symbol: entry.symbol,
       data: entry.data,

core/src/logger/log-entry.ts

@@ -195,7 +195,7 @@ export function createActionLog({
     parentConfigs: [...log.parentConfigs, log.getConfig()],
     metadata: log.metadata,
     root: log.root,
-    fixLevel,
+    fixLevel: fixLevel || log.fixLevel,
     context: {
       ...omitUndefined(log.context),
       type: "actionLog",

core/src/server/server.ts

@@ -41,7 +41,6 @@ import { eventLogLevel, LogLevel } from "../logger/logger"
 import { EventEmitter } from "eventemitter3"
 import { sanitizeValue } from "../util/logging"
 import { uuidv4 } from "../util/random"
-import { renderCommandErrors } from "../cli/helpers"
 import { GardenInstanceManager } from "./instance-manager"
 import { LocalConfigStore } from "../config-store/local"
 import { join } from "path"
@@ -725,10 +724,18 @@ export class GardenServer extends EventEmitter {
         }
 
         const persistent = command.maybePersistent(prepareParams)
-        // We don't want to print logs on every request for some commands.
-        const isInternal = internal || skipLogsForCommands.includes(command.getFullName())
-        const requestLog = this.log.createLog({ name: "garden-server" })
-        const cmdNameStr = chalk.bold.white(command.getFullName())
+
+        // The request log does the "high level" logging around the request life cycle
+        // but a separate command log is passed to the command that executes the request.
+        // Some commands we don't log at all, and internal commands we log at a higher log level.
+        const requestLog = skipLogsForCommands.includes(command.getFullName())
+          ? null
+          : this.log.createLog({
+              name: "garden-server",
+              fixLevel: internal ? LogLevel.debug : undefined,
+            })
+
+        const cmdNameStr = chalk.bold.white(command.getFullName() + (internal ? ` (internal)` : ""))
         const commandSessionId = requestId
 
         if (skipAnalyticsForCommands.includes(command.getFullName())) {
@@ -763,9 +770,7 @@ export class GardenServer extends EventEmitter {
               })
             }
 
-            if (!isInternal) {
-              requestLog.info(chalk.grey(`Running command ${cmdNameStr}`))
-            }
+            requestLog?.info(`Running command ${cmdNameStr}`)
 
             return command.run({
               ...prepareParams,
@@ -813,24 +818,27 @@ export class GardenServer extends EventEmitter {
                 errors,
               })
             )
-            if (!isInternal) {
-              if (errors?.length) {
-                renderCommandErrors(requestLog.root, errors, commandLog)
-              } else {
-                requestLog.success(chalk.green(`Command ${cmdNameStr} completed successfully`))
+
+            if (errors?.length && requestLog) {
+              requestLog.error(chalk.red(`Command ${cmdNameStr} failed with errors:`))
+              for (const error of errors) {
+                requestLog.error({ error })
               }
+            } else {
+              requestLog?.success(chalk.green(`Command ${cmdNameStr} completed successfully`))
             }
             delete this.activePersistentRequests[requestId]
           })
           .catch((error) => {
             send("error", { message: error.message, requestId })
-            if (!isInternal) {
-              requestLog.error({ error: toGardenError(error) })
-            }
+            requestLog?.error({
+              msg: chalk.red(`Command ${cmdNameStr} failed with errors:`),
+              error: toGardenError(error),
+            })
             delete this.activePersistentRequests[requestId]
           })
       } catch (error) {
-        this.log.error({
+        this.log.createLog({ name: "garden-server" }).error({
           msg: `Unexpected error handling request ID ${requestId}: ${error}`,
           error: toGardenError(error),
         })

core/test/unit/src/logger/log-entry.ts

@@ -301,6 +301,39 @@ describe("ActionLog", () => {
       })
     })
 
+    it("inherits fixLevel from input log if not set", () => {
+      const inputLog = log.createLog({
+        name: "test-log",
+        origin: "foo",
+        fixLevel: LogLevel.verbose,
+      })
+      // Inherits fixLevel from input log
+      const actionLogVerbose = createActionLog({
+        log: inputLog,
+        origin: "origin",
+        actionName: "api",
+        actionKind: "build",
+      })
+      expect(actionLogVerbose.fixLevel).to.eql(LogLevel.verbose)
+    })
+
+    it("overwrites input log fixLevel if set", () => {
+      const inputLog = log.createLog({
+        name: "test-log",
+        origin: "foo",
+        fixLevel: LogLevel.verbose,
+      })
+      // Overwrites fixLevel that was set on the input log
+      const actionLogDebug = createActionLog({
+        log: inputLog,
+        origin: "origin",
+        actionName: "api",
+        actionKind: "build",
+        fixLevel: LogLevel.debug,
+      })
+      expect(actionLogDebug.fixLevel).to.eql(LogLevel.debug)
+    })
+
     it("inherits context from input log", () => {
       log.context.sessionId = "foo"
       const actionLog = createActionLog({

core/test/unit/src/logger/logger.ts

@@ -11,6 +11,8 @@ import { getRootLogger, Logger, LogLevel, RootLogger } from "../../../../src/log
 import { LogEntryEventPayload } from "../../../../src/cloud/buffered-event-stream"
 import { freezeTime } from "../../../helpers"
 import { QuietWriter } from "../../../../src/logger/writers/quiet-writer"
+import { ConfigurationError } from "../../../../src/exceptions"
+import chalk from "chalk"
 
 const logger: Logger = getRootLogger()
 
@@ -37,6 +39,7 @@ describe("Logger", () => {
         log.info({
           msg: "hello",
           rawMsg: "hello-browser",
+          error: new ConfigurationError({ message: "hello-error" }),
           symbol: "success",
           data: { foo: "bar" },
           dataFormat: "json",
@@ -56,6 +59,7 @@ describe("Logger", () => {
           message: {
             msg: "hello",
             rawMsg: "hello-browser",
+            error: chalk.red("hello-error"),
             section: "log-context-name",
             symbol: "success",
             dataFormat: "json",