sst dev - zombie node processes #317
Comments
|
do you know what command the node servers were running? was it related to pulumi |
|
Doesn't look like it to me: While dev running: After dev exits: Verbose logs (a different run)
time=2024-04-28T15:13:05.990-07:00 level=INFO msg="checking for pulumi" path="/Users/quinn/Library/Application Support/sst/bin/pulumi"
time=2024-04-28T15:13:06.201-07:00 level=INFO msg="checking for bun" path="/Users/quinn/Library/Application Support/sst/bin/bun"
time=2024-04-28T15:13:06.216-07:00 level=INFO msg=args args=[] length=0
time=2024-04-28T15:13:06.217-07:00 level=INFO msg="no existing server found, starting new one"
time=2024-04-28T15:13:06.217-07:00 level=INFO msg="waiting for server to start"
time=2024-04-28T15:13:06.231-07:00 level=INFO msg="checking for pulumi" path="/Users/quinn/Library/Application Support/sst/bin/pulumi"
time=2024-04-28T15:13:06.339-07:00 level=INFO msg="checking for bun" path="/Users/quinn/Library/Application Support/sst/bin/bun"
time=2024-04-28T15:13:06.344-07:00 level=INFO msg="initializing project" version=0.0.326
time=2024-04-28T15:13:06.344-07:00 level=INFO msg="esbuild building"
time=2024-04-28T15:13:06.351-07:00 level=INFO msg="esbuild built" outfile=/Users/quinn/Code/sst-ion-zombies-repro/.sst/eval/eval-1714342386344.mjs
time=2024-04-28T15:13:06.351-07:00 level=INFO msg="evaluating config"
time=2024-04-28T15:13:06.386-07:00 level=INFO msg="config evaluated"
time=2024-04-28T15:13:06.387-07:00 level=INFO msg="checking platform"
time=2024-04-28T15:13:06.653-07:00 level=INFO msg="credentials found"
time=2024-04-28T15:13:06.653-07:00 level=INFO msg="fetching bootstrap"
time=2024-04-28T15:13:06.748-07:00 level=INFO msg="found existing bootstrap" data="{\"version\":1,\"asset\":\"sst-asset-khumcfbtafmx\",\"state\":\"sst-state-khumcfbtafmx\"}"
time=2024-04-28T15:13:06.748-07:00 level=INFO msg="loaded config" app=sst-ion-zombies-repro stage=quinn
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=server addr=0.0.0.0:13557
time=2024-04-28T15:13:06.750-07:00 level=INFO msg="getting endpoint"
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=subscribed type=*aws.FunctionInvokedEvent
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=subscribed type=*aws.FunctionResponseEvent
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=subscribed type=*aws.FunctionErrorEvent
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=subscribed type=*aws.FunctionLogEvent
time=2024-04-28T15:13:06.750-07:00 level=INFO msg=subscribed type=*project.StackEvent
time=2024-04-28T15:13:06.926-07:00 level=INFO msg="found endpoint endpoint" url="wss://a3hbsstknw054l.iot.us-west-2.amazonaws.com/mqtt?X-Amz-Expires=86400"
time=2024-04-28T15:13:06.926-07:00 level=INFO msg="signed request" url="wss://a3hbsstknw054l.iot.us-west-2.amazonaws.com/mqtt?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=ASIA3FLD3QJW7XXKRKHA%2F20240428%2Fus-west-2%2Fiotdevicegateway%2Faws4_request&X-Amz-Date=20240428T221306Z&X-Amz-Expires=86400&X-Amz-SignedHeaders=host&X-Amz-Signature=17d4852bccd894b90307a133aed723c86e1eafedb56f9ef30baa887aea8aa759"
time=2024-04-28T15:13:07.063-07:00 level=INFO msg="mqtt connected"
time=2024-04-28T15:13:07.121-07:00 level=INFO msg=subscribed type=*project.StackEvent
time=2024-04-28T15:13:07.121-07:00 level=INFO msg=subscribed type=*watcher.FileChangedEvent
time=2024-04-28T15:13:07.222-07:00 level=INFO msg="connected to iot"
time=2024-04-28T15:13:07.225-07:00 level=INFO msg=watching path=/Users/quinn/Code/sst-ion-zombies-repro
time=2024-04-28T15:13:07.225-07:00 level=INFO msg=watching path=/Users/quinn/Code/sst-ion-zombies-repro/src
time=2024-04-28T15:13:07.226-07:00 level=INFO msg=subscribed type=*watcher.FileChangedEvent
time=2024-04-28T15:13:07.226-07:00 level=INFO msg=subscribed type=*server.DeployRequestedEvent
time=2024-04-28T15:13:07.226-07:00 level=INFO msg=subscribed type=*project.StackEvent
time=2024-04-28T15:13:07.226-07:00 level=INFO msg="running stack command" cmd=up
time=2024-04-28T15:13:07.226-07:00 level=INFO msg=publishing type=*project.StackEvent
time=2024-04-28T15:13:07.226-07:00 level=INFO msg="INFO locking app=sst-ion-zombies-repro stage=quinn"
time=2024-04-28T15:13:07.226-07:00 level=INFO msg="INFO getting data key=lock app=sst-ion-zombies-repro stage=quinn"
time=2024-04-28T15:13:07.229-07:00 level=INFO msg="connecting to server" addr=0.0.0.0:13557
time=2024-04-28T15:13:07.231-07:00 level=INFO msg=subscribed addr=127.0.0.1:63676
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*aws.FunctionInvokedEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*aws.FunctionResponseEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*aws.FunctionErrorEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*aws.FunctionLogEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*project.StackEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*aws.FunctionBuildEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*cloudflare.WorkerBuildEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*cloudflare.WorkerUpdatedEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg=subscribed type=*cloudflare.WorkerInvokedEvent
time=2024-04-28T15:13:07.232-07:00 level=INFO msg="got server stream"
SST ❍ ion 0.0.326 ready!
Result: |
|
ah wow ok these are workers spawned to run your code locally - let me look into this |
|
are you invoking with a lot of requests? to shed some more light - for every instance of a lambda function in aws we create a new nodejs process locally |
|
@thdxr In the video to reproduce I'm refreshing the page pretty quickly, but locally it takes longer to get into this state - def still happens tho. Doesn't seem to happen unless a code edit is made however |
|
@thdxr I think I've figured out the root cause, ion expects the node process to be well behaved currently and exit with Not sure if this is something you want to tackle in ion, could be nice to warn if processes don't get cleaned up or something. Not sure I messed around with this pattern and seemed to fix my issue, but I don't think it's robust enough or cross platform: // Make it it's own process group
cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
// ...later...
// Kill the whole group
syscall.Kill(-w.cmd.Process.Pid, syscall.SIGKILL)I'd be happy to take a crack at implementation if it's something you think makes sense for ion. This library may even just solve the problem |
Example video on youtube
Reproduction repo
I was experiencing huge slowdowns after developing with
sst devafter an hour or so. Noticed quite a few node processes all using 40%+ cpu. Can reproduce consistently nowMy guess is it could have something to do with volta being
nodeon my systemDetails:
The text was updated successfully, but these errors were encountered: