This service will be undergoing maintenance at 00:00 UTC, 2017-10-23 It is expected to last about 30 minutes
Bug 1460947 - after minor update cinder services are not starting, cinder.conf is not configured at all [NEEDINFO]
after minor update cinder services are not starting, cinder.conf is not confi...
Status: CLOSED INSUFFICIENT_DATA
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-tripleo (Show other bugs)
8.0 (Liberty)
Unspecified Unspecified
medium Severity unspecified
: ---
: ---
Assigned To: Sofer Athlan-Guyot
Yurii Prokulevych
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-06-13 04:42 EDT by Eduard Barrera
Modified: 2017-08-18 07:22 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-08-18 07:22:08 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
sathlang: needinfo? (ebarrera)


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Bugzilla 1342646 None None None 2017-06-13 04:44 EDT
Red Hat Bugzilla 1351784 None None None 2017-06-13 04:44 EDT
Red Hat Bugzilla 1365350 None None None 2017-06-13 04:44 EDT
Launchpad 1546431 None None None 2017-06-13 04:45 EDT

  None (edit)
Description Eduard Barrera 2017-06-13 04:42:13 EDT
Description of problem:

After a minor update cinder is shown as failed on pacemaker. If we dig deeper we can see that that cinder.conf seems to be not configured at all (passwords are not set and fails to connect everywhere), like if it was extracted from the rpm and puppet did not touch it at all. There is no apparent errors on os-collect-config logs for that node.

Looking at the undercloud heat-engine logs it's possible to see all kind of errors

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

How reproducible:
On each minor update attempt the problem appears but it might be in a different controller 

Example of traces:

https://bugzilla.redhat.com/show_bug.cgi?id=1342646
2017-06-12 13:00:20.001 21982 INFO heat.engine.service [req-544d6c28-95c7-4336-b927-63acebc21d8f - -] Service b2abdc1d-c513-47a1-a86a-f02d11812dac is updated
2017-06-12 13:00:20.029 21981 INFO heat.engine.service [req-59503384-eaa0-4fe9-81ee-853c76f445ff - -] Service 07086cf6-a40f-4672-ba85-cde16299c07c is updated
2017-06-12 13:00:56.844 21974 ERROR heat.engine.service [-] Failed to stop engine service, Cannot switch to MAINLOOP from MAINLOOP
2017-06-12 13:00:56.844 21972 ERROR heat.engine.service [-] Failed to stop engine service, Cannot switch to MAINLOOP from MAINLOOP
2017-06-12 13:00:56.845 21974 INFO heat.engine.service [-] Waiting stack bd6abde7-0146-40b6-aaae-8377dcda5266 processing to be finished
2017-06-12 13:00:56.845 21972 INFO heat.engine.service [-] Waiting stack 363b4c6b-6b5a-409a-b0d8-c4e88165350b processing to be finished

017-06-12 13:00:56.854 21981 INFO heat.engine.service [-] Stack b421798f-551e-4fec-b581-12ea597f3037 processing was finished
2017-06-12 13:00:56.854 21979 INFO heat.engine.service [-] Waiting stack ce4f4e29-6276-42ce-9691-6bc086c28da8 processing to be finished
2017-06-12 13:00:56.854 21982 INFO heat.engine.service [-] Waiting stack d50ef732-78f3-403c-a9e8-aa899f5d386e processing to be finished
2017-06-12 13:00:56.853 21929 INFO oslo_service.service [-] Caught SIGTERM, stopping children
2017-06-12 13:00:56.854 21986 INFO heat.engine.service [-] Waiting stack 5281ea10-39bd-4e37-9ef7-2b9b0f96dd7b processing to be finished

https://bugzilla.redhat.com/show_bug.cgi?id=1365350
2017-06-12 13:00:56.857 21929 CRITICAL heat-engine [-] AttributeError: 'NoneType' object has no attribute 'groups'
2017-06-12 13:00:56.857 21929 ERROR heat-engine Traceback (most recent call last):
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/bin/heat-engine", line 10, in <module>
2017-06-12 13:00:56.857 21929 ERROR heat-engine     sys.exit(main())
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/lib/python2.7/site-packages/heat/cmd/engine.py", line 78, in main
2017-06-12 13:00:56.857 21929 ERROR heat-engine     launcher.wait()
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/lib/python2.7/site-packages/oslo_service/service.py", line 534, in wait
2017-06-12 13:00:56.857 21929 ERROR heat-engine     self.stop()
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/lib/python2.7/site-packages/oslo_service/service.py", line 543, in stop
2017-06-12 13:00:56.857 21929 ERROR heat-engine     service.stop()
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2017-06-12 13:00:56.857 21929 ERROR heat-engine     return f(*args, **kwargs)
2017-06-12 13:00:56.857 21929 ERROR heat-engine   File "/usr/lib/python2.7/site-packages/heat/engine/service.py", line 400, in stop
2017-06-12 13:00:56.857 21929 ERROR heat-engine     for stack_id in list(self.thread_group_mgr.groups.keys()):
2017-06-12 13:00:56.857 21929 ERROR heat-engine AttributeError: 'NoneType' object has no attribute 'groups'
2017-06-12 13:00:56.857 21929 ERROR heat-engine


