feat: reduce logging levels

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
 }
 

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

backend/common/exec/circularbuffer.go

@@ -0,0 +1,57 @@
+package exec
+
+import (
+	"container/ring"
+	"sync"
+)
+
+type CircularBuffer struct {
+	r    *ring.Ring
+	size int
+	mu   sync.Mutex
+	cap  int // Capacity of the buffer
+}
+
+func NewCircularBuffer(capacity int) *CircularBuffer {
+	return &CircularBuffer{
+		r:   ring.New(capacity),
+		cap: capacity,
+	}
+}
+
+func (cb *CircularBuffer) Write(p []byte) (n int, err error) {
+	cb.mu.Lock()
+	defer cb.mu.Unlock()
+
+	for _, b := range p {
+		// Store each byte in the current ring element
+		cb.r.Value = b
+		// Move to the next element, overwriting if necessary
+		cb.r = cb.r.Next()
+
+		// Keep track of size
+		if cb.size < cb.cap {
+			cb.size++
+		}
+	}
+
+	return len(p), nil
+}
+
+func (cb *CircularBuffer) Bytes() []byte {
+	cb.mu.Lock()
+	defer cb.mu.Unlock()
+
+	buf := make([]byte, cb.size)
+	if cb.size == 0 {
+		return buf
+	}
+
+	start := cb.r.Move(-cb.size)
+	for i := 0; i < cb.size; i++ {
+		buf[i] = start.Value.(byte) //nolint:forcetypeassert
+		start = start.Next()
+	}
+
+	return buf
+}

backend/common/exec/exec.go

@@ -13,6 +13,7 @@ import (
 
 type Cmd struct {
 	*exec.Cmd
+	level log.Level
 }
 
 func LookPath(exe string) (string, error) {
@@ -45,7 +46,22 @@ 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(4096)
+	c.Cmd.Stdout = outputBuffer
+	c.Cmd.Stderr = outputBuffer
+
+	err := c.Run()
+	if err != nil {
+		log.FromContext(ctx).Logf(c.level, string(outputBuffer.Bytes()))
+		return err
+	}
+
+	return nil
 }
 
 // Kill sends a signal to the process group of the command.

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)

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)

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
 }

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 {

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) {
@@ -454,7 +454,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 {
@@ -476,15 +476,15 @@ 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 {
 		if errors.Is(err, dal.ErrNotFound) {
 			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)
@@ -572,7 +572,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
@@ -588,7 +588,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:
@@ -711,7 +711,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
 }
 
@@ -756,7 +756,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
 }
 
@@ -840,31 +840,31 @@ 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,
 			Name:     reconcile.Deployment,
 		}
 		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")
 				}
@@ -1001,7 +1001,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{
@@ -1197,7 +1197,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()

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
 	}