I m seeing a strange bug when running Dagster job on ECS usi

Question

I m seeing a strange bug when running Dagster job on ECS using ECSRunLauncher I have a set of software defined assets I start an asset materialization job from Dagit Then exception is thrown inside the asset function Exception is legit there s an error in the input data so I see step failure in the log in Dagit `dagster core errors DagsterExecutionStepExecutionError Error occurred while executing op ` And here goes the most interesting part underlying ECS jobs keep running and Dagster job also keeps running forever Dagit shows it s status as `STARTED` but nothing actually happens in this job since it has already failed but somehow Dagster doesn t know about it Has anyone seen something like this before Dagster version `0 14 7`

johann · Answer

The ECS task keeps running indefinitely Does Dagit show a STEP FAILURE event

Grigoriy Sterin · Answer

Yes to both questions

johann · Answer

Very strange could you share the logs from the ECS task for the run

Grigoriy Sterin · Answer

Sure When I look into the ECS run logs CloudWatch I don t see the error there it all finishes with resources initialization for that failed asset ```2022 04 18T09 44 23 810 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 28 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 23 810 04 00 metadata=RUN METADATA 2022 04 18T09 44 23 810 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 45 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 23 810 04 00 asset 2022 04 18T09 44 23 810 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 55 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 23 810 04 00 metadata=RUN METADATA 2022 04 18T09 44 23 810 04 00 2022 04 18 13 44 23 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 1 RUN START Started execution of run for data ingestion assets 2022 04 18T09 44 23 827 04 00 2022 04 18 13 44 23 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 1 ENGINE EVENT Executing steps using multiprocess executor parent process pid 1 2022 04 18T09 44 23 910 04 00 2022 04 18 13 44 23 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 1 new novogene data folders in aggregation bucket ENGINE EVENT Launching subprocess for new novogene data folders in aggregation bucket 2022 04 18T09 44 28 635 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 28 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 28 635 04 00 metadata=RUN METADATA 2022 04 18T09 44 28 635 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 45 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 28 635 04 00 asset 2022 04 18T09 44 28 635 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 55 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 44 28 635 04 00 metadata=RUN METADATA 2022 04 18T09 44 28 635 04 00 2022 04 18 13 44 28 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket ENGINE EVENT Starting initialization of resources root manager s3 aggregation bucket io manager sqs source asset io manager 2022 04 18T09 44 28 816 04 00 2022 04 18 13 44 28 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket ENGINE EVENT Finished initialization of resources root manager s3 aggregation bucket io manager sqs source asset io manager 2022 04 18T09 44 29 896 04 00 2022 04 18 13 44 29 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket LOGS CAPTURED Started capturing logs for step new novogene data folders in aggregation bucket 2022 04 18T09 44 29 896 04 00 2022 04 18 13 44 29 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket STEP START Started execution of step new novogene data folders in aggregation bucket 2022 04 18T09 44 29 896 04 00 2022 04 18 13 44 29 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket LOADED INPUT Loaded input new folders in novogene landing bucket using input manager root manager 2022 04 18T09 44 30 896 04 00 2022 04 18 13 44 29 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket STEP INPUT Got input new folders in novogene landing bucket of type NewLandingData Type check passed 2022 04 18T09 44 30 896 04 00 2022 04 18 13 44 29 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 12 new novogene data folders in aggregation bucket STEP OUTPUT Yielded output result of type NewAggregationData Type check passed 2022 04 18T09 46 55 914 04 00 2022 04 18 13 46 55 +0000 dagster INFO data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 new novogene data folders in aggregation bucket Skipping fvl58 novogene data landing PLT314 317 already exists in aggregation bucket 2022 04 18T09 46 55 914 04 00 2022 04 18 13 46 55 +0000 dagster INFO data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 new novogene data folders in aggregation bucket Writing the list of last moved folders in aggregation bucket to fvl58 novogene data landing data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 lst 2022 04 18T09 46 57 095 04 00 2022 04 18 13 46 57 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 1 new novogene submission sets ENGINE EVENT Launching subprocess for new novogene submission sets 2022 04 18T09 47 03 435 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 28 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 47 03 435 04 00 metadata=RUN METADATA 2022 04 18T09 47 03 435 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 45 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 47 03 435 04 00 asset 2022 04 18T09 47 03 435 04 00 pipelines data ingestion assets assets novogene data ingestion assets py 55 ExperimentalWarning asset is an experimental decorator It may break in future versions even between dot releases To mute warnings for experimental functionality invoke warnings filterwarnings ignore category=dagster ExperimentalWarning or use one of the other methods described at 2022 04 18T09 47 03 435 04 00 metadata=RUN METADATA 2022 04 18T09 47 03 435 04 00 2022 04 18 13 47 03 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 26 new novogene submission sets ENGINE EVENT Starting initialization of resources s3 aggregation bucket io manager s3 novogene submission sets io manager 2022 04 18T09 47 03 614 04 00 2022 04 18 13 47 03 +0000 dagster DEBUG data ingestion assets f502119f b348 43fd a2aa 0741f89fefb3 26 new novogene submission sets ENGINE EVENT Finished initialization of resources s3 aggregation bucket io manager s3 novogene submission sets io manager ```

