Jira (PDB-3715) PuppetDB doesn't complete shutdown after migration fails

[Charlie Sharpsteen (JIRA)]

Title: Message Title

Charlie Sharpsteen created an issue   PuppetDB / PDB-3715 PuppetDB doesn't complete shutdown after migration fails Issue Type: Bug Affects Versions: PDB 5.1.1 Assignee: Unassigned Created: 2017/10/16 1:42 PM Priority: Major Reporter: Charlie Sharpsteen The PuppetDB service doesn't shut down after a failed migration, despite log messages indicating that the shutdown cycle has been started. This causes the init service to wait for the full START_TIMEOUT before declaring startup as failed and killing the process. Given we've bumped START_TIMEOUT to 4 hours to allow for migration of large databases, this significantly delays detection of failed upgrades due to migration issues. Reproduction Case Install PuppetDB 5.0.1 on a CentOS 7 VM using the puppetlabs/puppetdb module: Add package repos for version 5 of the Puppet Platform and install the puppet agent: rpm -Uvh http://yum.puppetlabs.com/puppet5/puppet-release-el-7.noarch.rpm yum install -y puppet agent Instal the PuppetDB module /opt/puppetlabs/bin/puppet module install puppetlabs-puppetdb --version 6.0.1 Apply the following manifest to install Postgres and PuppetDB. Two applications may be necessary due to a race condition where Puppet resources attempt to enforce state on the database while Postgres is still starting up. /opt/puppetlabs/puppet/bin/puppet apply << EOF class {'puppetdb::globals': version => '5.0.1'} class {'puppetdb': disable_ssl => true} EOF Add some test data to PuppetDB that will trigger the migration failure described in PDB-3692: /opt/puppetlabs/puppet/bin/curl -X POST \ -H 'Content-Type:application/json' \ -H 'Accept:application/json' \ -d '{"certname":"test1","environment":"DEV","values":{"myfact": null},"producer_timestamp":"2015-01-01", "producer":"master1"}' \ "http://localhost:8080/pdb/cmd/v1?command=replace_facts&version=5&certname=test1" /opt/puppetlabs/puppet/bin/curl -X POST \ -H 'Content-Type:application/json' \ -H 'Accept:application/json' \ -d '{"certname":"test2","environment":"DEV","values":{"myfact": null},"producer_timestamp":"2015-01-01", "producer":"master1"}' \ "http://localhost:8080/pdb/cmd/v1?command=replace_facts&version=5&certname=test2"   # Alter the facts table to trigger PDB-3692 on upgrade sudo -u postgres /usr/bin/psql -d puppetdb -c "UPDATE facts SET value='null' WHERE factset_id=2 AND value_type_id=4" Decrease the timeout for PuppetDB startup and then upgrade PuppetDB to 5.1.1: echo 'START_TIMEOUT=60' >> /etc/sysconfig/puppetdb   /opt/puppetlabs/bin/puppet resource --evaltrace package puppetdb ensure=5.1.1 Outcome /var/log/puppetlabs/puppetdb/puppetdb.log shows the migration fails and the service enters shutdown within seconds after starting: 2017-10-16 20:03:52,350 INFO [p.p.c.services] PuppetDB version 5.1.1 2017-10-16 20:03:52,351 INFO [c.z.h.HikariDataSource] PDBMigrationsPool - Starting... 2017-10-16 20:03:52,353 INFO [c.z.h.HikariDataSource] PDBMigrationsPool - Start completed. 2017-10-16 20:03:52,517 INFO [p.p.s.migrate] Applying database migration version 64 2017-10-16 20:03:52,518 INFO [p.p.s.migrate] [1/8] Cleaning up unreferenced facts... 2017-10-16 20:03:52,527 INFO [p.p.s.migrate] [2/8] Creating new fact storage tables... 2017-10-16 20:03:52,543 INFO [p.p.s.migrate] [3/8] Copying unique fact values into fact_values 2017-10-16 20:03:52,555 INFO [p.p.s.migrate] [4/8] Reconstructing facts to refer to fact_values... 2017-10-16 20:03:52,557 INFO [p.p.s.migrate] [5/8] Cleaning up duplicate null values... 2017-10-16 20:03:52,558 INFO [p.p.s.migrate] ... none found 2017-10-16 20:03:52,559 INFO [p.p.s.migrate] [6/8] Computing fact value hashes... 2017-10-16 20:03:52,611 INFO [p.p.s.migrate] [7/8] Indexing fact_values table... 2017-10-16 20:03:52,640 ERROR [p.p.s.migrate] Caught SQLException during migration java.sql.BatchUpdateException: Batch entry 3 ALTER TABLE fact_values ADD CONSTRAINT fact_values_value_hash_key UNIQUE (value_hash) was aborted. Call getNextException to see the cause. ... 2017-10-16 20:03:52,641 ERROR [p.p.s.migrate] Unravelled exception org.postgresql.util.PSQLException: ERROR: could not create unique index "fact_values_value_hash_key" Detail: Key (value_hash)=(\x2be88ca4242c76e8253ac62474851065032d6833) is duplicated. ... 2017-10-16 20:03:52,668 INFO [p.t.internal] Shutting down due to JVM shutdown hook. 2017-10-16 20:03:52,669 INFO [p.t.internal] Beginning shutdown sequence However, the upgrade takes over a full minute to complete, the init script hangs until START_TIMEOUT kicks in: # /opt/puppetlabs/bin/puppet resource --evaltrace --verbose package puppetdb ensure=5.1.1 Info: /Package[puppetdb]: Starting to evaluate the resource Notice: /Package[puppetdb]/ensure: ensure changed '5.0.1-1.el7' to '5.1.1' Info: /Package[puppetdb]: Evaluated in 132.98 seconds package { 'puppetdb': ensure => '5.1.1-1.el7', }   # journalctl -u puppetdb ... Oct 16 19:51:10 r1lt6c9aq1o5t4r systemd[1]: Starting puppetdb Service... Oct 16 19:51:29 r1lt6c9aq1o5t4r puppetdb[13361]: The [database] classname setting has been retired and will be ignored. Oct 16 19:51:29 r1lt6c9aq1o5t4r puppetdb[13361]: The [database] subprotocol setting has been retired and will be ignored. Oct 16 19:51:33 r1lt6c9aq1o5t4r puppetdb[13361]: The [database] classname setting has been retired and will be ignored. Oct 16 19:51:33 r1lt6c9aq1o5t4r puppetdb[13361]: The [database] subprotocol setting has been retired and will be ignored. Oct 16 19:52:10 r1lt6c9aq1o5t4r puppetdb[13361]: Startup timed out after 60 seconds Oct 16 19:52:10 r1lt6c9aq1o5t4r puppetdb[13361]: Startup script was terminated before completion Oct 16 19:53:11 r1lt6c9aq1o5t4r puppetdb[13361]: Process 13368 not terminated gracefully after 60 seconds Oct 16 19:53:12 r1lt6c9aq1o5t4r puppetdb[13361]: /opt/puppetlabs/server/apps/puppetdb/ezbake-functions.sh: line 79: 13368 Killed ${JAVA_BIN} ${JAVA_ARGS} -Djava.sec Oct 16 19:53:13 r1lt6c9aq1o5t4r puppetdb[13361]: Process 13368 killed after SIGKILL Oct 16 19:53:13 r1lt6c9aq1o5t4r systemd[1]: puppetdb.service: control process exited, code=exited status=1 Oct 16 19:53:13 r1lt6c9aq1o5t4r systemd[1]: Failed to start puppetdb Service. Expected Outcome PuppetDB startup should fail-fast after migration fails and not have to be killed by the init script due START_TIMEOUT. Add Comment   This message was sent by Atlassian JIRA (v6.4.14#64029-sha1:ae256fe) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To post to this group, send email to puppet-bugs@googlegroups.com. Visit this group at https://groups.google.com/group/puppet-bugs. For more options, visit https://groups.google.com/d/optout.