https://bugzilla.redhat.com/show_bug.cgi?id=1351784
https://bugzilla.redhat.com/show_bug.cgi?id=1342646
2017-06-12 13:00:56.928 21978 INFO heat.engine.service [-] Stack 8d515f71-02e8-455f-9fd4-20bbfb48503d processing was finished
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters [req-13d2d66f-aa04-44c3-929c-c74662e0f0f9 - -] DB exception wrapped.
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     context)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 146, in execute
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 296, in _query
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 781, in query
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 942, in _read_query_result
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1138, in read
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 895, in _read_packet
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     packet_header = self._read_bytes(4)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 912, in _read_bytes
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     data = self._rfile.read(num_bytes)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/_socketio.py", line 59, in readinto
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     return self._sock.recv_into(b)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 346, in recv_into
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     timeout_exc=socket.timeout("timed out"))
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 201, in _trampoline
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     mark_as_closed=self._mark_as_closed)
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/eventlet/hubs/__init__.py", line 144, in trampoline
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters     assert hub.greenlet is not current, 'do not call blocking functions from the mainloop'
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters AssertionError: do not call blocking functions from the mainloop
2017-06-12 13:00:56.926 21982 ERROR oslo_db.sqlalchemy.exc_filters


https://bugs.launchpad.net/heat/+bug/1546431
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool [-] Exception during reset or similar
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool Traceback (most recent call last):
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 636, in _finalize_fairy
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool     fairy._reset(pool)
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 776, in _reset
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool     pool._dialect.do_rollback(self)
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib64/python2.7/site-packages/sqlalchemy/dialects/mysql/base.py", line 2519, in do_rollback
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool     dbapi_connection.rollback()
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 724, in rollback
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool     self._read_ok_packet()
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 700, in _read_ok_packet
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool     raise err.OperationalError(2014, "Command Out of Sync")
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool OperationalError: (2014, 'Command Out of Sync')
2017-06-12 13:00:56.952 21982 ERROR sqlalchemy.pool.QueuePool


2017-06-12 13:00:57.160 21982 INFO oslo_service.service [-] Parent process has died unexpectedly, exiting
2017-06-12 13:00:57.160 21977 INFO oslo_service.service [-] Parent process has died unexpectedly, exiting
2017-06-12 13:00:57.160 21972 INFO oslo_service.service [-] Parent process has died unexpectedly, exiting
2017-06-12 13:00:57.160 21983 INFO oslo_service.service [-] Parent process has died unexpectedly, exiting

Steps to Reproduce:
1. perform a minor update
2.
3.

Actual results:
cinder services not started correctly, cinder.conf not populated at all

Expected results:
cinder.conf configured and able to start

Additional info:
Comment 2 Sofer Athlan-Guyot 2017-06-14 09:16:22 EDT
Hi,

so I'm seeing very unusual logs here, and it looks that some of them are related to our issue:

This happen on controller1, but not on controller0 where the update process is going all the way without those entries.

Jun 12 13:57:03 overcloud-controller-1.localdomain os-collect-config[12855]: erted /usr/share/openstack-puppet/modules/cinder/manifests/backend/emc_vnx.pp\n[REVERT-START] Trying to revert /etc/cinder/cinder.conf\n[REVERT-SUCCESS] Successfully reverted /etc/cinder/cinder.conf\n

The yum update has started at 13:47 on controller1:

Started yum_update.sh on server 7f9963e1-bb0e-4a34-9324-831feb9ba9a5 at Mon Jun 12 13:47:06 IST 2017

and ends at 13:57.

Then all those REVERT* log happen and I can see the puppet run that should happen there.

The heat engine log doesn't happen at the right time to be relevant.

So from where are those customization coming from? I can see them deploy by cloud-init at boot:

small excerpt:

un 12 11:59:23 overcloud-controller-1.localdomain cloud-init[10632]: Mon Jun 12 06:59:23 EDT 2017: Patching /usr/share/cbis/overcloud/patch/common/cinder.conf.patch
Jun 12 11:59:24 overcloud-controller-1.localdomain cloud-init[10632]: [PATCH-START] Trying to patch /etc/cinder/cinder.conf
Jun 12 11:59:24 overcloud-controller-1.localdomain cloud-init[10632]: [PATCH-SUCCESS] /etc/cinder/cinder.conf was patched successfully
Jun 12 11:59:24 overcloud-controller-1.localdomain cloud-init[10632]: restorecon reset /etc/cinder/cinder.conf context system_u:object_r:cloud_init_tmp_t:s0->system_u:object_r:etc_t:s0


