keystone resources are called before keystone haproxy backend is ready

[Vladimir Kuklin]

HA deployment may result in wrong ordering for keystone classes that create endpoints and other stuff. We need firstly to ensure that keystone backend is ready to accept requests and then create keystone endpoints/roles/services/etc.

Snippet from logs:
Fri Aug 15 12:16:25 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_service[cinder] (err): Could not evaluate: Execution of '/usr/bin/keystone --os-token 414A35P4 --os-endpoint http://10.108.2.6:35357/v2.0/ service-list' returned 1: Unable to establish connection to http://10.108.2.6:35357/v2.0/OS-KSADM/services

/usr/lib/ruby/vendor_ruby/puppet/util/execution.rb:188:in `execute'
/usr/lib/ruby/vendor_ruby/puppet/provider/command.rb:23:in `execute'
/usr/lib/ruby/vendor_ruby/puppet/provider.rb:237:in `keystone'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone.rb:54:in `auth_keystone'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone.rb:52:in `loop'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone.rb:52:in `auth_keystone'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone.rb:85:in `list_keystone_objects'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone_service/keystone.rb:87:in `build_service_hash'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone_service/keystone.rb:28:in `service_hash'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone_service/keystone.rb:32:in `service_hash'
/etc/puppet/modules/keystone/lib/puppet/provider/keystone_service/keystone.rb:56:in `exists?'
/usr/lib/ruby/vendor_ruby/puppet/property/ensure.rb:81:in `retrieve'
/usr/lib/ruby/vendor_ruby/puppet/type.rb:1035:in `retrieve'
/usr/lib/ruby/vendor_ruby/puppet/type.rb:1063:in `retrieve_resource'
/usr/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:223:in `from_resource'
/usr/lib/ruby/vendor_ruby/puppet/transaction/resource_harness.rb:17:in `evaluate'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:174:in `apply'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:187:in `eval_resource'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:117:in `call'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:117:in `evaluate'
/usr/lib/ruby/vendor_ruby/puppet/util.rb:327:in `thinmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/vendor_ruby/puppet/util.rb:326:in `thinmark'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:117:in `evaluate'
/usr/lib/ruby/vendor_ruby/puppet/graph/relationship_graph.rb:118:in `traverse'
/usr/lib/ruby/vendor_ruby/puppet/transaction.rb:108:in `evaluate'
/usr/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:164:in `apply'
/usr/lib/ruby/vendor_ruby/puppet/util/log.rb:149:in `with_destination'
/usr/lib/ruby/vendor_ruby/puppet/transaction/report.rb:108:in `as_logging_destination'
/usr/lib/ruby/vendor_ruby/puppet/resource/catalog.rb:163:in `apply'
/usr/lib/ruby/vendor_ruby/puppet/configurer.rb:125:in `apply_catalog'
/usr/lib/ruby/vendor_ruby/puppet/util.rb:161:in `benchmark'
/usr/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/usr/lib/ruby/vendor_ruby/puppet/util.rb:160:in `benchmark'
/usr/lib/ruby/vendor_ruby/puppet/configurer.rb:124:in `apply_catalog'
/usr/lib/ruby/vendor_ruby/puppet/configurer.rb:192:in `run'
/usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:268:in `apply_catalog'
/usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:218:in `main'
/usr/lib/ruby/vendor_ruby/puppet/application/apply.rb:146:in `run_command'
/usr/lib/ruby/vendor_ruby/puppet/application.rb:364:in `run'
/usr/lib/ruby/vendor_ruby/puppet/application.rb:470:in `plugin_hook'
/usr/lib/ruby/vendor_ruby/puppet/application.rb:364:in `run'
/usr/lib/ruby/vendor_ruby/puppet/util.rb:478:in `exit_on_fail'
/usr/lib/ruby/vendor_ruby/puppet/application.rb:364:in `run'
/usr/lib/ruby/vendor_ruby/puppet/util/command_line.rb:137:in `run'
/usr/lib/ruby/vendor_ruby/puppet/util/command_line.rb:91:in `execute'
/usr/bin/puppet:4
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_service[cinder] (info): Evaluated in 154.70 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_endpoint[RegionOne/cinder] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_endpoint[RegionOne/cinder] (notice): Dependency Keystone_service[cinder] has failures: true
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_endpoint[RegionOne/cinder] (warning): Skipping because of failed dependencies
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Cinder::Keystone::Auth/Keystone_endpoint[RegionOne/cinder] (info): Evaluated in 0.02 seconds
Fri Aug 15 12:16:26 +0000 2014 Class[Keystone::Endpoint] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 Class[Keystone::Endpoint] (info): Evaluated in 0.00 seconds
Fri Aug 15 12:16:26 +0000 2014 Haproxy::Listen[keystone-1] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 Haproxy::Listen[keystone-1] (info): Evaluated in 0.02 seconds
Fri Aug 15 12:16:26 +0000 2014 Haproxy::Service[keystone-1] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 Haproxy::Service[keystone-1] (info): Evaluated in 0.02 seconds
Fri Aug 15 12:16:26 +0000 2014 Concat::Fragment[haproxy_keystone-1] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 Concat::Fragment[haproxy_keystone-1] (info): Evaluated in 0.01 seconds
Fri Aug 15 12:16:26 +0000 2014 Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] (info): Evaluated in 0.01 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg]/ensure (notice): created
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg] (debug): The container Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] will propagate my refresh event
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg] (info): Scheduling refresh of Exec[concat_/etc/haproxy/conf.d/020-keystone-1.cfg]
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg] (info): Evaluated in 0.65 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat.out] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat.out]/ensure (notice): created
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat.out] (debug): The container Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] will propagate my refresh event
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat.out] (info): Evaluated in 0.01 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat]/ensure (notice): created
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat] (debug): The container Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] will propagate my refresh event
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments.concat] (info): Evaluated in 0.01 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments]/ensure (notice): created
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments] (debug): The container Concat[/etc/haproxy/conf.d/020-keystone-1.cfg] will propagate my refresh event
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments] (info): Scheduling refresh of Exec[concat_/etc/haproxy/conf.d/020-keystone-1.cfg]
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat[/etc/haproxy/conf.d/020-keystone-1.cfg]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments] (info): Evaluated in 0.01 seconds
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat::Fragment[haproxy_keystone-1]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments/00_haproxy_keystone-1] (info): Starting to evaluate the resource
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat::Fragment[haproxy_keystone-1]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments/00_haproxy_keystone-1]/ensure (notice): defined content as '{md5}1c66f3733b5de35605e21e60b4d732f7'
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat::Fragment[haproxy_keystone-1]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments/00_haproxy_keystone-1] (debug): The container Concat::Fragment[haproxy_keystone-1] will propagate my refresh event
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat::Fragment[haproxy_keystone-1]/File[/var/lib/puppet/concat/_etc_haproxy_conf.d_020-keystone-1.cfg/fragments/00_haproxy_keystone-1] (info): Scheduling refresh of Exec[concat_/etc/haproxy/conf.d/020-keystone-1.cfg]
Fri Aug 15 12:16:26 +0000 2014 /Stage[main]/Openstack::Ha::Keystone/Openstack::Ha::Haproxy_service[keystone-1]/Haproxy::Listen[keystone-1]/Haproxy::Service[keystone-1]/Concat::Fragmen

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/114577

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/114577
Committed: https://git.openstack.org/cgit/stackforge/fuel-library/commit/?id=6a157f7e5cfa5b1f53eeb1b715960ed43157384b
Submitter: Jenkins
Branch: master

commit 6a157f7e5cfa5b1f53eeb1b715960ed43157384b
Author: Vladimir Kuklin <email address hidden>
Date: Fri Aug 15 19:32:45 2014 +0400

    Configure haproxy keystone backend before keystone service

    Configure haproxy keystone backend before keystone service
    starts. This will fix ordering problem when we have keystone
    resources created before keystone is available. Service
    is already started before resources creation, so that
    puppet provider will receive a couple of 503|504 HTTP
    errors in the worst case and handle them.

    Closes-bug: #1357386

    Change-Id: I906fb01f678b0407e421a5db7f617901fed80f79

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/5.0
Review: https://review.openstack.org/117474

[Artem Panchenko (apanchenko-8)]

This issue was reproduced again on 5.1 iso (#483):

http://jenkins-product.srt.mirantis.net:8080/view/0_master_swarm/job/master_fuelmain.system_test.ubuntu.thread_2/152/testReport/junit/(root)/deploy_simple_flat/deploy_simple_flat/

Here are errors from puppet log (node-2):

http://paste.openstack.org/show/101649/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/117474
Committed: https://git.openstack.org/cgit/stackforge/fuel-library/commit/?id=315d6e3f0820e5f902eb9ca70ae0d25e2f9be89f
Submitter: Jenkins
Branch: stable/5.0

commit 315d6e3f0820e5f902eb9ca70ae0d25e2f9be89f
Author: Vladimir Kuklin <email address hidden>
Date: Fri Aug 15 19:32:45 2014 +0400

    Configure haproxy keystone backend before keystone service

    Configure haproxy keystone backend before keystone service
    starts. This will fix ordering problem when we have keystone
    resources created before keystone is available. Service
    is already started before resources creation, so that
    puppet provider will receive a couple of 503|504 HTTP
    errors in the worst case and handle them.

    Closes-bug: #1357386

    Change-Id: I906fb01f678b0407e421a5db7f617901fed80f79

[Vladimir Kuklin (vkuklin)]

Artem, your bug report is not related to this bug as this bug is related ONLY to HA mode. And yours one is simple