Setup failed as docker-compose matchminer-api fails to start due to mongodb NotYetInitialized error

[djhshih]

I tried setting up matchminer using setup.sh, and the script didn't work out of the box. It appears to be getting stuck waiting for the matchminer-API to load:

$ /bin/bash -c "$(curl -fsSL https://matchminer.org/setup.sh)"
...
curl: (28) Operation timed out after 1001 milliseconds with 0 bytes received
curl: (28) Operation timed out after 1000 milliseconds with 0 bytes received
Failed to start MatchMiner:
Startup failed! Check docker-compose logs to debug...

Tried again inside the setup directory and got same error:

cd ~/.matchminer-setup
./install

In particular, the following line fails:

wait_for_url http://localhost:1952/api/info

The following mongodb error is logged repeatedly every few seconds:

$ docker-compose logs -f
matchminer-setup-mongo-1           | {"t":{"$date":"2023-01-19T16:14:57.981+00:00"},"s":"I",  "c":"-",        "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"NotYetInitialized: Cannot use non-local read concern until replica set is finished initializing.","nextWakeupMillis":22600}}

I shutdown all docker-compose processes and tried again

$ docker-compose stop
$ docker-compose start

However, matchminer-api is not running:

$ docker-compose ps
NAME                               IMAGE                             COMMAND                  SERVICE             CR
EATED             STATUS              PORTS
matchminer-setup-elasticsearch-1   elasticsearch:6.8.12              "/usr/local/bin/dock…"   elasticsearch       35
 minutes ago      Up 23 minutes       9200/tcp, 9300/tcp
matchminer-setup-matchminer-ui-1   matchminer/matchminer-ui:latest   "/docker-entrypoint.…"   matchminer-ui       35
 minutes ago      Up 23 minutes       0.0.0.0:1952->80/tcp, :::1952->80/tcp
matchminer-setup-mongo-1           mongo:6.0-focal                   "docker-entrypoint.s…"   mongo               35
 minutes ago      Up 23 minutes       27017/tcp

$ docker-compose restart matchminer-api

$ docker-compose ps -f
atchminer-setup-matchminer-api-1  | pymongo.errors.NotMasterError: not master
matchminer-setup-matchminer-api-1  | [2023-01-19 15:58:47 +0000] [266] [INFO] Worker exiting (pid: 266)
matchminer-setup-matchminer-api-1  | /matchminerAPI/cerberus1/cerberus.py:1271: UserWarning: No validation schema is
 defined for the arguments of rule 'consented'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /matchminerAPI/cerberus1/cerberus.py:1271: UserWarning: No validation schema is
 defined for the arguments of rule 'match'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /matchminerAPI/cerberus1/cerberus.py:1271: UserWarning: No validation schema is
 defined for the arguments of rule 'normalized'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /matchminerAPI/cerberus1/cerberus.py:1271: UserWarning: No validation schema is
 defined for the arguments of rule 'unique'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /usr/local/lib/python3.8/site-packages/cerberus/validator.py:1401: UserWarning:
 No validation schema is defined for the arguments of rule 'consented'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /usr/local/lib/python3.8/site-packages/cerberus/validator.py:1401: UserWarning:
 No validation schema is defined for the arguments of rule 'match'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | /usr/local/lib/python3.8/site-packages/cerberus/validator.py:1401: UserWarning:
 No validation schema is defined for the arguments of rule 'normalized'
matchminer-setup-matchminer-api-1  |   warn("No validation schema is defined for the arguments of rule "
matchminer-setup-matchminer-api-1  | [WARNING] settings:
matchminer-setup-matchminer-api-1  | [WARNING] settings: mongodb://mongo:27017/matchminer
...
matchminer-setup-matchminer-api-1  |     self.reap_workers()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 525, in reap_workers
matchminer-setup-matchminer-api-1  |     raise HaltServer(reason, self.WORKER_BOOT_ERROR)
matchminer-setup-matchminer-api-1  | gunicorn.errors.HaltServer: <HaltServer 'Worker failed to boot.' 3>
matchminer-setup-matchminer-api-1  |
matchminer-setup-matchminer-api-1  | During handling of the above exception, another exception occurred:
matchminer-setup-matchminer-api-1  |
matchminer-setup-matchminer-api-1  | Traceback (most recent call last):
matchminer-setup-matchminer-api-1  |   File "/usr/local/bin/gunicorn", line 8, in <module>
matchminer-setup-matchminer-api-1  |     sys.exit(run())
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 58, in run
matchminer-setup-matchminer-api-1  |     WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/app/base.py", line 228, in run
matchminer-setup-matchminer-api-1  |     super().run()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
matchminer-setup-matchminer-api-1  |     Arbiter(self).run()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 229, in run
matchminer-setup-matchminer-api-1  |     self.halt(reason=inst.reason, exit_status=inst.exit_status)
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 342, in halt
matchminer-setup-matchminer-api-1  |     self.stop()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 393, in stop
matchminer-setup-matchminer-api-1  |     time.sleep(0.1)
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 242, in handle_chld
matchminer-setup-matchminer-api-1  |     self.reap_workers()
matchminer-setup-matchminer-api-1  |   File "/usr/local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 525, in reap_workers
matchminer-setup-matchminer-api-1  |     raise HaltServer(reason, self.WORKER_BOOT_ERROR)
matchminer-setup-matchminer-api-1  | gunicorn.errors.HaltServer: <HaltServer 'Worker failed to boot.' 3>
matchminer-setup-matchminer-api-1 exited with code 1

I guessing that matchminer-api cannot start due to the above error with mongodb?

I can connect to mongodb.

$ docker-compose exec mongo mongosh --eval ";" mongodb://mongo:27017
Current Mongosh Log ID: 63c970a93dd13d679ceee7da
Connecting to:          mongodb://mongo:27017/?directConnection=true&appName=mongosh+1.6.1
Using MongoDB:          6.0.3
Using Mongosh:          1.6.1

For mongosh info see: https://docs.mongodb.com/mongodb-shell/

------
   The server generated these startup warnings when booting
   2023-01-19T16:30:06.927+00:00: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine. See http://dochub.mongodb.org/core/prodnotes-filesystem
   2023-01-19T16:30:07.215+00:00: Access control is not enabled for the database. Read and write access to data and configuration is unrestricted
   2023-01-19T16:30:07.215+00:00: /sys/kernel/mm/transparent_hugepage/enabled is 'always'. We suggest setting it to 'never'
   2023-01-19T16:30:07.215+00:00: vm.max_map_count is too low
------

------
   Enable MongoDB's free cloud-based monitoring service, which will then receive and display
   metrics about your deployment (disk utilization, CPU, operation statistics, etc).

   The monitoring data will be available on a MongoDB website with a unique URL accessible to you
   and anyone you share the URL with. MongoDB may use this information to make product
   improvements and to suggest MongoDB products and deployment options to you.

   To enable free monitoring, run the following command: db.enableFreeMonitoring()
   To permanently disable this reminder, run the following command: db.disableFreeMonitoring()
------

Yet, I am still seeing the following error being logged repeatedly:

$ docker-compose logs -f
matchminer-setup-mongo-1           | {"t":{"$date":"2023-01-19T16:34:43.052+00:00"},"s":"I",  "c":"-",        "id":4939300, "ctx":"monitoring-keys-for-HMAC","msg":"Failed to refresh key cache","attr":{"error":"NotYetInitialized: Cannot use non-local read concern until replica set is finished initializing.","nextWakeupMillis":10600}}

Any thoughts?

Environment

$ uname -a
Linux durus 6.1.4-arch1-1 #1 SMP PREEMPT_DYNAMIC Sat, 07 Jan 2023 15:10:07 +0000 x86_64 GNU/Linux

$ docker version
Client:
 Version:           20.10.22
 API version:       1.41
 Go version:        go1.19.4
 Git commit:        3a2c30b63a
 Built:             Tue Dec 20 20:43:40 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server:
 Engine:
  Version:          20.10.22
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.19.4
  Git commit:       42c8b31499
  Built:            Tue Dec 20 20:42:46 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.6.14
  GitCommit:        9ba4b250366a5ddde94bb7c9d1def331423aa323.m
 runc:
  Version:          1.1.4
  GitCommit:
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

$ docker-compose version
Docker Compose version 2.14.2

[curlup]

Hi
by this

until replica set is finished initializing

seems, mongo didnt fully initialized maybe? you're saying you can connect to mongo, but looks like it's not fully operational and any op that requires non-local read concern would fail.
I hope that helps