on master noop review, multinode container update job failed while [tripleo-upgrade : run overcloud minor update in each of the roles/hostgroups]
From the logs http://logs.openstack.org/45/560445/201/check/tripleo-ci-centos-7-scenario000-multinode-oooq-container-updates/e74e20f/logs/undercloud/home/zuul/overcloud_update_run_Controller.log.txt.gz#_2018-11-23_01_58_58
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack [-] Update failed with: {u'status': u'RUNNING', u'message': u'\nTASK [Debug output for task: Run puppet host configuration for step 5] *********\nFriday 23 November 2018 01:58:50 +0000 (0:00:15.386) 0:09:06.600 ******* \nok: [centos-7-ovh-gra1-0000669515] => {\n "failed_when_result": false, \n "outputs.stdout_lines | default([]) | union(outputs.stderr_lines | default([]))": [\n "Notice: hiera(): Cannot load backend module_data: cannot load such file -- hiera/backend/module_data_backend", \n "Notice: Scope(Class[Tripleo::Firewall::Post]): At this stage, all network traffic is blocked.", \n "Notice: Compiled catalog for centos-7-ovh-gra1-0000669515.localdomain in environment production in 2.85 seconds", \n "Notice: /Stage[main]/Tripleo::Profile::Base::Kernel/Kmod::Load[nf_conntrack_proto_sctp]/Exec[modprobe nf_conntrack_proto_sctp]/returns: executed successfully", \n "Notice: Applied catalog in 4.47 seconds", \n "Changes:", \n " Total: 1", \n "Events:", \n " Success: 1", \n "Resources:", \n " Corrective change: 1", \n " Changed: 1", \n " Out of sync: 1", \n " Total: 171", \n "Time:", \n " Concat fragment: 0.00", \n " Concat file: 0.00", \n " Filebucket: 0.00", \n " File line: 0.00", \n " Anchor: 0.00", \n " Schedule: 0.00", \n " Package manifest: 0.00", \n " User: 0.00", \n " Package: 0.00", \n " Sysctl runtime: 0.01", \n " Firewall: 0.01", \n " Augeas: 0.02", \n " Sysctl: 0.06", \n " Service: 0.27", \n " File: 0.31", \n " Pcmk resource default: 0.70", \n " Pcmk property: 0.74", \n " Exec: 1.28", \n " Last run: 1542938329", \n " Config retrieval: 3.41", \n " Total: 6.81", \n "Version:", \n " Config: 1542938321", \n " Puppet: 4.8.2", \n "Warning: Undefined variable \'::deploy_config_name\'; ", \n " (file & line not available)", \n "Warning: Undefined variable \'deploy_config_name\'; ", \n "Warning: Unknown variable: \'::deployment_type\'. at /etc/puppet/modules/tripleo/manifests/profile/base/database/mysql/client.pp:85:31", \n "Warning: This method is deprecated, please use the stdlib validate_legacy function,", \n " with Stdlib::Compat::Bool. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 54]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " (at /etc/puppet/modules/stdlib/lib/puppet/functions/deprecation.rb:28:in `deprecation\')", \n " with Stdlib::Compat::Absolute_Path. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 55]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::String. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 56]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::Array. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 66]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Pattern[]. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 68]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::Numeric. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 76]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n "Warning: This method is deprecated, please use match expressions with Stdlib::Compat::String instead. They are described at https://docs.puppet.com/puppet/latest/reference/lang_data_type.html#match-expressions. at [\\"/etc/puppet/modules/snmp/manifests/params.pp\\", 310]:[\\"/var/lib/tripleo-config/puppet_step_config.pp\\", 39]", \n "Warning: tag is a metaparam; this value will inherit to all contained resources in the tripleo::firewall::rule definition", \n " with Stdlib::Compat::Hash. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/tripleo/manifests/firewall/rule.pp\\", 148]:"\n ]\n}\n\nTASK [Run docker-puppet tasks (generate config) during step 5] *****************\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.280) 0:09:06.880 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Run docker-puppet tasks (generate config) during step 5] ***\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.171) 0:09:07.052 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [Diff docker-puppet.py puppet-generated changes for check mode] ***********\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.082) 0:09:07.135 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"changed": false, "skip_reason": "Conditional result was False"}\n\nTASK [Diff docker-puppet.py puppet-generated changes for check mode] ***********\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.078) 0:09:07.213 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [Start containers for step 5] *********************************************\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.103) 0:09:07.316 ******* \nok: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Start containers for step 5] **********************\nFriday 23 November 2018 01:58:51 +0000 (0:00:00.761) 0:09:08.078 ******* \nok: [centos-7-ovh-gra1-0000669515] => {\n "failed_when_result": false, \n "outputs.stdout_lines | default([]) | union(outputs.stderr_lines | default([]))": [\n "$ docker ps -a --filter label=managed_by=paunch --filter label=config_id=tripleo_step5 --format {{.Names}} {{.Label \\"container_name\\"}}", \n "", \n "$ docker ps -a --filter label=managed_by=paunch --format {{.Names}} {{.Label \\"container_name\\"}}", \n "haproxy_init_bundle haproxy_init_bundle", \n "haproxy_restart_bundle haproxy_restart_bundle", \n "mysql_init_bundle mysql_init_bundle", \n "clustercheck clustercheck", \n "rabbitmq_init_bundle rabbitmq_init_bundle", \n "rabbitmq_restart_bundle rabbitmq_restart_bundle", \n "mysql_restart_bundle mysql_restart_bundle", \n "mysql_bootstrap mysql_bootstrap", \n "mysql_data_ownership mysql_data_ownership", \n "rabbitmq_bootstrap rabbitmq_bootstrap", \n "keystone_cron keystone_cron", \n "keystone keystone", \n "keystone_db_sync keystone_db_sync", \n "keystone_init_log keystone_init_log", \n "memcached memcached"\n ]\n}\n\nTASK [Check if /var/lib/docker-puppet/docker-puppet-tasks5.json exists] ********\nFriday 23 November 2018 01:58:51 +0000 (0:00:00.174) 0:09:08.253 ******* \nok: [centos-7-ovh-gra1-0000669515] => {"changed": false, "stat": {"exists": false}}\n\nTASK [Run docker-puppet tasks (bootstrap tasks) for step 5] ********************\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.388) 0:09:08.641 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Run docker-puppet tasks (bootstrap tasks) for step 5] ***\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.106) 0:09:08.747 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [include_tasks] ***********************************************************\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.076) 0:09:08.824 ******* \nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\n\nPLAY RECAP *********************************************************************\ncentos-7-ovh-gra1-0000669515 : ok=157 changed=53 unreachable=0 failed=0 \n\nFriday 23 November 2018 01:58:53 +0000 (0:00:00.642) 0:09:09.467 ******* \n=============================================================================== \n', u'execution': {u'id': u'6c71f304-8047-4ec9-ab61-e3c048d25169'}, u'plan_name': None}: RuntimeError: Update failed with: {u'status': u'RUNNING', u'message': u'\nTASK [Debug output for task: Run puppet host configuration for step 5] *********\nFriday 23 November 2018 01:58:50 +0000 (0:00:15.386) 0:09:06.600 ******* \nok: [centos-7-ovh-gra1-0000669515] => {\n "failed_when_result": false, \n "outputs.stdout_lines | default([]) | union(outputs.stderr_lines | default([]))": [\n "Notice: hiera(): Cannot load backend module_data: cannot load such file -- hiera/backend/module_data_backend", \n "Notice: Scope(Class[Tripleo::Firewall::Post]): At this stage, all network traffic is blocked.", \n "Notice: Compiled catalog for centos-7-ovh-gra1-0000669515.localdomain in environment production in 2.85 seconds", \n "Notice: /Stage[main]/Tripleo::Profile::Base::Kernel/Kmod::Load[nf_conntrack_proto_sctp]/Exec[modprobe nf_conntrack_proto_sctp]/returns: executed successfully", \n "Notice: Applied catalog in 4.47 seconds", \n "Changes:", \n " Total: 1", \n "Events:", \n " Success: 1", \n "Resources:", \n " Corrective change: 1", \n " Changed: 1", \n " Out of sync: 1", \n " Total: 171", \n "Time:", \n " Concat fragment: 0.00", \n " Concat file: 0.00", \n " Filebucket: 0.00", \n " File line: 0.00", \n " Anchor: 0.00", \n " Schedule: 0.00", \n " Package manifest: 0.00", \n " User: 0.00", \n " Package: 0.00", \n " Sysctl runtime: 0.01", \n " Firewall: 0.01", \n " Augeas: 0.02", \n " Sysctl: 0.06", \n " Service: 0.27", \n " File: 0.31", \n " Pcmk resource default: 0.70", \n " Pcmk property: 0.74", \n " Exec: 1.28", \n " Last run: 1542938329", \n " Config retrieval: 3.41", \n " Total: 6.81", \n "Version:", \n " Config: 1542938321", \n " Puppet: 4.8.2", \n "Warning: Undefined variable \'::deploy_config_name\'; ", \n " (file & line not available)", \n "Warning: Undefined variable \'deploy_config_name\'; ", \n "Warning: Unknown variable: \'::deployment_type\'. at /etc/puppet/modules/tripleo/manifests/profile/base/database/mysql/client.pp:85:31", \n "Warning: This method is deprecated, please use the stdlib validate_legacy function,", \n " with Stdlib::Compat::Bool. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 54]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " (at /etc/puppet/modules/stdlib/lib/puppet/functions/deprecation.rb:28:in `deprecation\')", \n " with Stdlib::Compat::Absolute_Path. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 55]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::String. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 56]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::Array. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 66]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Pattern[]. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 68]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n " with Stdlib::Compat::Numeric. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/ntp/manifests/init.pp\\", 76]:[\\"/etc/puppet/modules/tripleo/manifests/profile/base/time/ntp.pp\\", 34]", \n "Warning: This method is deprecated, please use match expressions with Stdlib::Compat::String instead. They are described at https://docs.puppet.com/puppet/latest/reference/lang_data_type.html#match-expressions. at [\\"/etc/puppet/modules/snmp/manifests/params.pp\\", 310]:[\\"/var/lib/tripleo-config/puppet_step_config.pp\\", 39]", \n "Warning: tag is a metaparam; this value will inherit to all contained resources in the tripleo::firewall::rule definition", \n " with Stdlib::Compat::Hash. There is further documentation for validate_legacy function in the README. at [\\"/etc/puppet/modules/tripleo/manifests/firewall/rule.pp\\", 148]:"\n ]\n}\n\nTASK [Run docker-puppet tasks (generate config) during step 5] *****************\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.280) 0:09:06.880 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Run docker-puppet tasks (generate config) during step 5] ***\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.171) 0:09:07.052 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [Diff docker-puppet.py puppet-generated changes for check mode] ***********\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.082) 0:09:07.135 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"changed": false, "skip_reason": "Conditional result was False"}\n\nTASK [Diff docker-puppet.py puppet-generated changes for check mode] ***********\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.078) 0:09:07.213 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [Start containers for step 5] *********************************************\nFriday 23 November 2018 01:58:50 +0000 (0:00:00.103) 0:09:07.316 ******* \nok: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Start containers for step 5] **********************\nFriday 23 November 2018 01:58:51 +0000 (0:00:00.761) 0:09:08.078 ******* \nok: [centos-7-ovh-gra1-0000669515] => {\n "failed_when_result": false, \n "outputs.stdout_lines | default([]) | union(outputs.stderr_lines | default([]))": [\n "$ docker ps -a --filter label=managed_by=paunch --filter label=config_id=tripleo_step5 --format {{.Names}} {{.Label \\"container_name\\"}}", \n "", \n "$ docker ps -a --filter label=managed_by=paunch --format {{.Names}} {{.Label \\"container_name\\"}}", \n "haproxy_init_bundle haproxy_init_bundle", \n "haproxy_restart_bundle haproxy_restart_bundle", \n "mysql_init_bundle mysql_init_bundle", \n "clustercheck clustercheck", \n "rabbitmq_init_bundle rabbitmq_init_bundle", \n "rabbitmq_restart_bundle rabbitmq_restart_bundle", \n "mysql_restart_bundle mysql_restart_bundle", \n "mysql_bootstrap mysql_bootstrap", \n "mysql_data_ownership mysql_data_ownership", \n "rabbitmq_bootstrap rabbitmq_bootstrap", \n "keystone_cron keystone_cron", \n "keystone keystone", \n "keystone_db_sync keystone_db_sync", \n "keystone_init_log keystone_init_log", \n "memcached memcached"\n ]\n}\n\nTASK [Check if /var/lib/docker-puppet/docker-puppet-tasks5.json exists] ********\nFriday 23 November 2018 01:58:51 +0000 (0:00:00.174) 0:09:08.253 ******* \nok: [centos-7-ovh-gra1-0000669515] => {"changed": false, "stat": {"exists": false}}\n\nTASK [Run docker-puppet tasks (bootstrap tasks) for step 5] ********************\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.388) 0:09:08.641 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"censored": "the output has been hidden due to the fact that \'no_log: true\' was specified for this result", "changed": false}\n\nTASK [Debug output for task: Run docker-puppet tasks (bootstrap tasks) for step 5] ***\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.106) 0:09:08.747 ******* \nskipping: [centos-7-ovh-gra1-0000669515] => {"skip_reason": "Conditional result was False"}\n\nTASK [include_tasks] ***********************************************************\nFriday 23 November 2018 01:58:52 +0000 (0:00:00.076) 0:09:08.824 ******* \nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\nincluded: /var/lib/mistral/6c71f304-8047-4ec9-ab61-e3c048d25169/post_update_steps_tasks.yaml for centos-7-ovh-gra1-0000669515\n\nPLAY RECAP *********************************************************************\ncentos-7-ovh-gra1-0000669515 : ok=157 changed=53 unreachable=0 failed=0 \n\nFriday 23 November 2018 01:58:53 +0000 (0:00:00.642) 0:09:09.467 ******* \n=============================================================================== \n', u'execution': {u'id': u'6c71f304-8047-4ec9-ab61-e3c048d25169'}, u'plan_name': None}
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack Traceback (most recent call last):
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/cliff/app.py", line 402, in run_subcommand
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack result = cmd.run(parsed_args)
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/tripleoclient/command.py", line 28, in run
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack super(Command, self).run(parsed_args)
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/osc_lib/command/command.py", line 41, in run
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack return super(Command, self).run(parsed_args)
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/cliff/command.py", line 184, in run
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack return_code = self.take_action(parsed_args) or 0
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/tripleoclient/v1/overcloud_update.py", line 159, in take_action
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack parsed_args.ssh_user)
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/tripleoclient/utils.py", line 1040, in run_update_ansible_action
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack skip_tags=skip_tags)
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack File "/usr/lib/python2.7/site-packages/tripleoclient/workflows/package_update.py", line 103, in update_ansible
2018-11-23 01:58:58 | 2018-11-23 01:58:58.092 175163 ERROR openstack raise RuntimeError('Update failed with: {}'.format(payload))
It appears that overcloud_update.MinorUpdateRun the code fail's on anything not "SUCCESS", not sure but with "RUNNING" we may want to continue until some other status is returned.
https://github.com/openstack/python-tripleoclient/blob/master/tripleoclient/workflows/package_update.py#L100-L103 needs to be tweaked till we get a new status.
I think I found the issue. It comes from https:/
We stop looking for messages once the execution is successful. But if we exit *before* the last message, we skip the success message and end up like the error we have before. It's a race condition.