and, as I said, just after the yum_update.sh scripts.  As a matter of fact those customization are not just touching the cinder.conf files:

[REVERT-START] Trying to revert /usr/share/openstack-puppet/modules/cinder/manifests/backend/emc_vnx.pp\n[REVERT-SUCCESS] Successfully rev
Jun 12 13:57:03 overcloud-controller-1.localdomain os-collect-config[12855]: erted /usr/share/openstack-puppet/modules/cinder/manifests/backend/emc_vnx.pp\n[REVERT-START] Trying to revert /etc/cinder/cinder.conf\n[REVERT-SUCCESS] Successfully reverted /etc/cinder/cinder.conf\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/nova/compute/api.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/nova/compute/api.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/nova/api/openstack/compute/volumes.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/nova/api/openstack/compute/volumes.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/nova/api/openstack/compute/legacy_v2/contrib/volumes.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/nova/api/openstack/compute/legacy_v2/contrib/volumes.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/neutron/db/extradhcpopt_db.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/neutron/db/extradhcpopt_db.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/neutron/extensions/extra_dhcp_opt.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/neutron/extensions/extra_dhcp_opt.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/heat/api/openstack/v1/util.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/heat/api/openstack/v1/util.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/heat/db/sqlalchemy/api.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/heat/db/sqlalchemy/api.py\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/heat/engine/service.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/heat/engine/service.py\n[REVERT-START] Trying to revert /etc/heat/policy.json\n[REVERT-SUCCESS] Successfully reverted /etc/heat/policy.json\n[REVERT-START] Trying to revert /usr/share/openstack-dashboard/openstack_dashboard/api/__init__.py\
Jun 12 13:57:03 overcloud-controller-1.localdomain os-collect-config[12855]: ifests/osds.pp\n[REVERT-SUCCESS] Successfully reverted /usr/share/openstack-puppet/modules/ceph/manifests/osds.pp\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/os_net_config/__init__.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/os_net_config/__init__.py\n[REVERT-START] Trying to revert /etc/rc.d/init.d/network\n[REVERT-SUCCESS] Successfully reverted /etc/rc.d/init.d/network\n[REVERT-START] Trying to revert /usr/share/openstack-puppet/modules/ceph/manifests/params.pp\n[REVERT-SUCCESS] Successfully reverted /usr/share/openstack-puppet/modules/ceph/manifests/params.pp\n[REVERT-START] Trying to revert /usr/share/openstack-puppet/modules/ceph/manifests/pool.pp\n[REVERT-SUCCESS] Successfully reverted /usr/share/openstack-puppet/modules/ceph/manifests/pool.pp\n[REVERT-START] Trying to revert /usr/share/openstack-puppet/modules/ceph/manifests/repo.pp\n[REVERT-SUCCESS] Successfully reverted /usr/share/openstack-puppet/modules/ceph/manifests/repo.pp\n[REVERT-START] Trying to revert /usr/lib/python2.7/site-packages/os_collect_config/request.py\n[REVERT-SUCCESS] Successfully reverted /usr/lib/python2.7/site-packages/os_collect_config/request.py\n[REVERT-START] Trying to revert /usr/share/openstack-puppet/modules/cinder/manifests/volume/emc_vnx.pp\n[REVERT-SUCCESS] Successfully reverted /usr/share/openstack-puppet/modules/cinder/manifests/volume/emc_vnx.pp\n[PATCH-START] Trying to patch /etc/cinder/cinder.conf\n[PATCH-SUCCESS] /etc/cinder/cinder.conf was patched successfully\nrestorecon reset /etc/cinder/cinder.conf context system_u:object_r:tmp_t:s0->system_u:object_r:etc_t:s0\n[PATCH-START] Trying to patch /usr/lib/python2.7/site-packages/os_net_config/impl_ifcfg.py\n[PATCH-SUCCESS] /usr/lib/python2.7/site-packages/os_net_config/impl_ifcfg.py was patched successfully\nrestorecon reset /usr/lib/python2.7/site-packages/os_net_config/impl_ifcfg.py context system_u:object_r:tmp_t:s0->system_u:object_r:lib_t:s0\n[PATCH-START] Trying to patch /usr/share/openstack-puppet/modules/c

So I think that those customization are breaking the minor update.  They should be removed from controller1 I guess if possible.
Comment 5 Sofer Athlan-Guyot 2017-08-18 07:22:08 EDT
Hi,

closing this one as we didn't have any update.   Don't hesitate to re-open it if needed.

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