Fuel for OpenStack

keystone resources are called before keystone haproxy backend is ready

Bug #1357386 reported by Vladimir Kuklin on 2014-08-15

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Fuel for OpenStack	Fix Released	Critical	Vladimir Kuklin	Fuel for OpenStack 5.1
	5.0.x	Fix Committed	High	Fuel Library (Deprecated)	Fuel for OpenStack 5.0.2

Bug Description

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

Revision history for this message

Vladimir Kuklin (vkuklin) wrote on 2014-08-15:

fail_error_deploy_ha_vlan-2014_08_15__13_11_44.tar.gz Edit (20.4 MiB, application/x-tar)

summary:

- keystone are called before keystone haproxy backend is ready
+ keystone resources are called before keystone haproxy backend is ready

Sergii Golovatiuk (sgolovatiuk) on 2014-08-15

Changed in fuel:
assignee:	Fuel Library Team (fuel-library) → Sergii Golovatiuk (sgolovatiuk)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-15: Fix proposed to fuel-library (master)

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

Changed in fuel:
assignee:	Sergii Golovatiuk (sgolovatiuk) → Vladimir Kuklin (vkuklin)
status:	Confirmed → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-17: Fix merged to fuel-library (master)

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

Changed in fuel:
status:	In Progress → Fix Committed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-28: Fix proposed to fuel-library (stable/5.0)

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

Revision history for this message

Artem Panchenko (apanchenko-8) wrote on 2014-08-28:

fuel-snapshot-2014-08-28_02-13-35.tgz Edit (3.1 MiB, application/x-tar)

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/

Changed in fuel:
status:	Fix Committed → Confirmed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-28: Fix merged to fuel-library (stable/5.0)

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

Closes-bug: #1357386

Change-Id: I906fb01f678b0407e421a5db7f617901fed80f79

Revision history for this message

Vladimir Kuklin (vkuklin) wrote on 2014-08-28:

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

Dmitry Pyzhov (dpyzhov) on 2014-09-02

no longer affects:

fuel/5.1.x

Giant Tao (wtctc) on 2016-09-04

Changed in fuel:
status:	Fix Committed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

Bug watches keep track of this bug in other bug trackers.