Manageiq: Upstream nightly failing for CFME QE: Cannot start postgresql.service due to emtpy cert

[jawatts]

CFME QE automation is failing to configure an upstream appliance from the lastest upstream build:

http://file.cloudforms.lab.eng.rdu2.redhat.com/builds/manageiq/master/20190327_2000/

Following is seen when postsql.service is started:

[root@dhcp-8-197-197 ~]# systemctl status evmserverd
● evmserverd.service - EVM server daemon
   Loaded: loaded (/usr/lib/systemd/system/evmserverd.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Thu 2019-03-28 13:35:49 EDT; 34s ago

Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Starting EVM server daemon...
Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: Generating a 2048 bit RSA private key
Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: ........................+++
Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: .........+++
Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: writing new private key to '/var/www/miq/vmdb/certs/server.cer.key'
Mar 28 13:35:36 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: -----
Mar 28 13:35:43 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14828]: EVM has no Database connection
Mar 28 13:35:49 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com sh[14842]: Stopping EVM gracefully...
Mar 28 13:35:49 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Started EVM server daemon.
[root@dhcp-8-197-197 ~]# systemctl status postgresql.service
● postgresql.service - PostgreSQL database server
   Loaded: loaded (/usr/lib/systemd/system/postgresql.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2019-03-28 13:33:05 EDT; 3min 30s ago
 Main PID: 4595 (code=exited, status=1/FAILURE)

Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Starting PostgreSQL database server...
Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com postmaster[4595]: 2019-03-28 13:33:05 EDT::5c9d0551.11f3:@:[4595]:FATAL:  could not load server certificate file "server.crt": no start line
Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: postgresql.service: main process exited, code=exited, status=1/FAILURE
Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Failed to start PostgreSQL database server.
Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Unit postgresql.service entered failed state.
Mar 28 13:33:05 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: postgresql.service failed.
[root@dhcp-8-197-197 ~]# cd /var/lib/pgsql/data
[root@dhcp-8-197-197 data]# ls
base              global  pg_commit_ts  pg_hba.conf    pg_log      pg_multixact  pg_replslot  pg_snapshots  pg_stat_tmp  pg_tblspc    PG_VERSION  pg_xact               postgresql.conf  server.crt
current_logfiles  log     pg_dynshmem   pg_ident.conf  pg_logical  pg_notify     pg_serial    pg_stat       pg_subtrans  pg_twophase  pg_wal      postgresql.auto.conf  postmaster.opts  server.key
[root@dhcp-8-197-197 data]# cat server.crt 
[root@dhcp-8-197-197 data]# cat server.key
[root@dhcp-8-197-197 data]# 

Was testing on rhev using: http://file.cloudforms.lab.eng.rdu2.redhat.com/builds/manageiq/master/20190327_2000/manageiq-ovirt-master-201903272000-d46c321f35.qc2

[carbonin]

@jawatts I just deployed that exact image and had no problem with postgresql starting.

Can you share the output of journalctl -u appliance-initialize and the appliance_console.log?

[jawatts]

journalctl -u appliance-initialize:

```[root@dhcp-8-197-197 data]# journalctl -u appliance-initialize
-- Logs begin at Thu 2019-03-28 10:52:11 EDT, end at Fri 2019-03-29 09:45:07 EDT. --
Mar 28 10:52:26 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com systemd[1]: Starting Initialize Appliance Database...
Mar 28 10:52:28 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com appliance-initialize.sh[4549]: TERM environment variable not set.
Mar 28 10:52:29 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com appliance-initialize.sh[4549]: create encryption key
Mar 28 10:52:29 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com appliance-initialize.sh[4549]: configuring internal database
Mar 28 10:52:29 dhcp-8-197-197.cfme2.lab.eng.rdu2.redhat.com appliance-initialize.sh[4549]: Initialize postgresql starting
[root@dhcp-8-197-197 data]#

appliance_console.log:

[root@dhcp-8-197-197 log]# cat appliance_console.log

Logfile created on 2019-03-28 10:52:29 -0400 by logger.rb/56815

I, [2019-03-28T10:52:29.672812 #4553] INFO -- : MIQ(ManageIQ::ApplianceConsole::InternalDatabaseConfiguration#initialize_postgresql) : starting
[root@dhcp-8-197-197 log]#
```

[carbonin]

It looks like something interrupted the initial processing. What kind of automation are you running to deploy the appliance? For example, this is what I get for those commands:

[root@localhost ~]# journalctl -u appliance-initialize
-- Logs begin at Fri 2019-03-29 09:26:45 EDT, end at Fri 2019-03-29 09:30:14 EDT. --
Mar 29 09:27:20 localhost.localdomain systemd[1]: Starting Initialize Appliance Database...
Mar 29 09:27:22 localhost.localdomain appliance-initialize.sh[3717]: TERM environment variable not set.
Mar 29 09:27:23 localhost.localdomain appliance-initialize.sh[3717]: create encryption key
Mar 29 09:27:23 localhost.localdomain appliance-initialize.sh[3717]: configuring internal database
Mar 29 09:27:23 localhost.localdomain appliance-initialize.sh[3717]: Initialize postgresql starting
Mar 29 09:27:48 localhost.localdomain appliance-initialize.sh[3717]: Initialize postgresql complete
Mar 29 09:27:48 localhost.localdomain appliance-initialize.sh[3717]: Checking for connections to the database...
Mar 29 09:28:00 localhost.localdomain appliance-initialize.sh[3717]: Create region starting
Mar 29 09:30:06 localhost.localdomain appliance-initialize.sh[3717]: Create region complete
Mar 29 09:30:14 localhost.localdomain systemctl[14169]: Removed symlink /etc/systemd/system/multi-user.target.wants/appliance-initialize.service.
Mar 29 09:30:14 localhost.localdomain systemd[1]: Started Initialize Appliance Database.

[root@localhost vmdb]# cat log/appliance_console.log 
# Logfile created on 2019-03-29 09:27:23 -0400 by logger.rb/56815
I, [2019-03-29T09:27:23.845993 #3726]  INFO -- : MIQ(ManageIQ::ApplianceConsole::InternalDatabaseConfiguration#initialize_postgresql) : starting
I, [2019-03-29T09:27:48.302483 #3726]  INFO -- : MIQ(ManageIQ::ApplianceConsole::InternalDatabaseConfiguration#initialize_postgresql) : complete
I, [2019-03-29T09:28:00.215426 #3726]  INFO -- : MIQ(ManageIQ::ApplianceConsole::InternalDatabaseConfiguration#create_region) : starting
I, [2019-03-29T09:30:06.863634 #3726]  INFO -- : MIQ(ManageIQ::ApplianceConsole::InternalDatabaseConfiguration#create_region) : complete
E, [2019-03-29T09:30:14.461738 #14146] ERROR -- : Failed to enable and start evmserverd service: /bin/systemctl exit code: 
E, [2019-03-29T09:30:14.461899 #14146] ERROR -- : /usr/local/lib/ruby/gems/2.4.0/gems/awesome_spawn-1.4.1/lib/awesome_spawn.rb:105:in `run!'
/usr/local/lib/ruby/gems/2.4.0/gems/linux_admin-1.2.2/lib/linux_admin/common.rb:24:in `run!'
/usr/local/lib/ruby/gems/2.4.0/gems/linux_admin-1.2.2/lib/linux_admin/service/systemd_service.rb:18:in `start'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/database_configuration.rb:237:in `block in start_evm'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/database_configuration.rb:235:in `fork'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/database_configuration.rb:235:in `start_evm'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/internal_database_configuration.rb:114:in `post_activation'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/cli.rb:225:in `set_internal_db'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/cli.rb:192:in `set_db'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/cli.rb:170:in `run'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/lib/manageiq/appliance_console/cli.rb:412:in `parse'
/usr/local/lib/ruby/gems/2.4.0/gems/manageiq-appliance_console-4.0.2/bin/appliance_console_cli:7:in `<top (required)>'
/usr/local/bin/appliance_console_cli:23:in `load'
/usr/local/bin/appliance_console_cli:23:in `<main>'

That backtrace is an issue that we've known about for a while and can't seem to track down. At this point I was able to start evmserverd and everything was fine.

[mshriver]

@carbonin Thanks for the engagement here Nick - wanted to chime in, as we are taking the raw image, uploading it to rhv, adding nics and a disk, and then marking that VM as a template. Its possible that appliance-initialize is started when the VM starts, and then gets cut off when shut down to mark as template.

Sorry for my lack of knowledge here, but is this a process that occurs on the downstream CFME images as well? We don't see this issue in running the same template creation process there.

[carbonin]

Ah, okay, I understand now. The upstream and downstream images are different in this regard.

The upstream image ships with a logical volume already set up for postgres and contains a service (appliance-initialize) which will set up the database and start evmserverd on first boot.

It seems likely that you're getting a bit of the way through that process before creating the template which could be causing this issue.

[carbonin]

You could incorporate something like https://gist.github.com/carbonin/a25b84efca2e6b3c3f91b673821a22c8 into the automation for upstream appliances.

That will get you to a point where the appliance looks similar enough to the downstream image.

You may also want to unmount /var/lib/pgsql if you're going to add and configure an external device.

[jawatts]

Thanks Nick, I will look into updating our upstream template creation process.

[Fryguy]

Closing as a path forward seems to have been described, but please reopen if you think it's needed.