From c76923e7537ecab13f8ac3751721a3c32f7828e8 Mon Sep 17 00:00:00 2001
From: Wes <wesbillman@users.noreply.github.com>
Date: Fri, 2 Feb 2024 08:06:00 -0700
Subject: [PATCH] feat: reduce logging levels

---
 authn/authn.go                                |  20 +--
 backend/common/download/download.go           |   4 +-
 backend/common/exec/circularbuffer.go         | 118 ++++++++++++++++++
 backend/common/exec/exec.go                   |  20 ++-
 backend/common/observability/client.go        |   2 +-
 backend/common/plugin/serve.go                |   4 +-
 backend/common/plugin/spawn.go                |   6 +-
 backend/common/rpc/rpc.go                     |   2 +-
 backend/controller/controller.go              |  34 ++---
 backend/controller/dal/dal.go                 |   2 +-
 backend/controller/dal/notify.go              |   8 +-
 .../controller/scaling/localscaling/devel.go  |   2 +-
 .../scaling/localscaling/local_scaling.go     |   6 +-
 .../scheduledtask/scheduledtask_test.go       |   2 +-
 backend/runner/runner.go                      |  10 +-
 cmd/ftl/cmd_build.go                          |  21 +++-
 cmd/ftl/cmd_build_go.go                       |   7 +-
 cmd/ftl/cmd_build_kotlin.go                   |  10 +-
 cmd/ftl/cmd_deploy.go                         |  19 ++-
 cmd/ftl/cmd_dev.go                            |   4 +-
 cmd/ftl/cmd_init.go                           |   7 +-
 cmd/ftl/cmd_schema_generate.go                |  10 +-
 cmd/ftl/cmd_schema_import.go                  |  14 +--
 cmd/ftl/cmd_serve.go                          |  16 ++-
 cmd/ftl/main.go                               |   2 +-
 frontend/local.go                             |   6 +-
 go-runtime/compile/build.go                   |  16 +--
 go-runtime/encoding/encoding.go               |   2 +
 integration/integration_test.go               |   6 +-
 .../ftl/hotswap/FtlHotswapAgentPlugin.kt      |   2 +-
 .../kotlin/xyz/block/ftl/registry/Registry.kt |   4 +-
 31 files changed, 270 insertions(+), 116 deletions(-)
 create mode 100644 backend/common/exec/circularbuffer.go

