feat: reduce logging levels (#877)

Fixes #869 

Reduce log levels for `Info` and `Debug`
`Debug -> Trace`
`Info -> Debug`

Also adds a `RunBuffered` to `exec` to allow `Command`s to be run and
the output buffered to a circular buffer. The output is printed out at
the current log level if an error occurs. The result is a quiet terminal
when things go well and context output when things fail.

Some examples:
```
ftl serve --recreate --allow-origins "*"
info: Starting FTL with 1 controller(s) and 0 runner(s)
info:controller0: Web console available at: http://localhost:5173
```

```
ftl build examples/kotlin/ftl-module-api
info: Building kotlin module 'api'
info: Successfully built module 'api' in 7.26s
```

```
ftl deploy examples/go/httpingress
info: Building go module 'httpingress'
info: Successfully built module 'httpingress' in 3.99s
info: Preparing module 'httpingress' for deployment
info: Successfully created deployment httpingress-5792064876
```

```
ftl dev examples/kotlin
info: Building kotlin module 'api'
info: Successfully built module 'api' in 8.85s
info: Preparing module 'api' for deployment
info: Successfully created deployment api-5837eca0af
info: Building kotlin module 'echo'
info: Successfully built module 'echo' in 6.95s
info: Preparing module 'echo' for deployment
info: Successfully created deployment echo-31ad4e0677
info: Building kotlin module 'ad'
info: Successfully built module 'ad' in 7.63s
info: Preparing module 'ad' for deployment
info: Successfully created deployment ad-e75c5b489a
```

And some error examples:
```
ftl dev examples/kotlin/ftl-module-echo
info: Building kotlin module 'echo'
info: r
[INFO]
[INFO] --- exec:3.0.0:exec (default) @ ftl-module-echo ---
Generated module: /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/target/generated-sources/ftl/builtin/BuiltinModuleClient.kt
[INFO]
[INFO] --- build-helper:3.2.0:add-source (default) @ ftl-module-echo ---
[INFO] Source directory: /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/target/generated-sources/ftl added.
[INFO]
[INFO] --- resources:3.3.1:resources (default-resources) @ ftl-module-echo ---
[WARNING] Using platform encoding (UTF-8 actually) to copy filtered resources, i.e. build is platform dependent!
[INFO] skip non existing resourceDirectory /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/resources
[INFO]
[INFO] --- compiler:3.11.0:compile (default-compile) @ ftl-module-echo ---
[INFO] Nothing to compile - all classes are up to date
[INFO]
[INFO] --- kotlin:1.9.0:compile (compile) @ ftl-module-echo ---
[WARNING] Source root doesn't exist: /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/java
[WARNING] Using experimental Kotlin incremental compilation
[INFO] Non-incremental compilation will be performed: NO_BUILD_HISTORY
[INFO] Kotlin compile iteration: /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt, /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/target/generated-sources/ftl/builtin/BuiltinModuleClient.kt
[INFO] Exit code: COMPILATION_ERROR
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (3, 12) Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (4, 12) Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (20, 28) Not enough information to infer type variable R
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (20, 33) Unresolved reference: TimeModuleClient
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (20, 51) Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt: (20, 57) Unresolved reference: TimeRequest
[INFO] Compiled 2 Kotlin files using incremental compiler
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  3.369 s
[INFO] Finished at: 2024-02-05T11:59:18-07:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.jetbrains.kotlin:kotlin-maven-plugin:1.9.0:compile (compile) on project ftl-module-echo: Compilation failure: Compilation failure:
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[3,12] Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[4,12] Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[20,28] Not enough information to infer type variable R
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[20,33] Unresolved reference: TimeModuleClient
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[20,51] Unresolved reference: time
[ERROR] /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo/src/main/kotlin/ftl/echo/Echo.kt:[20,57] Unresolved reference: TimeRequest
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException

error: Error deploying module /Users/wesbillman/dev/ftl/examples/kotlin/ftl-module-echo. Will retry: failed to build module: exit status 1
info: Building kotlin module 'echo'
```

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

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.

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 {