Bug 1582597 - Non-descriptive failure logs during RHOS-12->RHOS-13 upgrade [NEEDINFO]
Summary: Non-descriptive failure logs during RHOS-12->RHOS-13 upgrade
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-tripleo-common
Version: 12.0 (Pike)
Hardware: All
OS: All
medium
medium
Target Milestone: z3
: 12.0 (Pike)
Assignee: Sergii Golovatiuk
QA Contact: nlevinki
URL:
Whiteboard:
Keywords: Triaged, ZStream
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-05-25 17:13 UTC by Archit Modi
Modified: 2018-08-20 13:01 UTC (History)
8 users (show)

(edit)
Clone Of:
(edit)
Last Closed: 2018-08-20 13:00:33 UTC
jamsmith: needinfo? (sgolovat)


Attachments (Terms of Use)
Complete Controller upgrade log (538.64 KB, text/plain)
2018-05-25 17:13 UTC, Archit Modi
no flags Details
mistral-paackage_update.log (4.03 MB, text/plain)
2018-05-25 17:19 UTC, Archit Modi
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2018:2331 None None None 2018-08-20 13:01 UTC
OpenStack gerrit 572064 None stable/pike: NEW tripleo-common: Add a 'trash_output' flag to ansible playbook action (Id13c7cf52b306891d780243b2562c8ca305aa365) 2018-06-04 09:46 UTC

Description Archit Modi 2018-05-25 17:13:09 UTC
Created attachment 1441668 [details]
Complete Controller upgrade log

Description of problem: While upgrading Controller node, the logs did not specify that the upgrade was unsuccessful, this might need improvement.


Version-Release number of selected component (if applicable): None


How reproducible: Always


Steps to Reproduce:
1. Start the upgrade procedure from RHOS-12 to RHOS-13
2. openstack overcloud upgrade run --roles Controller
Workflow tripleo.package_update.v1.update_nodes. Execution ID: 56cc0653-fb22-4f66-8e10-4f45eacb92c8
[u'Using /tmp/ansible-mistral-actionZ77KQb/ansible.cfg as config file',
 u' [WARNING]: Skipping unexpected key (hostvars) in group (_meta), only "vars",',
 u'"children" and "hosts" are valid',
 u"[DEPRECATION WARNING]: The use of 'include' for tasks has been deprecated. Use ",
 u"'import_tasks' for static inclusions or 'include_tasks' for dynamic inclusions.",
 u' This feature will be removed in a future release. Deprecation warnings can be ',
 u'disabled by setting deprecation_warnings=False in ansible.cfg.',
 u'[DEPRECATION WARNING]: include is kept for backwards compatibility but usage is',
 u' discouraged. The module documentation details page may explain more about this',
 u' rationale.. This feature will be removed in a future release. Deprecation ',
 u'warnings can be disabled by setting deprecation_warnings=False in ansible.cfg.',
 u'',
 u'PLAY [overcloud] ***************************************************************',
 u'',
 u'TASK [Gathering Facts] *********************************************************',
 u'ok: [192.168.24.7]',
 u'',
 u'TASK [include] *****************************************************************',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/upgrade_steps_tasks.yaml for 192.168.24.7',
 u'',
 u'TASK [include] *****************************************************************',
 u'included: /var/lib/mistral/56cc0653-fb22-4f66-8e10-4f45eacb92c8/Controller/upgrade_tasks.yaml for 192.168.24.7',
 u'',
 u'TASK [Check for aodh api service running under apache] *************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": "httpd -t -D DUMP_VHOSTS | grep -q aodh", "delta": "0:00:00.056203", "end": "2018-05-25 16:09:14.362046", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:14.305843", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if httpd is running] ***********************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-active", "--quiet", "httpd"], "delta": "0:00:00.011728", "end": "2018-05-25 16:09:16.680176", "msg": "non-zero return code", "rc": 3, "start": "2018-05-25 16:09:16.668448", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if aodh_evaluator is deployed] *************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-aodh-evaluator"], "delta": "0:00:00.014672", "end": "2018-05-25 16:09:19.032107", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:19.017435", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if aodh_listener is deployed] **************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-aodh-listener"], "delta": "0:00:00.013498", "end": "2018-05-25 16:09:21.359029", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:21.345531", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if aodh_notifier is deployed] **************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-aodh-notifier"], "delta": "0:00:00.014066", "end": "2018-05-25 16:09:23.749082", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:23.735016", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if ceilometer_agent_central is deployed] ***************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-ceilometer-central"], "delta": "0:00:00.012788", "end": "2018-05-25 16:09:26.189478", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:26.176690", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if ceilometer_agent_notification is deployed] **********************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-ceilometer-notification"], "delta": "0:00:00.015527", "end": "2018-05-25 16:09:28.602843", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:28.587316", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check is cinder_api is deployed] *****************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "openstack-cinder-api"], "delta": "0:00:00.013182", "end": "2018-05-25 16:09:30.986835", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:30.973653", "stderr": "", "stderr_lines": [], "stdout": "disabled", "stdout_lines": ["disabled"]}',
 u'...ignoring',
 u'',
 u'TASK [Check if cinder_scheduler is deployed] ***********************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "openstack-cinder-scheduler"], "delta": "0:00:00.014102", "end": "2018-05-25 16:09:33.284501", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:33.270399", "stderr": "", "stderr_lines": [], "stdout": "disabled", "stdout_lines": ["disabled"]}']