johann · Answer

Is this happening every time or a flake

Grigoriy Sterin · Answer

Every time

johann · Answer

cc < alex> in case he has any ideas for a hanging multi process executor

johann · Answer

< Dagster Bot> issue Multiprocess executor hanging on ECS

Dagster Bot · Answer

Created issue at <https github com dagster io dagster issues 7490>

alex · Answer

does terminating canceling the run work how did you define your graph job

Grigoriy Sterin · Answer

terminating a run works

Grigoriy Sterin · Answer

Job is defined from an AssetGroup ```novogene data ingestion job = AssetGroup assets= new novogene data folders in aggregation bucket new novogene submission sets source assets= new folders in novogene landing bucket resource defs= s3 aggregation bucket io manager s3 aggregation bucket io manager sqs source asset io manager sqs source asset io manager s3 novogene submission sets io manager s3 novogene submission sets io manager build job data ingestion assets ```

alex · Answer

hmmm could you send a debug file theres a download debug file button on the run page

Grigoriy Sterin · Answer

Sure Where can I find it

Grigoriy Sterin · Answer

ok

Grigoriy Sterin · Answer

Here you go

Grigoriy Sterin · Answer

Hi Is there any update on this by any chance Thank you

alex · Answer

I tried reproing amp looking at what you sent for a short while but was unable to find any leads

alex · Answer

can you execute the same job locally and if yes do you get different behavior there

Grigoriy Sterin · Answer

I ll give it a try

alex · Answer

a debug file of a canceled terminated run may be useful too hoping it may include information about where it was stuck

Grigoriy Sterin · Answer

I was able to reproduce the bug locally

alex · Answer

ok thats good to know so ECS probably not a factor that leaves assets as the best lead since thats a newer feature < owen>

Grigoriy Sterin · Answer

One thing I noticed is that when this happens the job is forever stuck in the `Started` state rather than `Running` Could it be some race condition or some clause in the Dagster code like `if exception == true and jobStatus == Running terminateJob `

alex · Answer

i dont believe we have a running state so started is our equivalent to that since you can repro locally is the process still running can you `py spy dump p lt pid gt ` to see where its stuck

alex · Answer

there are events in the log that communicate what the pid is for the process driving the run

Grigoriy Sterin · Answer

ok gimme a sec

Grigoriy Sterin · Answer

