Skip to content

Commit

Permalink
feat: reduce logging levels
Browse files Browse the repository at this point in the history
  • Loading branch information
wesbillman committed Feb 6, 2024
1 parent 908cfcb commit c76923e
Show file tree
Hide file tree
Showing 31 changed files with 270 additions and 116 deletions.
20 changes: 10 additions & 10 deletions authn/authn.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
Expand All @@ -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 {
Expand All @@ -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
}
Expand Down Expand Up @@ -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)
Expand All @@ -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
}

Expand Down
4 changes: 2 additions & 2 deletions backend/common/download/download.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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()
}
118 changes: 118 additions & 0 deletions backend/common/exec/circularbuffer.go
Original file line number Diff line number Diff line change
@@ -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()
}
20 changes: 19 additions & 1 deletion backend/common/exec/exec.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package exec

import (
"context"
"fmt"
"os"
"os/exec"
"syscall"
Expand All @@ -13,6 +14,7 @@ import (

type Cmd struct {
*exec.Cmd
level log.Level
}

func LookPath(exe string) (string, error) {
Expand Down Expand Up @@ -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.
Expand Down
2 changes: 1 addition & 1 deletion backend/common/observability/client.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
4 changes: 2 additions & 2 deletions backend/common/plugin/serve.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
6 changes: 3 additions & 3 deletions backend/common/plugin/spawn.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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.")
}
Expand Down Expand Up @@ -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
}
2 changes: 1 addition & 1 deletion backend/common/rpc/rpc.go
Original file line number Diff line number Diff line change
Expand Up @@ -154,7 +154,7 @@ func RetryStreamingClientStream[Req, Resp any](
break
}
if errored {
logger.Infof("Stream recovered")
logger.Debugf("Stream recovered")
errored = false
}
select {
Expand Down
Loading

0 comments on commit c76923e

Please sign in to comment.