[u'...ignoring',
 u'',
 u'TASK [Get docker Cinder-Volume image] ******************************************',
 u'ok: [192.168.24.7] => {"ansible_facts": {"cinder_volume_docker_image_latest": "registry.access.redhat.com/rhosp13/openstack-cinder-volume:pcmklatest"}, "changed": false}',
 u'',
 u'TASK [Check for Cinder-Volume Kolla configuration] *****************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": false, "cmd": ["grep", "^volume_driver[ \\\\t]*=", "/var/lib/config-data/puppet-generated/cinder/etc/cinder/cinder.conf"], "delta": "0:00:00.003739", "end": "2018-05-25 16:09:35.676191", "msg": "non-zero return code", "rc": 2, "start": "2018-05-25 16:09:35.672452", "stderr": "grep: /var/lib/config-data/puppet-generated/cinder/etc/cinder/cinder.conf: No such file or directory", "stderr_lines": ["grep: /var/lib/config-data/puppet-generated/cinder/etc/cinder/cinder.conf: No such file or directory"], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if Cinder-Volume is already containerized] *************************',
 u'ok: [192.168.24.7] => {"ansible_facts": {"cinder_volume_containerized": false}, "changed": false}',
 u'',
 u'TASK [Check openstack-cinder-volume cluster resource status] *******************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": false, "error": "Error: unable to find resource \'openstack-cinder-volume\'\\n", "msg": "Failed, to set the resource openstack-cinder-volume to the state show", "output": "", "rc": 1}',
 u'...ignoring',
 u'',
 u'TASK [Check if glance_api is deployed] *****************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-glance-api"], "delta": "0:00:00.013784", "end": "2018-05-25 16:09:41.475210", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:41.461426", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if gnocchi_api is deployed] ****************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-enabled", "--quiet", "openstack-gnocchi-api"], "delta": "0:00:00.013891", "end": "2018-05-25 16:09:43.799806", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:43.785915", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check for gnocchi_api running under apache] ******************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": "httpd -t -D DUMP_VHOSTS | grep -q gnocchi", "delta": "0:00:00.056522", "end": "2018-05-25 16:09:46.141007", "msg": "non-zero return code", "rc": 1, "start": "2018-05-25 16:09:46.084485", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',
 u'',
 u'TASK [Check if httpd service is running] ***************************************',
 u'fatal: [192.168.24.7]: FAILED! => {"changed": true, "cmd": ["systemctl", "is-active", "--quiet", "httpd"], "delta": "0:00:00.010274", "end": "2018-05-25 16:09:48.491925", "msg": "non-zero return code", "rc": 3, "start": "2018-05-25 16:09:48.481651", "stderr": "", "stderr_lines": [], "stdout": "", "stdout_lines": []}',
 u'...ignoring',

Actual results:
Controller upgrade finished without specifying any error


Expected results: 
StdError: Displayed if upgrade is unsuccessful

Additional info:

Comment 1 Archit Modi 2018-05-25 17:19 UTC
Created attachment 1441669 [details]
mistral-paackage_update.log

Comment 2 Carlos Camacho 2018-05-28 13:58:45 UTC
Seems to be a known issue, just to confirm from Jose Luis and ask for more logs.

Comment 3 Jose Luis Franco 2018-05-28 16:31:10 UTC
This issue was reported already in https://bugzilla.redhat.com/show_bug.cgi?id=1573496 , the size of the log obtained from the ansible playbooks executed is way too long to be handled by mistral, and it simply crops it. 
This patch should handle the issue: https://review.openstack.org/#/c/566884/3 which was already cherry-picked downstream and being included in openstack-tripleo-common-8.6.1-14.el7ost.

Anyway, you can see the whole full output inside /var/log/mistral/package_update.log 

And the ansible task which failed during the upgrade process was this one:

INFO:__main__:Writing out command to execute", "+ chown -R mysql:mysql /var/lib/mysql", "+ timeout 60 sh -c \'while ! mysqladmin ping --silent; do sleep 1; done\'", "+ mysqld_safe --user=mysql --wsrep-provider=none --skip-networking --wsrep-on=off", "/usr/bin/mysqld_safe: line 728: ulimit: -1: invalid option", "ulimit: usage: ulimit [-SHacdefilmnpqrstuvx] [limit]", "+ mysql_upgrade"], "stdout": "180525 16:41:26 mysqld_safe Logging to \'/var/log/mariadb/mariadb.log\'.\\n180525 16:41:26 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql\\n180525 16:41:26 mysqld_safe WSREP: Running position recovery with --log_error=\'/var/lib/mysql/wsrep_recovery.ZlEvxe\' --pid-file=\'/var/lib/mysql/controller-0-recover.pid\'\\n180525 16:41:28 mysqld_safe WSREP: Recovered position bb8b69e3-5ecb-11e8-a4f7-1e48510494c2:115648\\nmysqld is alive\\nThis installation of MySQL is already upgraded to 5.5.42-MariaDB, use --force if you still need to run mysql_upgrade", "stdout_lines": ["180525 16:41:26 mysqld_safe Logging to \'/var/log/mariadb/mariadb.log\'.", "180525 16:41:26 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql", "180525 16:41:26 mysqld_safe WSREP: Running position recovery with --log_error=\'/var/lib/mysql/wsrep_recovery.ZlEvxe\' --pid-file=\'/var/lib/mysql/controller-0-recover.pid\'", "180525 16:41:28 mysqld_safe WSREP: Recovered position bb8b69e3-5ecb-11e8-a4f7-1e48510494c2:115648", "mysqld is alive", "This installation of MySQL is already upgraded to 5.5.42-MariaDB, use --force if you still need to run mysql_upgrade"

Comment 11 errata-xmlrpc 2018-08-20 13:00:33 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:2331


Note You need to log in before you can comment on or make changes to this bug.