I have several python process related to dagster Which pid should I use ``` 1127 pts 2 Sl+ 0 13 usr bin python3 home gsterin local bin dagit f data ingestion assets repo py 1129 pts 2 Sl+ 0 04 usr bin python3 m dagster api grpc lazy load user code socket tmp tmpzam80aki heartbeat heartbeat timeout 45 fixed server id 01eb010f 1058 41eb b6a3 8a7a0ddb06da log level WARNING use python environment entry point f data ingestion assets repo py d mnt c projects dagster data ingestion pipelines repo pipelines 2288 pts 2 S+ 0 00 usr bin python3 c from multiprocessing resource tracker import main main 13 2289 pts 2 Sl+ 0 01 usr bin python3 c from multiprocessing spawn import spawn main spawn main tracker fd=14 pipe handle=16 multiprocessing fork 2351 pts 2 Sl+ 0 01 usr bin python3 c from multiprocessing spawn import spawn main spawn main tracker fd=14 pipe handle=17 multiprocessing fork```

alex · Answer

if you look at the dagit logs you should see something like `Executing steps using multiprocess executor parent process pid 1 ` at the top

Grigoriy Sterin · Answer

```Process 2289 usr bin python3 c from multiprocessing spawn import spawn main spawn main tracker fd=14 pipe handle=16 multiprocessing fork Python v3 8 10 usr bin python3 8 Thread 2289 idle MainThread poll multiprocessing popen fork py 27 wait multiprocessing popen fork py 47 join multiprocessing process py 149 execute child process command dagster core executor child process executor py 165 execute step out of process dagster core executor multiprocess py 323 execute dagster core executor multiprocess py 210 pipeline execution iterator dagster core execution api py 785 iter dagster core execution api py 879 core execute run dagster grpc impl py 91 run in subprocess dagster grpc impl py 168 start run in subprocess dagster grpc impl py 192 run multiprocessing process py 108 bootstrap multiprocessing process py 315 main multiprocessing spawn py 129 spawn main multiprocessing spawn py 116 lt module gt lt string gt 1 Thread 2294 idle kill on event wait multiprocessing synchronize py 261 wait multiprocessing synchronize py 349 kill on event dagster utils init py 357 run threading py 870 bootstrap inner threading py 932 bootstrap threading py 890 Thread 2295 idle QueueFeederThread wait threading py 302 feed multiprocessing queues py 227 run threading py 870 bootstrap inner threading py 932 bootstrap threading py 890 ```

alex · Answer

hmm and is the process for the step still running pid is printed in message like gt Executing step new novogene submission sets in subprocess

Grigoriy Sterin · Answer

Ok looks like it was my fault Process for the step was stuck trying to execute destructor for the custom io manager ```Process 2351 usr bin python3 c from multiprocessing spawn import spawn main spawn main tracker fd=14 pipe handle=17 multiprocessing fork Python v3 8 10 usr bin python3 8 Thread 0x7FD090C9F740 active MainThread wait for tstate lock threading py 1027 join threading py 1011 close python dynamodb lock python dynamodb lock py 688 del data ingestion assets io managers s3 aggregation bucket io manager py 36 Thread 2357 idle kill on event wait multiprocessing synchronize py 261 wait multiprocessing synchronize py 349 kill on event dagster utils init py 357 run threading py 870 bootstrap inner threading py 932 bootstrap threading py 890 Thread 0x7FD086E21700 active DynamoDBLockClient HS 0dd9417a179b4812bb474c504ee3e360 send heartbeat loop python dynamodb lock python dynamodb lock py 167 run threading py 870 bootstrap inner threading py 932 bootstrap threading py 890 Thread 0x7FD086620700 active DynamoDBLockClient HC 0dd9417a179b4812bb474c504ee3e360 check heartbeat loop python dynamodb lock python dynamodb lock py 284 run threading py 870 bootstrap inner threading py 932 bootstrap threading py 890 ```

Grigoriy Sterin · Answer

After commenting out the `data ingestion assets io managers s3 aggregation bucket io manager py 36` line the error doesn t reproduce anymore Thank you for help with debugging this

alex · Answer

well at least we figured it out and now you know how to debug similar problems if they ever arise not sure what we could do to help catch problems like this

alex · Answer

destructor dead lock is nasty nasty business