Bug 1383832

Summary: Cinder services down after upgrade to osp8
Product: Red Hat OpenStack Reporter: Jeremy <jmelvin>
Component: openstack-cinderAssignee: Eric Harney <eharney>
Status: CLOSED NOTABUG QA Contact: nlevinki <nlevinki>
Severity: high Docs Contact:
Priority: high    
Version: 8.0 (Liberty)CC: eharney, fahmed, rcernin, srevivo, tshefi
Target Milestone: ---Flags: tshefi: automate_bug-
Target Release: 8.0 (Liberty)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-10-12 13:03:27 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Comment 2 Faiaz Ahmed 2016-10-11 22:54:36 UTC 
Just before the ERROR noticed this WARNING. Wondering if this is related.

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2016-10-11 17:17:34.367 26327 WARNING oslo_config.cfg [-] Option "notification_driver" from group "DEFAULT" is deprecated. Use option "driver" from group "oslo_messaging_notifications".
2016-10-11 17:17:34.645 26327 WARNING py.warnings [-] /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py:241: NotSupportedWarning: Configuration option(s) ['use_tpool'] not supported
  exception.NotSupportedWarning

<<<<<<<<<<<<<<<<<<<<<< SNIP >>>>>>>>>>>>>>>>>>>>>>>>>>>>

2016-10-11 17:17:35.245 26363 WARNING cinder.volume.drivers.nfs [req-99303cd7-6be5-4059-8d9b-47434441fe10 - - - - -] The NAS file permissions mode will be 666 (allowing other/world read & write access). This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NFS configuration.
2016-10-11 17:17:35.246 26363 WARNING cinder.volume.drivers.nfs [req-99303cd7-6be5-4059-8d9b-47434441fe10 - - - - -] The NAS file operations will be run as root: allowing root level access at the storage backend. This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NAS configuration.

<<<<<<<<<<<<<<<<<<<<<< SNIP >>>>>>>>>>>>>>>>>>>>>>>>>>>>

2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager [req-99303cd7-6be5-4059-8d9b-47434441fe10 - - - - -] Failed to initialize driver.
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager Traceback (most recent call last):
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 367, in init_host
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     self.driver.do_setup(ctxt)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/osprofiler/profiler.py", line 105, in wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 872, in trace_method_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 872, in trace_method_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/nfs_cmode.py", line 71, in do_setup
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     vserver=self.vserver)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 872, in trace_method_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 872, in trace_method_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py", line 46, in __init__
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     (major, minor) = self.get_ontapi_version(cached=False)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 872, in trace_method_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_base.py", line 58, in get_ontapi_version
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     res = self.connection.invoke_successfully(ontapi_version, False)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/api.py", line 235, in invoke_successfully
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     result = self.send_http_request(na_element, enable_tunneling)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/utils.py", line 882, in trace_api_logging_wrapper
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     return f(*args, **kwargs)
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager   File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/api.py", line 220, in send_http_request
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager     raise NaApiError('Unexpected error')
2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~


For the Second time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2016-10-11 17:20:19.747 26553 DEBUG cinder.volume.drivers.nfs [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] NAS variable secure_file_permissions setting is: false set_nas_security_options /usr/lib/python2.7/site-packages/cinder/volume/drivers/nfs.py:351
2016-10-11 17:20:19.748 26553 WARNING cinder.volume.drivers.nfs [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] The NAS file permissions mode will be 666 (allowing other/world read & write access). This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NFS configuration.
2016-10-11 17:20:19.748 26553 DEBUG cinder.volume.drivers.nfs [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] NAS variable secure_file_operations setting is: false set_nas_security_options /usr/lib/python2.7/site-packages/cinder/volume/drivers/nfs.py:372
2016-10-11 17:20:19.749 26553 WARNING cinder.volume.drivers.nfs [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] The NAS file operations will be run as root: allowing root level access at the storage backend. This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NAS configuration.
2016-10-11 17:20:19.750 26553 DEBUG cinder.volume.drivers.netapp.dataontap.client.api [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] Using NetApp controller: 10.199.203.2 __init__ /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/api.py:67
2016-10-11 17:20:19.763 26553 ERROR cinder.volume.manager [req-8c0b99e2-9fe8-4ba9-b5ce-9a595ef29fe6 - - - - -] Failed to initialize driver.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~