diff --git a/authn/authn.go b/authn/authn.go
index 1dec8aaaac..94b5eb930f 100644
--- a/authn/authn.go
+++ b/authn/authn.go
@@ -31,7 +31,7 @@ func GetAuthenticationHeaders(ctx context.Context, endpoint *url.URL, authentica
 	logger := log.FromContext(ctx).Scope(endpoint.Hostname())
 
 	// Next, try the authenticator.
-	logger.Debugf("Trying authenticator")
+	logger.Tracef("Trying authenticator")
 	authenticator, ok := authenticators[endpoint.Hostname()]
 	if !ok {
 		logger.Tracef("No authenticator found for %s in %s", endpoint, authenticators)
@@ -51,13 +51,13 @@ func GetAuthenticationHeaders(ctx context.Context, endpoint *url.URL, authentica
 
 	// First, check if we have credentials in the keyring and that they work.
 	keyringKey := "ftl+" + endpoint.String()
-	logger.Debugf("Trying keyring key %s", keyringKey)
+	logger.Tracef("Trying keyring key %s", keyringKey)
 	creds, err := keyring.Get(keyringKey, usr.Name)
 	if errors.Is(err, keyring.ErrNotFound) {
 		logger.Tracef("No credentials found in keyring")
 	} else if err != nil {
 		if !strings.Contains(err.Error(), `exec: "dbus-launch": executable file not found in $PATH`) {
-			logger.Debugf("Failed to get credentials from keyring: %s", err)
+			logger.Tracef("Failed to get credentials from keyring: %s", err)
 		}
 	} else {
 		logger.Tracef("Credentials found in keyring: %s", creds)
@@ -84,7 +84,7 @@ func GetAuthenticationHeaders(ctx context.Context, endpoint *url.URL, authentica
 		return nil, nil
 	}
 
-	logger.Debugf("Authenticator %s succeeded", authenticator)
+	logger.Tracef("Authenticator %s succeeded", authenticator)
 	w := &strings.Builder{}
 	for name, values := range headers {
 		for _, value := range values {
@@ -93,7 +93,7 @@ func GetAuthenticationHeaders(ctx context.Context, endpoint *url.URL, authentica
 	}
 	err = keyring.Set(keyringKey, usr.Name, w.String())
 	if err != nil {
-		logger.Debugf("Failed to save credentials to keyring: %s", err)
+		logger.Tracef("Failed to save credentials to keyring: %s", err)
 	}
 	return headers, nil
 }
@@ -127,7 +127,7 @@ func checkAuth(ctx context.Context, logger *log.Logger, endpoint *url.URL, creds
 	if err != nil {
 		return nil, err
 	}
-	logger.Debugf("Authentication probe: %s %s", req.Method, req.URL)
+	logger.Tracef("Authentication probe: %s %s", req.Method, req.URL)
 	for header, values := range headers {
 		for _, value := range values {
 			req.Header.Add(header, value)
@@ -141,12 +141,12 @@ func checkAuth(ctx context.Context, logger *log.Logger, endpoint *url.URL, creds
 	defer resp.Body.Close() //nolint:gosec
 	if resp.StatusCode != http.StatusOK {
 		body, _ := io.ReadAll(resp.Body)
-		logger.Debugf("Endpoint returned %d for authenticated request", resp.StatusCode)
-		logger.Debugf("Response headers: %s", resp.Header)
-		logger.Debugf("Response body: %s", body)
+		logger.Tracef("Endpoint returned %d for authenticated request", resp.StatusCode)
+		logger.Tracef("Response headers: %s", resp.Header)
+		logger.Tracef("Response body: %s", body)
 		return nil, nil
 	}
-	logger.Debugf("Successfully authenticated with %s", headers)
+	logger.Tracef("Successfully authenticated with %s", headers)
 	return headers, nil
 }
 
diff --git a/backend/common/download/download.go b/backend/common/download/download.go
index 8de07af033..e251e15823 100644
--- a/backend/common/download/download.go
+++ b/backend/common/download/download.go
@@ -39,7 +39,7 @@ func Artefacts(ctx context.Context, client ftlv1connect.ControllerServiceClient,
 			if !filepath.IsLocal(artefact.Path) {
 				return fmt.Errorf("path %q is not local", artefact.Path)
 			}
-			logger.Infof("Downloading %s", filepath.Join(dest, artefact.Path))
+			logger.Debugf("Downloading %s", filepath.Join(dest, artefact.Path))
 			err = os.MkdirAll(filepath.Join(dest, filepath.Dir(artefact.Path)), 0700)
 			if err != nil {
 				return err
@@ -63,6 +63,6 @@ func Artefacts(ctx context.Context, client ftlv1connect.ControllerServiceClient,
 	if w != nil {
 		w.Close()
 	}
-	logger.Infof("Downloaded %d artefacts in %s", count, time.Since(start))
+	logger.Debugf("Downloaded %d artefacts in %s", count, time.Since(start))
 	return stream.Err()
 }
diff --git a/backend/common/exec/circularbuffer.go b/backend/common/exec/circularbuffer.go
new file mode 100644
index 0000000000..194727d145
--- /dev/null
+++ b/backend/common/exec/circularbuffer.go
@@ -0,0 +1,118 @@
+package exec
+
+import (
+	"bufio"
+	"bytes"
+	"container/ring"
+	"context"
+	"fmt"
+	"io"
+	"runtime"
+	"sync"
+
+	"github.com/TBD54566975/ftl/backend/common/log"
+)
+
+type CircularBuffer struct {
+	r    *ring.Ring
+	size int
+	mu   sync.Mutex
+	cap  int
+}
+
+func NewCircularBuffer(capacity int) *CircularBuffer {
+	return &CircularBuffer{
+		r:   ring.New(capacity),
+		cap: capacity,
+	}
+}
+
+// Write accepts a string and stores it in the buffer.
+// It expects entire lines and stores each line as a separate entry in the ring buffer.
+func (cb *CircularBuffer) Write(p string) error {
+	cb.mu.Lock()
+	defer cb.mu.Unlock()
+
+	cb.r.Value = p
+	cb.r = cb.r.Next()
+
+	if cb.size < cb.cap {
+		cb.size++
+	}
+
+	return nil
+}
+
+func (cb *CircularBuffer) Bytes() []byte {
+	cb.mu.Lock()
+	defer cb.mu.Unlock()
+
+	if cb.size == 0 {
+		fmt.Println("Buffer is empty.")
+		return []byte{}
+	}
+
+	var buf bytes.Buffer
+	start := cb.r.Move(-cb.size) // Correctly calculate the starting position
+
+	for i := 0; i < cb.size; i++ {
+		if str, ok := start.Value.(string); ok {
+			buf.WriteString(str)
+		} else {
+			fmt.Println("Unexpected type or nil found in buffer")
+		}
+		start = start.Next()
+	}
+
+	return buf.Bytes()
+}
+
+func (cb *CircularBuffer) WriterAt(ctx context.Context, level log.Level) *io.PipeWriter {
+	// Copied from logger.go which is based on logrus
+	// Based on MIT licensed Logrus https://github.com/sirupsen/logrus/blob/bdc0db8ead3853c56b7cd1ac2ba4e11b47d7da6b/writer.go#L27
+	logger := log.FromContext(ctx)
+	reader, writer := io.Pipe()
+	var printFunc func(format string, args ...interface{})
+
+	switch level {
+	case log.Trace:
+		printFunc = logger.Tracef
+	case log.Debug:
+		printFunc = logger.Debugf
+	case log.Info:
+		printFunc = logger.Infof
+	case log.Warn:
+		printFunc = logger.Warnf
+	case log.Error:
+		printFunc = func(format string, args ...interface{}) {
+			logger.Errorf(nil, format, args...)
+		}
+	default:
+		panic(level)
+	}
+
+	go cb.writerScanner(reader, printFunc)
+	runtime.SetFinalizer(writer, writerFinalizer)
+
+	return writer
+}
+
+func (cb *CircularBuffer) writerScanner(reader *io.PipeReader, printFunc func(format string, args ...interface{})) {
+	scanner := bufio.NewScanner(reader)
+	for scanner.Scan() {
+		text := scanner.Text()
+		printFunc(text)
+		err := cb.Write(text + "\n")
+		if err != nil {
+			fmt.Println("Error writing to buffer")
+		}
+	}
+	if err := scanner.Err(); err != nil {
+		fmt.Println("Error reading from pipe:", err)
+	}
+	reader.Close()
+}
+
+func writerFinalizer(writer *io.PipeWriter) {
+	writer.Close()
+}
diff --git a/backend/common/exec/exec.go b/backend/common/exec/exec.go
index b92933aad4..00a8484cd4 100644
--- a/backend/common/exec/exec.go
+++ b/backend/common/exec/exec.go
@@ -2,6 +2,7 @@ package exec
 
 import (
 	"context"
+	"fmt"
 	"os"
 	"os/exec"
 	"syscall"
@@ -13,6 +14,7 @@ import (
 
 type Cmd struct {
 	*exec.Cmd
+	level log.Level
 }
 
 func LookPath(exe string) (string, error) {
@@ -45,7 +47,23 @@ func Command(ctx context.Context, level log.Level, dir, exe string, args ...stri
 	cmd.Stdout = output
 	cmd.Stderr = output
 	cmd.Env = os.Environ()
-	return &Cmd{cmd}
+	return &Cmd{cmd, level}
+}
+
+// RunBuffered runs the command and captures the output. If the command fails, the output is logged.
+func (c *Cmd) RunBuffered(ctx context.Context) error {
+	outputBuffer := NewCircularBuffer(100)
+	output := outputBuffer.WriterAt(ctx, c.level)
+	c.Cmd.Stdout = output
+	c.Cmd.Stderr = output
+
+	err := c.Run()
+	if err != nil {
+		fmt.Printf("%s", outputBuffer.Bytes())
+		return err
+	}
+
+	return nil
 }
 
 // Kill sends a signal to the process group of the command.
diff --git a/backend/common/observability/client.go b/backend/common/observability/client.go
index ba241dd477..4150c2830b 100644
--- a/backend/common/observability/client.go
+++ b/backend/common/observability/client.go
@@ -40,7 +40,7 @@ func Init(ctx context.Context, serviceName, serviceVersion string, config Config
 		return nil
 	}
 
-	logger.Infof("OTEL is enabled, exporting to %s", os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT"))
+	logger.Debugf("OTEL is enabled, exporting to %s", os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT"))
 
 	otelLogger := NewOtelLogger(logger, config.LogLevel)
 	otel.SetLogger(otelLogger)
diff --git a/backend/common/plugin/serve.go b/backend/common/plugin/serve.go
index d4fae136ce..302d27d316 100644
--- a/backend/common/plugin/serve.go
+++ b/backend/common/plugin/serve.go
@@ -119,14 +119,14 @@ func Start[Impl any, Iface any, Config any](
 	logger = logger.Scope(name)
 	ctx = log.ContextWithLogger(ctx, logger)
 
-	logger.Debugf("Starting on %s", cli.Bind)
+	logger.Tracef("Starting on %s", cli.Bind)
 
 	// Signal handling.
 	sigch := make(chan os.Signal, 1)
 	signal.Notify(sigch, syscall.SIGINT, syscall.SIGTERM)
 	go func() {
 		sig := <-sigch
-		logger.Infof("Terminated by signal %s", sig)
+		logger.Debugf("Terminated by signal %s", sig)
 		cancel()
 		_ = syscall.Kill(-syscall.Getpid(), sig.(syscall.Signal)) //nolint:forcetypeassert
 		os.Exit(0)
diff --git a/backend/common/plugin/spawn.go b/backend/common/plugin/spawn.go
index 8bb09f5c1f..ffa7d159c0 100644
--- a/backend/common/plugin/spawn.go
+++ b/backend/common/plugin/spawn.go
@@ -121,7 +121,7 @@ func Spawn[Client PingableClient](
 
 	// Start the plugin process.
 	pluginEndpoint := &url.URL{Scheme: "http", Host: addr.String()}
-	logger.Debugf("Spawning plugin on %s", pluginEndpoint)
+	logger.Tracef("Spawning plugin on %s", pluginEndpoint)
 	cmd := exec.Command(ctx, defaultLevel, dir, exe)
 
 	// Send the plugin's stderr to the logger.
@@ -142,7 +142,7 @@ func Spawn[Client PingableClient](
 	go func() { cancelWithCause(cmd.Wait()) }()
 
 	go func() {
-		err := log.JSONStreamer(pipe, logger, log.Info)
+		err := log.JSONStreamer(pipe, logger, log.Debug)
 		if err != nil {
 			logger.Errorf(err, "Error streaming plugin logs.")
 		}
@@ -196,7 +196,7 @@ func Spawn[Client PingableClient](
 		makeClient(pluginEndpoint.String())
 	}
 
-	logger.Infof("Online")
+	logger.Debugf("Online")
 	plugin = &Plugin[Client]{Cmd: cmd, Endpoint: pluginEndpoint, Client: client}
 	return plugin, cmdCtx, nil
 }
diff --git a/backend/common/rpc/rpc.go b/backend/common/rpc/rpc.go
index a5a4b492d9..12f1963bfb 100644
--- a/backend/common/rpc/rpc.go
+++ b/backend/common/rpc/rpc.go
@@ -154,7 +154,7 @@ func RetryStreamingClientStream[Req, Resp any](
 				break
 			}
 			if errored {
-				logger.Infof("Stream recovered")
+				logger.Debugf("Stream recovered")
 				errored = false
 			}
 			select {
diff --git a/backend/controller/controller.go b/backend/controller/controller.go
index fc439cf31b..23f31ce52b 100644
--- a/backend/controller/controller.go
+++ b/backend/controller/controller.go
@@ -76,7 +76,7 @@ func Start(ctx context.Context, config Config, runnerScaling scaling.RunnerScali
 	config.SetDefaults()
 
 	logger := log.FromContext(ctx)
-	logger.Infof("Starting FTL controller")
+	logger.Debugf("Starting FTL controller")
 
 	c, err := frontend.Server(ctx, config.ContentTime, config.ConsoleURL)
 	if err != nil {
@@ -97,7 +97,7 @@ func Start(ctx context.Context, config Config, runnerScaling scaling.RunnerScali
 	if err != nil {
 		return err
 	}
-	logger.Infof("Listening on %s", config.Bind)
+	logger.Debugf("Listening on %s", config.Bind)
 
 	console := NewConsoleService(dal)
 
@@ -178,7 +178,7 @@ type HTTPResponse struct {
 // ServeHTTP handles ingress routes.
 func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	logger := log.FromContext(r.Context())
-	logger.Infof("%s %s", r.Method, r.URL.Path)
+	logger.Debugf("%s %s", r.Method, r.URL.Path)
 	routes, err := s.dal.GetIngressRoutes(r.Context(), r.Method)
 	if err != nil {
 		if errors.Is(err, dal.ErrNotFound) {
@@ -460,7 +460,7 @@ func (s *Service) UpdateDeploy(ctx context.Context, req *connect.Request[ftlv1.U
 	}
 
 	logger := s.getDeploymentLogger(ctx, deploymentName)
-	logger.Infof("Update deployment for: %s", deploymentName)
+	logger.Debugf("Update deployment for: %s", deploymentName)
 
 	err = s.dal.SetDeploymentReplicas(ctx, deploymentName, int(req.Msg.MinReplicas))
 	if err != nil {
@@ -482,7 +482,7 @@ func (s *Service) ReplaceDeploy(ctx context.Context, c *connect.Request[ftlv1.Re
 	}
 
 	logger := s.getDeploymentLogger(ctx, newDeploymentName)
-	logger.Infof("Replace deployment for: %s", newDeploymentName)
+	logger.Debugf("Replace deployment for: %s", newDeploymentName)
 
 	err = s.dal.ReplaceDeployment(ctx, newDeploymentName, int(c.Msg.MinReplicas))
 	if err != nil {
@@ -490,7 +490,7 @@ func (s *Service) ReplaceDeploy(ctx context.Context, c *connect.Request[ftlv1.Re
 			logger.Errorf(err, "Deployment not found: %s", newDeploymentName)
 			return nil, connect.NewError(connect.CodeNotFound, errors.New("deployment not found"))
 		} else if errors.Is(err, dal.ErrConflict) {
-			logger.Infof("Deployment already exists: %s", newDeploymentName)
+			logger.Debugf("Deployment already exists: %s", newDeploymentName)
 		} else {
 			logger.Errorf(err, "Could not replace deployment: %s", newDeploymentName)
 			return nil, fmt.Errorf("%s: %w", "could not replace deployment", err)
@@ -578,7 +578,7 @@ func (s *Service) GetDeployment(ctx context.Context, req *connect.Request[ftlv1.
 	}
 
 	logger := s.getDeploymentLogger(ctx, deployment.Name)
-	logger.Infof("Get deployment for: %s", deployment.Name)
+	logger.Debugf("Get deployment for: %s", deployment.Name)
 
 	return connect.NewResponse(&ftlv1.GetDeploymentResponse{
 		Schema:    deployment.Schema.ToProto().(*schemapb.Module), //nolint:forcetypeassert
@@ -594,7 +594,7 @@ func (s *Service) GetDeploymentArtefacts(ctx context.Context, req *connect.Reque
 	defer deployment.Close()
 
 	logger := s.getDeploymentLogger(ctx, deployment.Name)
-	logger.Infof("Get deployment artefacts for: %s", deployment.Name)
+	logger.Debugf("Get deployment artefacts for: %s", deployment.Name)
 
 	chunk := make([]byte, s.config.ArtefactChunkSize)
 nextArtefact:
@@ -717,7 +717,7 @@ func (s *Service) UploadArtefact(ctx context.Context, req *connect.Request[ftlv1
 	if err != nil {
 		return nil, err
 	}
-	logger.Infof("Created new artefact %s", digest)
+	logger.Debugf("Created new artefact %s", digest)
 	return connect.NewResponse(&ftlv1.UploadArtefactResponse{Digest: digest[:]}), nil
 }
 
@@ -762,7 +762,7 @@ func (s *Service) CreateDeployment(ctx context.Context, req *connect.Request[ftl
 		return nil, fmt.Errorf("%s: %w", "could not create deployment", err)
 	}
 	deploymentLogger := s.getDeploymentLogger(ctx, dname)
-	deploymentLogger.Infof("Created deployment %s", dname)
+	deploymentLogger.Debugf("Created deployment %s", dname)
 	return connect.NewResponse(&ftlv1.CreateDeploymentResponse{DeploymentName: dname.String()}), nil
 }
 
@@ -846,7 +846,7 @@ func (s *Service) reconcileDeployments(ctx context.Context) (time.Duration, erro
 	for _, reconcile := range reconciliation {
 		reconcile := reconcile
 		deploymentLogger := s.getDeploymentLogger(ctx, reconcile.Deployment)
-		deploymentLogger.Infof("Reconciling %s", reconcile.Deployment)
+		deploymentLogger.Debugf("Reconciling %s", reconcile.Deployment)
 		deployment := model.Deployment{
 			Module:   reconcile.Module,
 			Language: reconcile.Language,
@@ -854,23 +854,23 @@ func (s *Service) reconcileDeployments(ctx context.Context) (time.Duration, erro
 		}
 		require := reconcile.RequiredReplicas - reconcile.AssignedReplicas
 		if require > 0 {
-			deploymentLogger.Infof("Need %d more runners for %s", require, reconcile.Deployment)
+			deploymentLogger.Debugf("Need %d more runners for %s", require, reconcile.Deployment)
 			wg.Go(func(ctx context.Context) error {
 				if err := s.deploy(ctx, deployment); err != nil {
 					deploymentLogger.Warnf("Failed to increase deployment replicas: %s", err)
 				} else {
-					deploymentLogger.Infof("Reconciled %s", reconcile.Deployment)
+					deploymentLogger.Debugf("Reconciled %s", reconcile.Deployment)
 				}
 				return nil
 			})
 		} else if require < 0 {
-			deploymentLogger.Infof("Need %d less runners for %s", -require, reconcile.Deployment)
+			deploymentLogger.Debugf("Need %d less runners for %s", -require, reconcile.Deployment)
 			wg.Go(func(ctx context.Context) error {
 				ok, err := s.terminateRandomRunner(ctx, deployment.Name)
 				if err != nil {
 					deploymentLogger.Warnf("Failed to terminate runner: %s", err)
 				} else if ok {
-					deploymentLogger.Infof("Reconciled %s", reconcile.Deployment)
+					deploymentLogger.Debugf("Reconciled %s", reconcile.Deployment)
 				} else {
 					deploymentLogger.Warnf("Failed to terminate runner: no runners found")
 				}
@@ -1007,7 +1007,7 @@ func (s *Service) watchModuleChanges(ctx context.Context, sendChange func(respon
 	for _, deployment := range seedDeployments {
 		deploymentChanges <- dal.DeploymentNotification{Message: optional.Some(deployment)}
 	}
-	logger.Infof("Seeded %d deployments", initialCount)
+	logger.Debugf("Seeded %d deployments", initialCount)
 
 	builtins := schema.Builtins().ToProto().(*schemapb.Module) //nolint:forcetypeassert
 	buildinsResponse := &ftlv1.PullSchemaResponse{
@@ -1203,7 +1203,7 @@ func runWithRetries(ctx context.Context, success, failure time.Duration, fn func
 			}
 		} else {
 			if failed {
-				logger.Infof("Recovered")
+				logger.Debugf("Recovered")
 				failed = false
 			}
 			failureRetry.Reset()
diff --git a/backend/controller/dal/dal.go b/backend/controller/dal/dal.go
index 0de38c43eb..6e33bfc581 100644
--- a/backend/controller/dal/dal.go
+++ b/backend/controller/dal/dal.go
@@ -414,7 +414,7 @@ func (d *DAL) CreateDeployment(ctx context.Context, language string, moduleSchem
 	if err != nil {
 		return "", err
 	} else if existingDeployment != "" {
-		logger.Debugf("Returning existing deployment %s", existingDeployment)
+		logger.Tracef("Returning existing deployment %s", existingDeployment)
 		return existingDeployment, nil
 	}
 
diff --git a/backend/controller/dal/notify.go b/backend/controller/dal/notify.go
index 0e71b56f13..0220344fb5 100644
--- a/backend/controller/dal/notify.go
+++ b/backend/controller/dal/notify.go
@@ -53,7 +53,7 @@ type event struct {
 func (d *DAL) runListener(ctx context.Context, conn *pgx.Conn) {
 	logger := log.FromContext(ctx)
 
-	logger.Infof("Starting DB listener")
+	logger.Debugf("Starting DB listener")
 
 	// Wait for the notification channel to be ready.
 	retry := backoff.Backoff{}
@@ -70,10 +70,10 @@ func (d *DAL) runListener(ctx context.Context, conn *pgx.Conn) {
 	// Main loop for listening to notifications.
 	for {
 		delay := time.Millisecond * 100
-		logger.Debugf("Waiting for notification")
+		logger.Tracef("Waiting for notification")
 		notification, err := waitForNotification(ctx, conn)
 		if err == nil {
-			logger.Debugf("Publishing notification: %s", notification)
+			logger.Tracef("Publishing notification: %s", notification)
 			err = d.publishNotification(ctx, notification, logger)
 		}
 		if err != nil {
@@ -111,7 +111,7 @@ func (d *DAL) publishNotification(ctx context.Context, notification event, logge
 		if err != nil {
 			return err
 		}
-		logger.Debugf("Deployment notification: %s", deployment)
+		logger.Tracef("Deployment notification: %s", deployment)
 		d.DeploymentChanges.Publish(deployment)
 
 	default:
diff --git a/backend/controller/scaling/localscaling/devel.go b/backend/controller/scaling/localscaling/devel.go
index 57fd007ade..9e1d26dcbe 100644
--- a/backend/controller/scaling/localscaling/devel.go
+++ b/backend/controller/scaling/localscaling/devel.go
@@ -16,7 +16,7 @@ var templateDirOnce sync.Once
 
 func templateDir(ctx context.Context) string {
 	templateDirOnce.Do(func() {
-		cmd := exec.Command(ctx, log.Info, internal.FTLSourceRoot(), "bit", "build/template/ftl/jars/ftl-runtime.jar")
+		cmd := exec.Command(ctx, log.Debug, internal.FTLSourceRoot(), "bit", "build/template/ftl/jars/ftl-runtime.jar")
 		err := cmd.Run()
 		if err != nil {
 			panic(err)
diff --git a/backend/controller/scaling/localscaling/local_scaling.go b/backend/controller/scaling/localscaling/local_scaling.go
index eb4388a8be..760ff4d57e 100644
--- a/backend/controller/scaling/localscaling/local_scaling.go
+++ b/backend/controller/scaling/localscaling/local_scaling.go
@@ -71,7 +71,7 @@ func (l *LocalScaling) SetReplicas(ctx context.Context, replicas int, idleRunner
 		return nil
 	}
 
-	logger.Infof("Adding %d replicas", replicasToAdd)
+	logger.Debugf("Adding %d replicas", replicasToAdd)
 	for i := 0; i < replicasToAdd; i++ {
 		i := i
 
@@ -105,7 +105,7 @@ func (l *LocalScaling) SetReplicas(ctx context.Context, replicas int, idleRunner
 		l.runners[config.Key] = cancel
 
 		go func() {
-			logger.Infof("Starting runner: %s", config.Key)
+			logger.Debugf("Starting runner: %s", config.Key)
 			err := runner.Start(runnerCtx, config)
 			if err != nil && !errors.Is(err, context.Canceled) {
 				logger.Errorf(err, "Runner failed: %s", err)
@@ -118,7 +118,7 @@ func (l *LocalScaling) SetReplicas(ctx context.Context, replicas int, idleRunner
 
 func (l *LocalScaling) remove(ctx context.Context, runner model.RunnerKey) error {
 	log := log.FromContext(ctx)
-	log.Infof("Removing runner: %s", runner)
+	log.Debugf("Removing runner: %s", runner)
 
 	cancel, ok := l.runners[runner]
 	if !ok {
diff --git a/backend/controller/scheduledtask/scheduledtask_test.go b/backend/controller/scheduledtask/scheduledtask_test.go
index cc5b669ace..cfcbe6d610 100644
--- a/backend/controller/scheduledtask/scheduledtask_test.go
+++ b/backend/controller/scheduledtask/scheduledtask_test.go
@@ -19,7 +19,7 @@ import (
 
 func TestCron(t *testing.T) {
 	t.Parallel()
-	ctx := log.ContextWithLogger(context.Background(), log.Configure(os.Stderr, log.Config{Level: log.Info}))
+	ctx := log.ContextWithLogger(context.Background(), log.Configure(os.Stderr, log.Config{Level: log.Debug}))
 	ctx, cancel := context.WithCancel(ctx)
 	t.Cleanup(cancel)
 
diff --git a/backend/runner/runner.go b/backend/runner/runner.go
index 72d1a3a739..6d48ad5311 100644
--- a/backend/runner/runner.go
+++ b/backend/runner/runner.go
@@ -61,14 +61,14 @@ func Start(ctx context.Context, config Config) error {
 	ctx = rpc.ContextWithClient(ctx, client)
 
 	logger := log.FromContext(ctx).Attrs(map[string]string{"runner": config.Key.String()})
-	logger.Infof("Starting FTL Runner")
-	logger.Infof("Deployment directory: %s", config.DeploymentDir)
+	logger.Debugf("Starting FTL Runner")
+	logger.Debugf("Deployment directory: %s", config.DeploymentDir)
 	err = os.MkdirAll(config.DeploymentDir, 0700)
 	if err != nil {
 		return fmt.Errorf("%s: %w", "failed to create deployment directory", err)
 	}
-	logger.Infof("Using FTL endpoint: %s", config.ControllerEndpoint)
-	logger.Infof("Listening on %s", config.Bind)
+	logger.Debugf("Using FTL endpoint: %s", config.ControllerEndpoint)
+	logger.Debugf("Listening on %s", config.Bind)
 
 	controllerClient := rpc.Dial(ftlv1connect.NewControllerServiceClient, config.ControllerEndpoint.String(), log.Error)
 
@@ -211,7 +211,7 @@ func (s *Service) Deploy(ctx context.Context, req *connect.Request[ftlv1.DeployR
 	verbCtx := log.ContextWithLogger(ctx, deploymentLogger.Attrs(map[string]string{"module": module.Name}))
 	deployment, cmdCtx, err := plugin.Spawn(
 		unstoppable.Context(verbCtx),
-		log.Info,
+		log.FromContext(ctx).GetLevel(),
 		gdResp.Msg.Schema.Name,
 		deploymentDir,
 		"./main",
diff --git a/cmd/ftl/cmd_build.go b/cmd/ftl/cmd_build.go
index 10c1b7d179..e139650c9e 100644
--- a/cmd/ftl/cmd_build.go
+++ b/cmd/ftl/cmd_build.go
@@ -3,7 +3,9 @@ package main
 import (
 	"context"
 	"fmt"
+	"time"
 
+	"github.com/TBD54566975/ftl/backend/common/log"
 	"github.com/TBD54566975/ftl/backend/common/moduleconfig"
 	"github.com/TBD54566975/ftl/protos/xyz/block/ftl/v1/ftlv1connect"
 )
@@ -13,20 +15,35 @@ type buildCmd struct {
 }
 
 func (b *buildCmd) Run(ctx context.Context, client ftlv1connect.ControllerServiceClient) error {
+	logger := log.FromContext(ctx)
+
+	startTime := time.Now()
 	// Load the TOML file.
+	var err error
 	config, err := moduleconfig.LoadConfig(b.ModuleDir)
 	if err != nil {
 		return err
 	}
 
+	logger.Infof("Building %s module '%s'", config.Language, config.Module)
+
 	switch config.Language {
 	case "kotlin":
-		return b.buildKotlin(ctx, config)
+		err = b.buildKotlin(ctx, config)
 
 	case "go":
-		return b.buildGo(ctx, config, client)
+		err = b.buildGo(ctx, client)
 
 	default:
 		return fmt.Errorf("unable to build, unknown language %q", config.Language)
 	}
+
+	if err != nil {
+		return err
+	}
+
+	duration := time.Since(startTime)
+	formattedDuration := fmt.Sprintf("%.2fs", duration.Seconds())
+	logger.Infof("Successfully built module '%s' in %s", config.Module, formattedDuration)
+	return nil
 }
diff --git a/cmd/ftl/cmd_build_go.go b/cmd/ftl/cmd_build_go.go
index f68e728127..a782a77cf0 100644
--- a/cmd/ftl/cmd_build_go.go
+++ b/cmd/ftl/cmd_build_go.go
@@ -6,17 +6,13 @@ import (
 
 	"connectrpc.com/connect"
 
-	"github.com/TBD54566975/ftl/backend/common/log"
-	"github.com/TBD54566975/ftl/backend/common/moduleconfig"
 	"github.com/TBD54566975/ftl/backend/schema"
 	"github.com/TBD54566975/ftl/go-runtime/compile"
 	ftlv1 "github.com/TBD54566975/ftl/protos/xyz/block/ftl/v1"
 	"github.com/TBD54566975/ftl/protos/xyz/block/ftl/v1/ftlv1connect"
 )
 
-func (b *buildCmd) buildGo(ctx context.Context, config moduleconfig.ModuleConfig, client ftlv1connect.ControllerServiceClient) error {
-	logger := log.FromContext(ctx)
-	logger.Infof("Building Go module '%s'", config.Module)
+func (b *buildCmd) buildGo(ctx context.Context, client ftlv1connect.ControllerServiceClient) error {
 	resp, err := client.GetSchema(ctx, connect.NewRequest(&ftlv1.GetSchemaRequest{}))
 	if err != nil {
 		return err
@@ -28,5 +24,6 @@ func (b *buildCmd) buildGo(ctx context.Context, config moduleconfig.ModuleConfig
 	if err := compile.Build(ctx, b.ModuleDir, sch); err != nil {
 		return fmt.Errorf("failed to build module: %w", err)
 	}
+
 	return nil
 }
diff --git a/cmd/ftl/cmd_build_kotlin.go b/cmd/ftl/cmd_build_kotlin.go
index 4ba700dfd4..db6a85c6c8 100644
--- a/cmd/ftl/cmd_build_kotlin.go
+++ b/cmd/ftl/cmd_build_kotlin.go
@@ -17,16 +17,14 @@ import (
 func (b *buildCmd) buildKotlin(ctx context.Context, config moduleconfig.ModuleConfig) error {
 	logger := log.FromContext(ctx)
 
-	logger.Infof("Building kotlin module '%s'", config.Module)
-
 	if err := setPomProperties(logger, filepath.Join(b.ModuleDir, "..")); err != nil {
 		return fmt.Errorf("unable to update ftl.version in %s: %w", b.ModuleDir, err)
 	}
 
-	logger.Infof("Using build command '%s'", config.Build)
-	err := exec.Command(ctx, logger.GetLevel(), b.ModuleDir, "bash", "-c", config.Build).Run()
+	logger.Debugf("Using build command '%s'", config.Build)
+	err := exec.Command(ctx, log.Debug, b.ModuleDir, "bash", "-c", config.Build).RunBuffered(ctx)
 	if err != nil {
-		return err
+		return fmt.Errorf("failed to build module: %w", err)
 	}
 
 	return nil
@@ -45,7 +43,7 @@ func setPomProperties(logger *log.Logger, baseDir string) error {
 
 	pomFile := filepath.Clean(filepath.Join(baseDir, "pom.xml"))
 
-	logger.Infof("Setting ftl.version in %s to %s", pomFile, ftlVersion)
+	logger.Debugf("Setting ftl.version in %s to %s", pomFile, ftlVersion)
 
 	tree := etree.NewDocument()
 	if err := tree.ReadFromFile(pomFile); err != nil {
diff --git a/cmd/ftl/cmd_deploy.go b/cmd/ftl/cmd_deploy.go
index 1bf083fcf5..f62ec495a7 100644
--- a/cmd/ftl/cmd_deploy.go
+++ b/cmd/ftl/cmd_deploy.go
@@ -34,7 +34,6 @@ func (d *deployCmd) Run(ctx context.Context, client ftlv1connect.ControllerServi
 	if err != nil {
 		return err
 	}
-	logger.Infof("Creating deployment for module %s", config.Module)
 
 	if len(config.Deploy) == 0 {
 		return fmt.Errorf("no deploy paths defined in config")
@@ -46,6 +45,8 @@ func (d *deployCmd) Run(ctx context.Context, client ftlv1connect.ControllerServi
 		return err
 	}
 
+	logger.Infof("Preparing module '%s' for deployment", config.Module)
+
 	deployDir := filepath.Join(d.ModuleDir, config.DeployDir)
 	files, err := findFiles(deployDir, config.Deploy)
 	if err != nil {
@@ -67,22 +68,23 @@ func (d *deployCmd) Run(ctx context.Context, client ftlv1connect.ControllerServi
 		return fmt.Errorf("failed to load protobuf schema from %q: %w", config.Schema, err)
 	}
 
-	logger.Infof("Uploading %d/%d files", len(gadResp.Msg.MissingDigests), len(files))
+	logger.Debugf("Uploading %d/%d files", len(gadResp.Msg.MissingDigests), len(files))
 	for _, missing := range gadResp.Msg.MissingDigests {
 		file := filesByHash[missing]
 		content, err := os.ReadFile(file.localPath)
 		if err != nil {
 			return err
 		}
-		logger.Debugf("Uploading %s", relToCWD(file.localPath))
+		logger.Tracef("Uploading %s", relToCWD(file.localPath))
 		resp, err := client.UploadArtefact(ctx, connect.NewRequest(&ftlv1.UploadArtefactRequest{
 			Content: content,
 		}))
 		if err != nil {
 			return err
 		}
-		logger.Infof("Uploaded %s as %s:%s", relToCWD(file.localPath), sha256.FromBytes(resp.Msg.Digest), file.Path)
+		logger.Debugf("Uploaded %s as %s:%s", relToCWD(file.localPath), sha256.FromBytes(resp.Msg.Digest), file.Path)
 	}
+
 	resp, err := client.CreateDeployment(ctx, connect.NewRequest(&ftlv1.CreateDeploymentRequest{
 		Schema: module,
 		Artefacts: slices.Map(maps.Values(filesByHash), func(a deploymentArtefact) *ftlv1.DeploymentArtefact {
@@ -92,9 +94,14 @@ func (d *deployCmd) Run(ctx context.Context, client ftlv1connect.ControllerServi
 	if err != nil {
 		return err
 	}
-	logger.Infof("Created deployment %s", resp.Msg.DeploymentName)
+
 	_, err = client.ReplaceDeploy(ctx, connect.NewRequest(&ftlv1.ReplaceDeployRequest{DeploymentName: resp.Msg.GetDeploymentName(), MinReplicas: d.Replicas}))
-	return err
+	if err != nil {
+		return err
+	}
+
+	logger.Infof("Successfully created deployment %s", resp.Msg.DeploymentName)
+	return nil
 }
 
 func (d *deployCmd) loadProtoSchema(deployDir string, config moduleconfig.ModuleConfig) (*schemapb.Module, error) {
diff --git a/cmd/ftl/cmd_dev.go b/cmd/ftl/cmd_dev.go
index 45dae3b151..fd7756d004 100644
--- a/cmd/ftl/cmd_dev.go
+++ b/cmd/ftl/cmd_dev.go
@@ -98,7 +98,7 @@ func (m *moduleMap) RebuildDependentModules(ctx context.Context, sch *schema.Mod
 
 func (d *devCmd) Run(ctx context.Context, client ftlv1connect.ControllerServiceClient) error {
 	logger := log.FromContext(ctx)
-	logger.Infof("Watching %s for FTL modules", d.BaseDir)
+	logger.Debugf("Watching %s for FTL modules", d.BaseDir)
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
 
@@ -112,7 +112,7 @@ func (d *devCmd) Run(ctx context.Context, client ftlv1connect.ControllerServiceC
 	})
 
 	for {
-		logger.Debugf("Scanning %s for FTL module changes", d.BaseDir)
+		logger.Tracef("Scanning %s for FTL module changes", d.BaseDir)
 		delay := d.Watch
 
 		tomls, err := d.getTomls(ctx)
diff --git a/cmd/ftl/cmd_init.go b/cmd/ftl/cmd_init.go
index 696dcafdbd..1d4d4f0c89 100644
--- a/cmd/ftl/cmd_init.go
+++ b/cmd/ftl/cmd_init.go
@@ -43,15 +43,16 @@ func (i initGoCmd) Run(ctx context.Context, parent *initCmd) error {
 		return fmt.Errorf("module name %q is invalid", i.Name)
 	}
 	logger := log.FromContext(ctx)
-	logger.Infof("Initializing FTL Go module %s in %s", i.Name, i.Dir)
+	logger.Debugf("Initializing FTL Go module %s in %s", i.Name, i.Dir)
 	if err := scaffold(parent.Hermit, goruntime.Files(), i.Dir, i, scaffolder.Exclude("^go.mod$")); err != nil {
 		return err
 	}
 	if err := updateGitIgnore(ctx, i.Dir); err != nil {
 		return err
 	}
-	logger.Infof("Running go mod tidy")
-	return exec.Command(ctx, log.Debug, filepath.Join(i.Dir, i.Name), "go", "mod", "tidy").Run()
+	logger.Debugf("Running go mod tidy")
+
+	return exec.Command(ctx, log.Debug, filepath.Join(i.Dir, i.Name), "go", "mod", "tidy").RunBuffered(ctx)
 }
 
 type initKotlinCmd struct {
diff --git a/cmd/ftl/cmd_schema_generate.go b/cmd/ftl/cmd_schema_generate.go
index 3f9077b413..7186ba1d62 100644
--- a/cmd/ftl/cmd_schema_generate.go
+++ b/cmd/ftl/cmd_schema_generate.go
@@ -66,7 +66,7 @@ func (s *schemaGenerateCmd) hotReload(ctx context.Context, client ftlv1connect.C
 	}
 
 	logger := log.FromContext(ctx)
-	logger.Infof("Watching %s", s.Template)
+	logger.Debugf("Watching %s", s.Template)
 
 	if err := watch.AddRecursive(s.Template); err != nil {
 		return err
@@ -109,7 +109,7 @@ func (s *schemaGenerateCmd) hotReload(ctx context.Context, client ftlv1connect.C
 			}
 
 			stream.Close()
-			logger.Infof("Stream disconnected, attempting to reconnect...")
+			logger.Debugf("Stream disconnected, attempting to reconnect...")
 			time.Sleep(s.ReconnectDelay)
 		}
 	})
@@ -123,7 +123,7 @@ func (s *schemaGenerateCmd) hotReload(ctx context.Context, client ftlv1connect.C
 			return wg.Wait()
 
 		case event := <-watch.Event:
-			logger.Infof("Template changed (%s), regenerating modules", event.Path)
+			logger.Debugf("Template changed (%s), regenerating modules", event.Path)
 			if err := s.regenerateModules(logger, previousModules); err != nil {
 				return err
 			}
@@ -150,14 +150,14 @@ func (s *schemaGenerateCmd) regenerateModules(logger *log.Logger, modules []*sch
 			return err
 		}
 	}
-	logger.Infof("Generated %d modules in %s", len(modules), s.Dest)
+	logger.Debugf("Generated %d modules in %s", len(modules), s.Dest)
 	return nil
 }
 
 func makeJSLoggerAdapter(logger *log.Logger) func(args ...any) {
 	return func(args ...any) {
 		strs := slices.Map(args, func(v any) string { return fmt.Sprintf("%v", v) })
-		level := log.Info
+		level := log.Debug
 		if prefix, ok := args[0].(string); ok {
 			switch prefix {
 			case "log:":
diff --git a/cmd/ftl/cmd_schema_import.go b/cmd/ftl/cmd_schema_import.go
index 842d795711..d2fdc66139 100644
--- a/cmd/ftl/cmd_schema_import.go
+++ b/cmd/ftl/cmd_schema_import.go
@@ -108,7 +108,7 @@ func (i *importKotlinCmd) Run(ctx context.Context, parent *schemaImportCmd) erro
 func query(ctx context.Context, prompt string) error {
 	logger := log.FromContext(ctx)
 
-	logger.Infof("The import schema command relies on the %s AI chat model to translate schemas from other "+
+	logger.Debugf("The import schema command relies on the %s AI chat model to translate schemas from other "+
 		"languages into FTL compliant objects in the specified language. Output may vary and results should be inspected "+
 		"for correctness. It is suggested that if the results are not satisfactory, you try again.\n\n", ollamaModel)
 
@@ -145,7 +145,7 @@ func (s *schemaImportCmd) setup(ctx context.Context) error {
 	port := fmt.Sprintf("%d", s.OllamaPort)
 
 	if len(output) == 0 {
-		logger.Infof("Creating docker container '%s' for ollama", ollamaContainerName)
+		logger.Debugf("Creating docker container '%s' for ollama", ollamaContainerName)
 
 		// check if port s.OllamaPort is already in use
 		l, err := net.Listen("tcp", fmt.Sprintf("127.0.0.1:%d", s.OllamaPort))
@@ -154,13 +154,12 @@ func (s *schemaImportCmd) setup(ctx context.Context) error {
 		}
 		_ = l.Close()
 
-		err = exec.Command(ctx, logger.GetLevel(), "./", "docker", "run",
+		err = exec.Command(ctx, log.Debug, "./", "docker", "run",
 			"-d", // run detached so we can follow with other commands
 			"-v", ollamaVolume,
 			"-p", fmt.Sprintf("%s:11434", port),
 			"--name", ollamaContainerName,
-			"ollama/ollama",
-		).Run()
+			"ollama/ollama").RunBuffered(ctx)
 		if err != nil {
 			return err
 		}
@@ -173,11 +172,10 @@ func (s *schemaImportCmd) setup(ctx context.Context) error {
 	}
 
 	// Initialize Ollama
-	err = exec.Command(ctx, logger.GetLevel(), "./", "docker", "exec",
+	err = exec.Command(ctx, log.Debug, "./", "docker", "exec",
 		ollamaContainerName,
 		"ollama",
-		"run", ollamaModel,
-	).Run()
+		"run", ollamaModel).RunBuffered(ctx)
 	if err != nil {
 		return err
 	}
diff --git a/cmd/ftl/cmd_serve.go b/cmd/ftl/cmd_serve.go
index c103161684..09bdb46563 100644
--- a/cmd/ftl/cmd_serve.go
+++ b/cmd/ftl/cmd_serve.go
@@ -34,14 +34,13 @@ const ftlContainerName = "ftl-db-1"
 
 func (s *serveCmd) Run(ctx context.Context) error {
 	logger := log.FromContext(ctx)
+	logger.Infof("Starting FTL with %d controller(s) and %d runner(s)", s.Controllers, s.Runners)
 
 	dsn, err := s.setupDB(ctx)
 	if err != nil {
 		return err
 	}
 
-	logger.Infof("Starting %d controller(s) and %d runner(s)", s.Controllers, s.Runners)
-
 	wg, ctx := errgroup.WithContext(ctx)
 
 	bindAllocator, err := bind.NewBindAllocator(s.Bind)
@@ -106,7 +105,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 	port := strconv.Itoa(s.DBPort)
 
 	if len(output) == 0 {
-		logger.Infof("Creating docker container '%s' for postgres db", ftlContainerName)
+		logger.Debugf("Creating docker container '%s' for postgres db", ftlContainerName)
 
 		// check if port s.DBPort is already in use
 		_, err := exec.Capture(ctx, ".", "sh", "-c", fmt.Sprintf("lsof -i:%d", s.DBPort))
@@ -114,7 +113,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 			return "", fmt.Errorf("port %d is already in use", s.DBPort)
 		}
 
-		err = exec.Command(ctx, logger.GetLevel(), "./", "docker", "run",
+		err = exec.Command(ctx, log.Debug, "./", "docker", "run",
 			"-d", // run detached so we can follow with other commands
 			"--name", ftlContainerName,
 			"--user", "postgres",
@@ -127,8 +126,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 			"--health-retries=60",
 			"--health-start-period=80s",
 			"postgres:latest", "postgres",
-		).Run()
-
+		).RunBuffered(ctx)
 		if err != nil {
 			return "", err
 		}
@@ -154,7 +152,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 			return port
 		})
 
-		logger.Infof("Reusing existing docker container %q on port %q for postgres db", ftlContainerName, port)
+		logger.Debugf("Reusing existing docker container %q on port %q for postgres db", ftlContainerName, port)
 	}
 
 	err = pollContainerHealth(ctx, ftlContainerName, 10*time.Second)
@@ -163,7 +161,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 	}
 
 	dsn := fmt.Sprintf("postgres://postgres:secret@localhost:%s/ftl?sslmode=disable", port)
-	logger.Infof("Postgres DSN: %s", dsn)
+	logger.Debugf("Postgres DSN: %s", dsn)
 
 	_, err = databasetesting.CreateForDevel(ctx, dsn, recreate)
 	if err != nil {
@@ -175,7 +173,7 @@ func (s *serveCmd) setupDB(ctx context.Context) (string, error) {
 
 func pollContainerHealth(ctx context.Context, containerName string, timeout time.Duration) error {
 	logger := log.FromContext(ctx)
-	logger.Infof("Waiting for %s to be healthy", containerName)
+	logger.Debugf("Waiting for %s to be healthy", containerName)
 
 	pollCtx, cancel := context.WithTimeout(ctx, timeout)
 	defer cancel()
diff --git a/cmd/ftl/main.go b/cmd/ftl/main.go
index dcad232c8e..8bae37f0f3 100644
--- a/cmd/ftl/main.go
+++ b/cmd/ftl/main.go
@@ -78,7 +78,7 @@ func main() {
 	signal.Notify(sigch, syscall.SIGINT, syscall.SIGTERM)
 	go func() {
 		sig := <-sigch
-		logger.Infof("FTL terminating with signal %s", sig)
+		logger.Debugf("FTL terminating with signal %s", sig)
 		cancel()
 		_ = syscall.Kill(-syscall.Getpid(), sig.(syscall.Signal)) //nolint:forcetypeassert
 		os.Exit(0)
diff --git a/frontend/local.go b/frontend/local.go
index fcfd844c94..e4b7f16741 100644
--- a/frontend/local.go
+++ b/frontend/local.go
@@ -19,9 +19,9 @@ var proxy = httputil.NewSingleHostReverseProxy(consoleURL)
 
 func Server(ctx context.Context, timestamp time.Time, allowOrigin *url.URL) (http.Handler, error) {
 	logger := log.FromContext(ctx)
-	logger.Infof("Building console...")
+	logger.Debugf("Building console...")
 
-	err := exec.Command(ctx, log.Debug, "frontend", "npm", "install").Run()
+	err := exec.Command(ctx, log.Debug, "frontend", "npm", "install").RunBuffered(ctx)
 	if err != nil {
 		return nil, err
 	}
@@ -30,7 +30,7 @@ func Server(ctx context.Context, timestamp time.Time, allowOrigin *url.URL) (htt
 	if err != nil {
 		return nil, err
 	}
-	logger.Infof("Console started")
+	logger.Infof("Web console available at: %s", consoleURL)
 
 	if allowOrigin == nil {
 		return proxy, nil
diff --git a/go-runtime/compile/build.go b/go-runtime/compile/build.go
index e12915adde..05dad42e5d 100644
--- a/go-runtime/compile/build.go
+++ b/go-runtime/compile/build.go
@@ -68,7 +68,7 @@ func Build(ctx context.Context, moduleDir string, sch *schema.Schema) error {
 	// Wipe the modules directory to ensure we don't have any stale modules.
 	_ = os.RemoveAll(filepath.Join(buildDir, "go", "modules"))
 
-	logger.Infof("Generating external modules")
+	logger.Debugf("Generating external modules")
 	if err := internal.ScaffoldZip(externalModuleTemplateFiles(), moduleDir, externalModuleContext{
 		ModuleDir: moduleDir,
 		GoVersion: goModVersion,
@@ -78,12 +78,12 @@ func Build(ctx context.Context, moduleDir string, sch *schema.Schema) error {
 		return err
 	}
 
-	logger.Infof("Tidying go.mod")
-	if err := exec.Command(ctx, log.Debug, moduleDir, "go", "mod", "tidy").Run(); err != nil {
+	logger.Debugf("Tidying go.mod")
+	if err := exec.Command(ctx, log.Debug, moduleDir, "go", "mod", "tidy").RunBuffered(ctx); err != nil {
 		return fmt.Errorf("failed to tidy go.mod: %w", err)
 	}
 
-	logger.Infof("Extracting schema")
+	logger.Debugf("Extracting schema")
 	main, err := ExtractModuleSchema(moduleDir)
 	if err != nil {
 		return fmt.Errorf("failed to extract module schema: %w", err)
@@ -97,7 +97,7 @@ func Build(ctx context.Context, moduleDir string, sch *schema.Schema) error {
 		return fmt.Errorf("failed to write schema: %w", err)
 	}
 
-	logger.Infof("Generating main module")
+	logger.Debugf("Generating main module")
 	if err := internal.ScaffoldZip(buildTemplateFiles(), moduleDir, mainModuleContext{
 		GoVersion: goModVersion,
 		Module:    main,
@@ -105,13 +105,13 @@ func Build(ctx context.Context, moduleDir string, sch *schema.Schema) error {
 		return err
 	}
 
-	logger.Infof("Compiling")
+	logger.Debugf("Compiling")
 	mainDir := filepath.Join(buildDir, "go", "main")
-	if err := exec.Command(ctx, log.Debug, mainDir, "go", "mod", "tidy").Run(); err != nil {
+	if err := exec.Command(ctx, log.Debug, mainDir, "go", "mod", "tidy").RunBuffered(ctx); err != nil {
 		return fmt.Errorf("failed to tidy go.mod: %w", err)
 	}
 
-	return exec.Command(ctx, log.Info, mainDir, "go", "build", "-o", "../../main", ".").Run()
+	return exec.Command(ctx, log.Debug, mainDir, "go", "build", "-o", "../../main", ".").RunBuffered(ctx)
 }
 
 var scaffoldFuncs = scaffolder.FuncMap{
diff --git a/go-runtime/encoding/encoding.go b/go-runtime/encoding/encoding.go
index 401b532599..717509ac33 100644
--- a/go-runtime/encoding/encoding.go
+++ b/go-runtime/encoding/encoding.go
@@ -21,6 +21,7 @@ var (
 func Marshal(v any) ([]byte, error) {
 	w := &bytes.Buffer{}
 	err := encodeValue(reflect.ValueOf(v), w)
+	fmt.Printf("Marshal: %s\n", w.String())
 	return w.Bytes(), err
 }
 
@@ -68,6 +69,7 @@ func encodeValue(v reflect.Value, w *bytes.Buffer) error {
 		return encodeValue(v.Elem(), w)
 
 	case reflect.Slice:
+		fmt.Printf("slice: %s %v\n", v.Type().Elem().Kind(), v)
 		if v.Type().Elem().Kind() == reflect.Uint8 {
 			return encodeBytes(v, w)
 		}
diff --git a/integration/integration_test.go b/integration/integration_test.go
index 10fadb2b37..01c710c565 100644
--- a/integration/integration_test.go
+++ b/integration/integration_test.go
@@ -220,9 +220,9 @@ func runTests(t *testing.T, tmpDir string, tests []test) {
 	// Build FTL binary
 	logger := log.Configure(&logWriter{logger: t}, log.Config{Level: log.Debug})
 	ctx := log.ContextWithLogger(context.Background(), logger)
-	logger.Infof("Building ftl")
+	logger.Debugf("Building ftl")
 	binDir := filepath.Join(rootDir, "build", "release")
-	err = exec.Command(ctx, log.Debug, rootDir, filepath.Join(rootDir, "bin", "bit"), "build/release/ftl", "**/*.jar").Run()
+	err = exec.RunBuffered(ctx, log.Debug, rootDir, filepath.Join(rootDir, "bin", "bit"), "build/release/ftl", "**/*.jar")
 	assert.NoError(t, err)
 
 	controller := rpc.Dial(ftlv1connect.NewControllerServiceClient, "http://localhost:8892", log.Debug)
@@ -525,7 +525,7 @@ func (i itContext) assertWithRetry(t testing.TB, assertion assertion) {
 func startProcess(ctx context.Context, t testing.TB, args ...string) context.Context {
 	t.Helper()
 	ctx, cancel := context.WithCancel(ctx)
-	cmd := exec.Command(ctx, log.Info, "..", args[0], args[1:]...)
+	cmd := exec.Command(ctx, log.Debug, "..", args[0], args[1:]...)
 	err := cmd.Start()
 	assert.NoError(t, err)
 	terminated := make(chan bool)
diff --git a/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/hotswap/FtlHotswapAgentPlugin.kt b/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/hotswap/FtlHotswapAgentPlugin.kt
index 3a1deefabb..bfe9d51a66 100644
--- a/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/hotswap/FtlHotswapAgentPlugin.kt
+++ b/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/hotswap/FtlHotswapAgentPlugin.kt
@@ -13,6 +13,6 @@ object FtlHotswapAgentPlugin {
   @JvmStatic
   @OnClassLoadEvent(classNameRegexp = ".*", events = [LoadEvent.REDEFINE])
   fun loaded(ctClass: CtClass) {
-    logger.info("Reloaded " + ctClass.name)
+    logger.debug("Reloaded " + ctClass.name)
   }
 }
diff --git a/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/registry/Registry.kt b/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/registry/Registry.kt
index 888241a527..f0afc140ec 100644
--- a/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/registry/Registry.kt
+++ b/kotlin-runtime/ftl-runtime/src/main/kotlin/xyz/block/ftl/registry/Registry.kt
@@ -54,7 +54,7 @@ class Registry(val jvmModuleName: String = defaultJvmModuleName) {
 
   /** Register all Verbs in the JVM package by walking the class graph. */
   fun registerAll() {
-    logger.info("Scanning for Verbs in ${jvmModuleName}...")
+    logger.debug("Scanning for Verbs in ${jvmModuleName}...")
     ClassGraph()
       .enableAllInfo() // Scan classes, methods, fields, annotations
       .acceptPackages(jvmModuleName)
@@ -83,7 +83,7 @@ class Registry(val jvmModuleName: String = defaultJvmModuleName) {
       ftlModuleName = moduleName
     }
 
-    logger.info("      @Verb ${function.name}()")
+    logger.debug("      @Verb ${function.name}()")
     val verbRef = VerbRef(module = ftlModuleName!!, name = verbName)
     val verbHandle = VerbHandle(klass, function)
     if (verbs.containsKey(verbRef)) throw IllegalArgumentException("Duplicate Verb $verbRef")