Quick-start script timeout is too short for flowdb-synthetic-data

[maxalbert]

On a fresh VM I ran the command below to try out the worked examples from @jch1g10's PR #770. However, the script reports a failure to start up FlowDB:

$ CI=true CIRCLE_SHA1=7c868eb4c71994241fa1ce1e9b3a98d1186b604a bash <(curl -s https://raw.githubusercontent.com/Flowminder/FlowKit/7c868eb4c71994241fa1ce1e9b3a98d1186b604a/quick_start.sh) examples
Starting containers (this may take a few minutes)
Pulling flowdb                   ... done
Pulling flowdb_testdata          ... done
Pulling flowdb_synthetic_data    ... done
Pulling worked_examples          ... done
Pulling flowapi                  ... done
Pulling flowauth                 ... done
Pulling flowmachine_query_locker ... done
Pulling flowmachine              ... done
Pulling flowetl                  ... done
Pulling flowetl_db               ... done
Creating network "flowkit_db" with the default driver
Creating network "flowkit_redis" with the default driver
Creating network "flowkit_zero" with the default driver
Creating network "flowkit_default" with the default driver
Creating network "flowkit_flowetl_db" with the default driver
Creating flowdb_synthetic_data    ... done
Creating worked_examples          ... done
Creating flowauth                 ... done
Creating flowmachine_query_locker ... done
Creating flowapi                  ... done
Creating flowmachine              ... done

Waiting for containers to be ready..
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
127.0.0.1:5432 - no response
Waiting 10s
FlowDB failed to start :( Please open an issue at https://github.com/Flowminder/FlowKit/issues/new?template=bug_report.md&labels=FlowDB,bug including the output of running 'docker logs flowdb'

However, the containers actually all start successfully:

$ docker ps
CONTAINER ID        IMAGE                                                                       COMMAND                  CREATED             STATUS              PORTS                           NAMES
9cf254b5fb22        flowminder/flowmachine:7c868eb4c71994241fa1ce1e9b3a98d1186b604a             "pipenv run flowmach…"   6 minutes ago       Up 13 seconds       0.0.0.0:5555->5555/tcp          flowmachine
114f22826cd9        flowminder/flowapi:7c868eb4c71994241fa1ce1e9b3a98d1186b604a                 "pipenv run ./start.…"   7 minutes ago       Up 6 minutes        0.0.0.0:9090->9090/tcp          flowapi
ca6f7dcd7dfa        bitnami/redis                                                               "/entrypoint.sh /run…"   7 minutes ago       Up 6 minutes        0.0.0.0:6379->6379/tcp          flowmachine_query_locker
dae6d8b6938b        flowminder/flowkit-examples:7c868eb4c71994241fa1ce1e9b3a98d1186b604a        "tini -g -- start.sh…"   7 minutes ago       Up 6 minutes        0.0.0.0:8888->8888/tcp          worked_examples
5c3fcdfc746c        flowminder/flowauth:7c868eb4c71994241fa1ce1e9b3a98d1186b604a                "/entrypoint.sh /sta…"   7 minutes ago       Up 6 minutes        443/tcp, 0.0.0.0:9091->80/tcp   flowauth
f35ad84c9638        flowminder/flowdb-synthetic-data:7c868eb4c71994241fa1ce1e9b3a98d1186b604a   "docker-entrypoint.s…"   7 minutes ago       Up 6 minutes        0.0.0.0:9000->5432/tcp          flowdb_synthetic_data

It's just that the synthetic data container now seems to take a longer time to start up compared to a while ago.

Unless this is some sort of unexpected regression which causes the longer startup, we should increase the timeout in the quick-start script so that flowdb has time to start up before the script tries to abort.

[greenape]

Damn timeouts! The timer is currently four minutes, which is already pretty damn long. How powerful (or not) was the VM?

Obviously we need to increase this though.

[maxalbert]

It was a droplet with 4GB RAM. Interestingly, I noticed that the startup time of flowdb_synthetic_data (and now that I think of it probably memory usage too) increased significantly between whatever master was when I tested the branch for PR #770 and the tip of that branch. There isn't anything in that PR which would have caused a change to flowdb, but there seems to be something in recent changes that has had an effect (possibly related to other changes that got merged recently).

My comment about a likey increase in memory usage is based on the observation that I could start flowdb_synthetic_data on a droplet with only 2GB RAM for recent master, but it would simply abort halfway through the data generation when I tried to run it for the PR branch. I may try to dissect the recent history to see if I can pinpoint this to a particular commit.

[maxalbert]

Just for the record, I just tried again to run the quick-start script with the commit (164fab7) when #770 was merged into master.

This time I used a droplet with 2GB RAM, and it started up all containers successfully, including synthetic data generation (although it was a bit slow; took ~16 minutes to start up, and as before the script erroneously reported flowdb as having failed to start up).

So I'm not sure why it failed on the previous runs with a 2GB VM and how to reproduce the issue, but I'll keep an eye open.