And Again
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2016-10-11 17:20:19.954 26559 WARNING cinder.volume.drivers.nfs [req-cb05e7e1-06aa-405d-902a-53f21fc756ea - - - - -] The NAS file permissions mode will be 666 (allowing other/world read & write access). This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NFS configuration.
2016-10-11 17:20:19.954 26559 DEBUG cinder.volume.drivers.nfs [req-cb05e7e1-06aa-405d-902a-53f21fc756ea - - - - -] NAS variable secure_file_operations setting is: false set_nas_security_options /usr/lib/python2.7/site-packages/cinder/volume/drivers/nfs.py:372
2016-10-11 17:20:19.954 26518 DEBUG oslo_service.service [req-83af8bf4-1d60-4970-9483-ce267dc4b86b - - - - -] osapi_volume_base_URL          = None log_opt_values /usr/lib/python2.7/site-packages/oslo_config/cfg.py:2229
2016-10-11 17:20:19.955 26559 WARNING cinder.volume.drivers.nfs [req-cb05e7e1-06aa-405d-902a-53f21fc756ea - - - - -] The NAS file operations will be run as root: allowing root level access at the storage backend. This is considered an insecure NAS environment. Please see http://docs.openstack.org/admin-guide-cloud/blockstorage_nfs_backend.html for information on a secure NAS configuration.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Comment 3 Faiaz Ahmed 2016-10-11 23:25:58 UTC 
The other ERROR I noticed too

egrep "not sending heartbeat. Service will appear" volume.log* |grep  2016-10-11 | wc -l
788
$ pwd
/cases/01718988/sosreport-20161011-174038/vlo-controller-p03.test.com/var/log/cinder


