Mistral fails to start with - password authentication failed for user

Describe the problem
The mistral-api and mistral-server services fail to start in the stackstorm container. The

Versions

Host OS: CentOS 7.4
docker: Docker version 18.03.1-ce, build 9ee9f40
docker-compose: docker-compose version 1.21.2, build a133471
stackstorm/stackstorm image: stackstorm/stackstorm latest aec9a79c7122
To Reproduce
Fresh clone of st2-docker, follow the normal steps in the TLDR section in the readme.

git clone git@github.com:stackstorm/st2-docker
cd st2-docker
make env
docker-compose up -d
docker-compose exec stackstorm bash
** Debugging info **

StackStorm container
Noticed that mistral-api and mistral-server weren't running:

root@faf971c95e40:/# st2ctl status
##### st2 components status #####
st2actionrunner PID: 95
st2actionrunner PID: 103
st2actionrunner PID: 108
st2actionrunner PID: 114
st2actionrunner PID: 129
st2actionrunner PID: 146
st2actionrunner PID: 156
st2actionrunner PID: 164
st2api PID: 57
st2api PID: 289
st2stream PID: 59
st2stream PID: 298
st2auth PID: 48
st2auth PID: 290
st2garbagecollector PID: 46
st2notifier PID: 52
st2resultstracker PID: 50
st2rulesengine PID: 55
st2sensorcontainer PID: 43
st2chatops is not running.
mistral-server is not running.
mistral.api is not running.
Trying to restart the service didn't help.

Looking at the logs /var/log/mistral/mistral-server.log the following error is present multiple times:

2018-05-24 00:11:50.878 929 ERROR oslo_service.service [-] Error starting thread.: DBError: Failed to setup database: (psycopg2.OperationalError) FATAL:  password authentication failed for user "mistral-user"
 (Background on this error at: http://sqlalche.me/e/e3q8)
2018-05-24 00:11:50.878 929 ERROR oslo_service.service Traceback (most recent call last):
2018-05-24 00:11:50.878 929 ERROR oslo_service.service   File "/opt/stackstorm/mistral/local/lib/python2.7/site-packages/oslo_service/service.py", line 729, in run_service
2018-05-24 00:11:50.878 929 ERROR oslo_service.service     service.start()
2018-05-24 00:11:50.878 929 ERROR oslo_service.service   File "/opt/stackstorm/mistral/local/lib/python2.7/site-packages/mistral/engine/engine_server.py", line 49, in start
2018-05-24 00:11:50.878 929 ERROR oslo_service.service     db_api.setup_db()
2018-05-24 00:11:50.878 929 ERROR oslo_service.service   File "/opt/stackstorm/mistral/local/lib/python2.7/site-packages/mistral/db/v2/api.py", line 29, in setup_db
2018-05-24 00:11:50.878 929 ERROR oslo_service.service     IMPL.setup_db()
2018-05-24 00:11:50.878 929 ERROR oslo_service.service   File "/opt/stackstorm/mistral/local/lib/python2.7/site-packages/mistral/db/v2/sqlalchemy/api.py", line 73, in setup_db
2018-05-24 00:11:50.878 929 ERROR oslo_service.service     raise exc.DBError("Failed to setup database: %s" % e)
2018-05-24 00:11:50.878 929 ERROR oslo_service.service DBError: Failed to setup database: (psycopg2.OperationalError) FATAL:  password authentication failed for user "mistral-user"
2018-05-24 00:11:50.878 929 ERROR oslo_service.service  (Background on this error at: http://sqlalche.me/e/e3q8)
2018-05-24 00:11:50.878 929 ERROR oslo_service.service 
Checking conf/postgres.env:

$ cat conf/postgres.env 
POSTGRES_USER=mistral-user
POSTGRES_PASSWORD=Af8zZoL24vQtAnQIIn2XjaHC
POSTGRES_HOST=postgres
POSTGRES_PORT=5432
POSTGRES_DB=mistral
Comparing against /etc/mistral/mistral.conf looks the same

root@faf971c95e40:/# cat /etc/mistral/mistral.conf  | grep postg
connection = postgresql+psycopg2://mistral-user:Af8zZoL24vQtAnQIIn2XjaHC@postgres:5432/mistral
Postgres container
Logging into the database:

su - postgres
psql
Making sure the user was created:

postgres=# select * from pg_authid ;
      rolname      | rolsuper | rolinherit | rolcreaterole | rolcreatedb | rolca
nlogin | rolreplication | rolbypassrls | rolconnlimit |             rolpassword 
            | rolvaliduntil 
-------------------+----------+------------+---------------+-------------+------
-------+----------------+--------------+--------------+-------------------------
------------+---------------
 postgres          | t        | t          | t             | t           | t    
       | t              | t            |           -1 |                         
            | 
 pg_signal_backend | f        | t          | f             | f           | f    
       | f              | f            |           -1 |                         
            | 
 mistral-user      | t        | t          | f             | f           | t    
       | f              | f            |           -1 | md50d27f1a3b9d45e2fa8942
61a0ab1a598 | 
(3 rows)
When i changed the password to the new one, the md5sum changed for the password hash:

postgres=# ALTER USER "mistral-user" WITH PASSWORD 'Af8zZoL24vQtAnQIIn2XjaHC';
ALTER ROLE
postgres=# select * from pg_authid ;
      rolname      | rolsuper | rolinherit | rolcreaterole | rolcreatedb | rolca
nlogin | rolreplication | rolbypassrls | rolconnlimit |             rolpassword 
            | rolvaliduntil 
-------------------+----------+------------+---------------+-------------+------
-------+----------------+--------------+--------------+-------------------------
------------+---------------
 postgres          | t        | t          | t             | t           | t    
       | t              | t            |           -1 |                         
            | 
 pg_signal_backend | f        | t          | f             | f           | f    
       | f              | f            |           -1 |                         
            | 
 mistral-user      | t        | t          | f             | f           | t    
       | f              | f            |           -1 | md5c68d82ac9f0e4f8b67274
69a599748ef | 
(3 rows)
I changed it a second time to see if the md5sum changed, and it did NOT. This leads me to believe that the password sent in initially was incorrect.

postgres=# ALTER USER "mistral-user" WITH PASSWORD 'Af8zZoL24vQtAnQIIn2XjaHC';
ALTER ROLE
postgres=# select * from pg_authid ;
      rolname      | rolsuper | rolinherit | rolcreaterole | rolcreatedb | rolca
nlogin | rolreplication | rolbypassrls | rolconnlimit |             rolpassword 
            | rolvaliduntil 
-------------------+----------+------------+---------------+-------------+------
-------+----------------+--------------+--------------+-------------------------
------------+---------------
 postgres          | t        | t          | t             | t           | t    
       | t              | t            |           -1 |                         
            | 
 pg_signal_backend | f        | t          | f             | f           | f    
       | f              | f            |           -1 |                         
            | 
 mistral-user      | t        | t          | f             | f           | t    
       | f              | f            |           -1 | md5c68d82ac9f0e4f8b67274
69a599748ef | 
(3 rows)
Afher changing the password
Restarted the mistral service and it connected immediately and no longer reported as not running in st2ctl status

@nmaludy
 
Member
Author
nmaludy commented on 24 May 2018
This appears to be a race condition.

If i do docker-compose down -v then docker-compose up -d sometimes mistral starts up fine, other times it does not.

FYI this is all with the same postgres password, so i don't think it's password related.