`ftl dev` controller failed to start randomly errors

[wesbillman]

ftl dev --recreate info: Starting FTL with 1 controller(s) info:controller0: Web console available at: http://localhost:8892 info:controller0: HTTP ingress server listening on: http://localhost:8891 error: Timeout reached while polling for controller status: context deadline exceeded ftl: error: controller failed to start: context deadline exceeded

[alecthomas]

I think this might be the same issue that @matt2e is working on, though it does look slightly different

[matt2e]

From slack DMs: this is on examples/go so no secrets

debug logs would be helpful to see if theres any errors

[worstell]

maybe related? https://github.com/TBD54566975/ftl/issues/1956

[alecthomas]

Also probably #1973

[gak]

This looks like a different issue to #1973 where that one is related to only happening when not running in the root. This one looks like a timeout waiting for npm to build. Investigating.

[gak]

The timeout was set to 10s for the controller to run, and adding this code shows it's running over:

    // Wait for controller to start, then run startup commands.
    start := time.Now()
    if err := waitForControllerOnline(ctx, time.Second*30, client); err != nil {
        return fmt.Errorf("controller failed to start: %w", err)
    }
    logger.Infof("Controller started in %s", time.Since(start))

10:55:40 info: Controller started in 12.017002542s

[gak]

@wesbillman was this crashing at ~10s? Maybe this is another issue too otherwise!

[gak]

Also just to clarify, need to clean out build cache to reproduce:

ftl🐚 ➜  ftl git:(gak/controller-timeout) ✗ ftl dev --log-level=info --log-timestamps --recreate examples/go
11:00:28 info: Starting FTL with 1 controller(s)
11:00:29 info:controller0: Web console available at: http://localhost:8892
11:00:29 info:controller0: HTTP ingress server listening on: http://localhost:8891
11:00:29 info: Controller started in 1.009589583s <-----
11:00:29 info: FTL startup command ⚡️
11:00:31 info:time: Building module
11:00:33 info:time: Deploying module
11:00:33 info:echo: Building module
^C%

ftl🐚 ➜  ftl git:(gak/controller-timeout) ✗ git clean -fdx frontend
Removing frontend/dist/
Removing frontend/node_modules/
ftl🐚 ➜  ftl git:(gak/controller-timeout) ✗ ftl dev --log-level=info --log-timestamps --recreate examples/go
11:00:46 info: Starting FTL with 1 controller(s)
11:01:04 info:controller0: Web console available at: http://localhost:8892
11:01:04 info:controller0: HTTP ingress server listening on: http://localhost:8891
11:01:04 info: Controller started in 17.0101555s <-----
11:01:04 info: FTL startup command ⚡️
11:01:05 info:time: Building module
11:01:08 info:time: Deploying module
11:01:08 info:echo: Building module
11:01:11 info:controller0: Deployed dpl-time-454e7hqfb53hl8n
11:01:11 info:echo: Deploying module
11:01:13 info:controller0: Deployed dpl-echo-13eom47qcx7835km
11:01:13 info: All modules deployed, watching for changes...

[gak]

Optimistically closing :)