ERROR in breif

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
2016-10-11 17:41:40.354 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:41:50.354 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:00.364 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:10.368 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:20.368 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:20.413 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
2016-10-11 17:42:24.987 26553 DEBUG oslo_service.periodic_task [req-ca1e1503-51bd-4233-b5a4-4da0ee5730f0 - - - - -] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
2016-10-11 17:42:24.988 26553 DEBUG oslo_service.periodic_task [req-ca1e1503-51bd-4233-b5a4-4da0ee5730f0 - - - - -] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
2016-10-11 17:42:24.989 26553 WARNING cinder.volume.manager [req-ca1e1503-51bd-4233-b5a4-4da0ee5730f0 - - - - -] Update driver status failed: (config name datastore) is uninitialized.
2016-10-11 17:42:30.373 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:33.080 26559 DEBUG oslo_service.periodic_task [req-007e0de6-468b-49f9-b8df-8c27b07173ed - - - - -] Running periodic task VolumeManager._publish_service_capabilities run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
2016-10-11 17:42:33.084 26559 DEBUG cinder.manager [req-007e0de6-468b-49f9-b8df-8c27b07173ed - - - - -] Notifying Schedulers of capabilities ... _publish_service_capabilities /usr/lib/python2.7/site-packages/cinder/manager.py:156
2016-10-11 17:42:33.091 26559 DEBUG oslo_service.periodic_task [req-007e0de6-468b-49f9-b8df-8c27b07173ed - - - - -] Running periodic task VolumeManager._report_driver_status run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213
--
2016-10-11 17:42:33.244 26559 DEBUG cinder.volume.drivers.netapp.dataontap.nfs_base [-] Image cache cleaning in progress. _clean_image_cache /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/nfs_base.py:361
2016-10-11 17:42:33.249 26559 DEBUG oslo_concurrency.lockutils [req-007e0de6-468b-49f9-b8df-8c27b07173ed - - - - -] Lock "clean_cache" released by "cinder.volume.drivers.netapp.dataontap.nfs_base._spawn_clean_cache_job" :: held 0.007s inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265
2016-10-11 17:42:33.372 26559 DEBUG cinder.volume.drivers.netapp.dataontap.nfs_base [-] Image cache cleaning done. _clean_image_cache /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/nfs_base.py:389
2016-10-11 17:42:40.378 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:42:50.379 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
2016-10-11 17:43:00.389 26553 ERROR cinder.service [-] Manager for service cinder-volume vlo-controller-p03.test.com@datastore is reporting problems, not sending heartbeat. Service will appear "down".
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Comment 6 Faiaz Ahmed 2016-10-12 01:15:00 UTC 
In addition to previous logs

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
$ egrep -E "NetApp API failed" -r .
./cinder/volume.log-20161010-2:2016-10-11 14:40:36.646 12660 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-2:2016-10-11 14:47:50.529 13317 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-2:2016-10-11 14:56:11.246 13925 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-5:2016-10-11 15:54:23.479 19546 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-5:2016-10-11 16:10:21.566 19556 ERROR cinder.volume.drivers.netapp.dataontap.nfs_cmode NaApiError: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource
./cinder/volume.log-20161010-5:2016-10-11 16:30:30.799 19556 ERROR cinder.volume.drivers.netapp.dataontap.nfs_cmode NaApiError: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource
./cinder/volume.log-20161010-5:2016-10-11 16:30:32.091 19556 ERROR cinder.volume.drivers.netapp.dataontap.nfs_cmode NaApiError: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource
./cinder/volume.log-20161010-5:2016-10-11 16:51:56.025 24300 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-3:2016-10-11 15:31:21.349 17308 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-3:2016-10-11 15:31:55.325 17472 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-4:2016-10-11 15:32:06.413 17546 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log-20161010-1:2016-10-11 14:40:02.310 12489 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log:2016-10-11 17:17:35.269 26363 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log:2016-10-11 17:20:19.763 26553 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log:2016-10-11 17:21:20.403 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
./cinder/volume.log:2016-10-11 17:22:20.404 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
./cinder/volume.log:2016-10-11 17:23:20.404 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
./cinder/volume.log:2016-10-11 17:24:20.403 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Its seems like some how NetApp failed to talk with cinder.volume.drivers due write access.
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
./cinder/volume.log-20161010-5:2016-10-11 16:30:30.799 19556 ERROR cinder.volume.drivers.netapp.dataontap.nfs_cmode NaApiError: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource
./cinder/volume.log-20161010-5:2016-10-11 16:30:32.091 19556 ERROR cinder.volume.drivers.netapp.dataontap.nfs_cmode NaApiError: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
And
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
./cinder/volume.log:2016-10-11 17:20:19.763 26553 ERROR cinder.volume.manager NaApiError: NetApp API failed. Reason - Unexpected error:unknown
./cinder/volume.log:2016-10-11 17:21:20.403 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
./cinder/volume.log:2016-10-11 17:22:20.404 26559 DEBUG cinder.volume.drivers.netapp.dataontap.client.client_cmode [-] Could not delete QOS policy groups. Details: NetApp API failed. Reason - 13003:Insufficient privileges: user 'openstack-adm' does not have write access to this resource remove_unused_qos_policy_groups /usr/lib/python2.7/site-packages/cinder/volume/drivers/netapp/dataontap/client/client_cmode.py:411
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Comment 8 Eric Harney 2016-10-12 13:03:27 UTC 
It sounds like this is not a bug and that the NetApp driver was correctly failing to initialize because it could not talk to the NetApp array due to configuration problems, causing the volume service to report as down.

Please re-open if there is reason to believe otherwise.

Thanks.