diff --git a/backend/controller/controller.go b/backend/controller/controller.go index b5bf702aa2..c21ab75610 100644 --- a/backend/controller/controller.go +++ b/backend/controller/controller.go @@ -1310,7 +1310,7 @@ func (s *Service) executeAsyncCalls(ctx context.Context) (interval time.Duration call.Release() //nolint:errcheck }() - logger = logger.Scope(fmt.Sprintf("%s:%s", call.Origin, call.Verb)) + logger = logger.Scope(fmt.Sprintf("%s:%s", call.Origin, call.Verb)).Module(call.Verb.Module) if call.Catching { // Retries have been exhausted but catch verb has previously failed @@ -1516,7 +1516,7 @@ func (s *Service) finaliseAsyncCall(ctx context.Context, tx *dal.DAL, call *dal. } func (s *Service) onAsyncFSMCallCompletion(ctx context.Context, tx *dal.DAL, origin async.AsyncOriginFSM, failed bool, isFinalResult bool) error { - logger := log.FromContext(ctx).Scope(origin.FSM.String()) + logger := log.FromContext(ctx).Scope(origin.FSM.String()).Module(origin.FSM.Module) // retrieve the next fsm event and delete it next, err := tx.PopNextFSMEvent(ctx, origin.FSM, origin.Key) diff --git a/backend/controller/cronjobs/cronjobs.go b/backend/controller/cronjobs/cronjobs.go index 46d5e331c8..59a3efc1e2 100644 --- a/backend/controller/cronjobs/cronjobs.go +++ b/backend/controller/cronjobs/cronjobs.go @@ -43,7 +43,7 @@ func NewForTesting(ctx context.Context, key model.ControllerKey, requestSource s } func (s *Service) NewCronJobsForModule(ctx context.Context, module *schemapb.Module) ([]model.CronJob, error) { - logger := log.FromContext(ctx).Scope("cron") + logger := log.FromContext(ctx).Scope("cron").Module(module.Name) start := s.clock.Now().UTC() newJobs := []model.CronJob{} merr := []error{} @@ -149,7 +149,7 @@ func (s *Service) OnJobCompletion(ctx context.Context, key model.CronJobKey, fai // scheduleCronJob schedules the next execution of a single cron job. func (s *Service) scheduleCronJob(ctx context.Context, tx *dal.DAL, job model.CronJob) error { - logger := log.FromContext(ctx).Scope("cron") + logger := log.FromContext(ctx).Scope("cron").Module(job.Verb.Module) now := s.clock.Now().UTC() pending, err := tx.IsCronJobPending(ctx, job.Key, now) if err != nil { diff --git a/backend/controller/ingress/handler.go b/backend/controller/ingress/handler.go index fd8f6ed2a7..bc884f42be 100644 --- a/backend/controller/ingress/handler.go +++ b/backend/controller/ingress/handler.go @@ -50,6 +50,7 @@ func Handle( observability.Ingress.Request(r.Context(), r.Method, r.URL.Path, optional.None[*schemapb.Ref](), startTime, optional.Some("failed to resolve route")) return } + logger = logger.Module(route.Module) verbRef := &schemapb.Ref{Module: route.Module, Name: route.Verb} diff --git a/backend/controller/scaling/k8sscaling/deployment_provisioner.go b/backend/controller/scaling/k8sscaling/deployment_provisioner.go index 10063485d4..32647581cc 100644 --- a/backend/controller/scaling/k8sscaling/deployment_provisioner.go +++ b/backend/controller/scaling/k8sscaling/deployment_provisioner.go @@ -103,6 +103,8 @@ func (r *DeploymentProvisioner) handleSchemaChange(ctx context.Context, msg *ftl return nil } logger := log.FromContext(ctx) + logger = logger.Module(msg.ModuleName) + ctx = log.ContextWithLogger(ctx, logger) logger.Infof("Handling schema change for %s", msg.DeploymentKey) deploymentClient := r.Client.AppsV1().Deployments(r.Namespace) deployment, err := deploymentClient.Get(ctx, msg.DeploymentKey, v1.GetOptions{}) diff --git a/backend/controller/scaling/localscaling/local_scaling.go b/backend/controller/scaling/localscaling/local_scaling.go index 0731d24907..31f45dfbc3 100644 --- a/backend/controller/scaling/localscaling/local_scaling.go +++ b/backend/controller/scaling/localscaling/local_scaling.go @@ -106,7 +106,7 @@ func (l *localScaling) handleSchemaChange(ctx context.Context, msg *ftlv1.PullSc } l.lock.Lock() defer l.lock.Unlock() - logger := log.FromContext(ctx).Scope("localScaling") + logger := log.FromContext(ctx).Scope("localScaling").Module(msg.ModuleName) ctx = log.ContextWithLogger(ctx, logger) logger.Infof("Handling schema change for %s", msg.DeploymentKey) moduleDeployments := l.runners[msg.ModuleName] @@ -192,7 +192,7 @@ func (l *localScaling) startRunner(ctx context.Context, deploymentKey string, in config.HeartbeatPeriod = time.Second config.HeartbeatJitter = time.Millisecond * 100 - runnerCtx := log.ContextWithLogger(ctx, logger.Scope(simpleName)) + runnerCtx := log.ContextWithLogger(ctx, logger.Scope(simpleName).Module(info.module)) runnerCtx, cancel := context.WithCancel(runnerCtx) info.runner = optional.Some(runnerInfo{cancelFunc: cancel, port: bind.Port()}) diff --git a/frontend/cli/cmd_interactive.go b/frontend/cli/cmd_interactive.go index 26358a1f02..ba3e8089ae 100644 --- a/frontend/cli/cmd_interactive.go +++ b/frontend/cli/cmd_interactive.go @@ -15,7 +15,7 @@ type interactiveCmd struct { } func (i *interactiveCmd) Run(ctx context.Context, k *kong.Kong, projectConfig projectconfig.Config, binder terminal.KongContextBinder, cancel context.CancelFunc, client ftlv1connect.ControllerServiceClient) error { - err := terminal.RunInteractiveConsole(ctx, k, projectConfig, binder, nil, cancel, client) + err := terminal.RunInteractiveConsole(ctx, k, projectConfig, binder, cancel, client) if err != nil { return fmt.Errorf("interactive console: %w", err) } diff --git a/internal/buildengine/build.go b/internal/buildengine/build.go index d8bf768e2b..a0c1083f11 100644 --- a/internal/buildengine/build.go +++ b/internal/buildengine/build.go @@ -32,7 +32,7 @@ func buildModule(ctx context.Context, projectRootDir string, sch *schema.Schema, return err } defer release() //nolint:errcheck - logger := log.FromContext(ctx).Scope(module.Config.Module) + logger := log.FromContext(ctx).Module(module.Config.Module).Scope("build") ctx = log.ContextWithLogger(ctx, logger) // clear the deploy directory before extracting schema diff --git a/internal/buildengine/deploy.go b/internal/buildengine/deploy.go index 60e1cbbbd0..d4a33df95c 100644 --- a/internal/buildengine/deploy.go +++ b/internal/buildengine/deploy.go @@ -36,7 +36,7 @@ type DeployClient interface { // Deploy a module to the FTL controller with the given number of replicas. Optionally wait for the deployment to become ready. func Deploy(ctx context.Context, module Module, replicas int32, waitForDeployOnline bool, client DeployClient) error { - logger := log.FromContext(ctx).Scope(module.Config.Module) + logger := log.FromContext(ctx).Module(module.Config.Module).Scope("deploy") ctx = log.ContextWithLogger(ctx, logger) logger.Infof("Deploying module") @@ -107,7 +107,7 @@ func Deploy(ctx context.Context, module Module, replicas int32, waitForDeployOnl } func terminateModuleDeployment(ctx context.Context, client ftlv1connect.ControllerServiceClient, module string) error { - logger := log.FromContext(ctx).Scope(module) + logger := log.FromContext(ctx).Module(module).Scope("terminate") status, err := client.Status(ctx, connect.NewRequest(&ftlv1.StatusRequest{})) if err != nil { diff --git a/internal/buildengine/engine.go b/internal/buildengine/engine.go index d31d55cc75..d164b38f8b 100644 --- a/internal/buildengine/engine.go +++ b/internal/buildengine/engine.go @@ -636,7 +636,7 @@ func (e *Engine) buildWithCallback(ctx context.Context, callback buildCallback, wg.SetLimit(e.parallelism) for _, moduleName := range group { wg.Go(func() error { - logger := log.FromContext(ctx).Scope(moduleName) + logger := log.FromContext(ctx).Module(moduleName).Scope("build") ctx := log.ContextWithLogger(ctx, logger) err := e.tryBuild(ctx, mustBuild, moduleName, builtModules, schemas, callback) if err != nil { diff --git a/internal/log/logger.go b/internal/log/logger.go index 07aac3fe9a..241ce2df07 100644 --- a/internal/log/logger.go +++ b/internal/log/logger.go @@ -15,6 +15,7 @@ import ( var _ Interface = (*Logger)(nil) const scopeKey = "scope" +const moduleKey = "module" type Entry struct { Time time.Time `json:"-"` @@ -46,6 +47,9 @@ func New(level Level, sink Sink) *Logger { func (l Logger) Scope(scope string) *Logger { return l.Attrs(map[string]string{scopeKey: scope}) } +func (l Logger) Module(module string) *Logger { + return l.Attrs(map[string]string{moduleKey: module}) +} // Attrs creates a new logger with the given attributes. func (l Logger) Attrs(attributes map[string]string) *Logger { diff --git a/internal/log/plain.go b/internal/log/plain.go index 607ddeba22..55ad441871 100644 --- a/internal/log/plain.go +++ b/internal/log/plain.go @@ -96,12 +96,24 @@ func (t *plainSink) Log(entry Entry) error { } // Add scope if required + scopeString := "" scope, exists := entry.Attributes[scopeKey] + module, moduleExists := entry.Attributes[moduleKey] + if moduleExists { + if exists && scope != module { + scopeString = module + ":" + scope + } else { + scopeString = module + } + } else if exists { + scopeString = scope + module = scope + } if exists { if t.isaTTY { - prefix += entry.Level.String() + ":" + scopeColour(scope) + scope + "\x1b[0m: " + prefix += entry.Level.String() + ":" + ScopeColor(module) + scopeString + "\x1b[0m: " } else { - prefix += entry.Level.String() + ":" + scope + ": " + prefix += entry.Level.String() + ":" + scopeString + ": " } } else { prefix += entry.Level.String() + ": " @@ -128,7 +140,7 @@ func parseRGB(s string) (int, int, int) { return int(r), int(g), int(b) } -func scopeColour(scope string) string { +func ScopeColor(scope string) string { hash := fnv.New32a() hash.Write([]byte(scope)) colours, _ := scopeColours.Get(context.Background()) //nolint:errcheck diff --git a/internal/terminal/interactive.go b/internal/terminal/interactive.go index a7d93b6094..15bd33973b 100644 --- a/internal/terminal/interactive.go +++ b/internal/terminal/interactive.go @@ -18,22 +18,32 @@ import ( "github.com/TBD54566975/ftl/internal/projectconfig" ) +const interactivePrompt = "\033[32m>\033[0m " + var _ readline.AutoCompleter = &FTLCompletion{} var errExitTrap = errors.New("exit trap") type KongContextBinder func(ctx context.Context, kctx *kong.Context, projectConfig projectconfig.Config, app *kong.Kong, cancel context.CancelFunc) context.Context -func RunInteractiveConsole(ctx context.Context, k *kong.Kong, projectConfig projectconfig.Config, binder KongContextBinder, refreshFunction func(func()), cancelContext context.CancelFunc, client ftlv1connect.ControllerServiceClient) error { +func RunInteractiveConsole(ctx context.Context, k *kong.Kong, projectConfig projectconfig.Config, binder KongContextBinder, cancelContext context.CancelFunc, client ftlv1connect.ControllerServiceClient) error { + l, err := readline.NewEx(&readline.Config{ - Prompt: "\033[32m>\033[0m ", + Prompt: interactivePrompt, InterruptPrompt: "^C", AutoComplete: &FTLCompletion{app: k, ctx: ctx, client: client}, Listener: &ExitListener{cancel: func() { os.Exit(0) }}, }) - if refreshFunction != nil { - refreshFunction(l.Refresh) + sm := FromContext(ctx) + var tsm *terminalStatusManager + ok := false + if tsm, ok = sm.(*terminalStatusManager); ok { + tsm.statusLock.Lock() + tsm.console = true + tsm.consoleRefresh = l.Refresh + tsm.recalculateLines() + tsm.statusLock.Unlock() } if err != nil { return fmt.Errorf("init readline: %w", err) @@ -54,6 +64,9 @@ func RunInteractiveConsole(ctx context.Context, k *kong.Kong, projectConfig proj } else if errors.Is(err, io.EOF) { os.Exit(0) } + if tsm != nil { + tsm.consoleNewline(line) + } line = strings.TrimSpace(line) if line == "" { continue @@ -84,8 +97,6 @@ func RunInteractiveConsole(ctx context.Context, k *kong.Kong, projectConfig proj errorf("error: %s", err) return } - // Force a status refresh - println("") }() } return nil diff --git a/internal/terminal/status.go b/internal/terminal/status.go index 644cb63018..e1ef78a7b2 100644 --- a/internal/terminal/status.go +++ b/internal/terminal/status.go @@ -10,6 +10,7 @@ import ( "strings" "sync" "syscall" + "time" "unicode/utf8" "github.com/alecthomas/atomic" @@ -18,26 +19,30 @@ import ( "golang.org/x/term" "github.com/TBD54566975/ftl/backend/protos/xyz/block/ftl/v1/ftlv1connect" + "github.com/TBD54566975/ftl/internal/log" "github.com/TBD54566975/ftl/internal/projectconfig" ) type BuildState string -const BuildStateWaiting BuildState = "🕗" -const BuildStateBuilding BuildState = "🛠️ " -const BuildStateBuilt BuildState = "📦️️" -const BuildStateDeploying BuildState = "🚀" -const BuildStateDeployed BuildState = "✅" -const BuildStateFailed BuildState = "❌" +const BuildStateWaiting BuildState = "Waiting" +const BuildStateBuilding BuildState = "Building" +const BuildStateBuilt BuildState = "Built" +const BuildStateDeploying BuildState = "Deploying" +const BuildStateDeployed BuildState = "Deployed" +const BuildStateFailed BuildState = "Failed" // moduleStatusPadding is the padding between module status entries -// it accounts for the colon, space and the emoji -const moduleStatusPadding = 10 +// it accounts for the icon, the module name, and the padding between them +const moduleStatusPadding = 5 var _ StatusManager = &terminalStatusManager{} var _ StatusLine = &terminalStatusLine{} var buildColors map[BuildState]string +var buildStateIcon map[BuildState]func(int) string + +var spinner = []string{"▁", "▃", "▄", "▅", "▆", "▇", "█", "▇", "▆", "▅", "▄", "▃"} func init() { buildColors = map[BuildState]string{ @@ -48,6 +53,23 @@ func init() { BuildStateDeployed: "\u001B[92m", BuildStateFailed: "\u001B[91m", } + spin := func(spinnerCount int) string { + return spinner[spinnerCount] + } + block := func(int) string { + return "█" + } + empty := func(int) string { + return "▁" + } + buildStateIcon = map[BuildState]func(int) string{ + BuildStateWaiting: empty, + BuildStateBuilding: spin, + BuildStateBuilt: block, + BuildStateDeploying: spin, + BuildStateDeployed: block, + BuildStateFailed: spin, + } } type StatusManager interface { @@ -78,6 +100,7 @@ type terminalStatusManager struct { exitWait sync.WaitGroup console bool consoleRefresh func() + spinnerCount int } type statusKey struct{} @@ -177,6 +200,34 @@ func NewStatusManager(ctx context.Context) StatusManager { <-ctx.Done() sm.Close() }() + + // Animate the spinners + + go func() { + for !sm.closed.Load() { + time.Sleep(300 * time.Millisecond) + sm.statusLock.Lock() + if sm.spinnerCount == len(spinner)-1 { + sm.spinnerCount = 0 + } else { + sm.spinnerCount++ + } + // only redraw if not stable + stable := true + for _, state := range sm.moduleStates { + if state != BuildStateDeployed && state != BuildStateBuilt { + stable = false + break + } + } + if !stable { + sm.recalculateLines() + } + sm.statusLock.Unlock() + + } + }() + return sm } @@ -222,6 +273,21 @@ func (r *terminalStatusManager) clearStatusMessages() { } } +func (r *terminalStatusManager) consoleNewline(line string) { + r.statusLock.Lock() + defer r.statusLock.Unlock() + count := r.totalStatusLines + for range count { + r.underlyingWrite("\u001B[1A\033[2K") + } + if line == "" { + r.underlyingWrite("\r" + interactivePrompt + line) + r.redrawStatus() + } else { + r.underlyingWrite("\r" + interactivePrompt + line + strings.Repeat("\n", r.totalStatusLines)) + } +} + func (r *terminalStatusManager) IntoContext(ctx context.Context) context.Context { return context.WithValue(ctx, statusKeyInstance, r) } @@ -292,7 +358,7 @@ func (r *terminalStatusManager) writeLine(s string) { defer r.statusLock.RUnlock() if r.totalStatusLines == 0 { - r.underlyingWrite("\n" + s) + r.underlyingWrite("\n---" + fmt.Sprintf("%v", r.console) + s) return } r.clearStatusMessages() @@ -345,9 +411,9 @@ func (r *terminalStatusManager) recalculateLines() { multiLine = true total++ } - pad := strings.Repeat(" ", entryLength-len(k)-moduleStatusPadding+2) + pad := strings.Repeat(" ", entryLength-len(k)-moduleStatusPadding) state := r.moduleStates[k] - msg += pad + buildColors[state] + k + ": " + string(state) + "\u001B[39m" + msg += buildColors[state] + buildStateIcon[state](r.spinnerCount) + "[" + log.ScopeColor(k) + k + buildColors[state] + "] \u001B[39m" + pad } if !multiLine { // For multi-line messages we don't want to trim the message as we want to line up the columns @@ -425,22 +491,13 @@ func (r *terminalStatusLine) SetMessage(message string) { func LaunchEmbeddedConsole(ctx context.Context, k *kong.Kong, projectConfig projectconfig.Config, binder KongContextBinder, cancel context.CancelFunc, client ftlv1connect.ControllerServiceClient) { sm := FromContext(ctx) - if tsm, ok := sm.(*terminalStatusManager); ok { - tsm.console = true + if _, ok := sm.(*terminalStatusManager); ok { go func() { - - err := RunInteractiveConsole(ctx, k, projectConfig, binder, func(f func()) { - tsm.statusLock.Lock() - defer tsm.statusLock.Unlock() - tsm.consoleRefresh = f - }, cancel, client) + err := RunInteractiveConsole(ctx, k, projectConfig, binder, cancel, client) if err != nil { fmt.Printf("\033[31mError: %s\033[0m\n", err) return } }() - tsm.statusLock.Lock() - defer tsm.statusLock.Unlock() - tsm.recalculateLines() } }