Description of problem: ----------------------- After minor update of RHOS-11 tempest tests started to fail. In cinder/scheduler.log next traceback present: 2017-03-16 15:33:55.845 290408 WARNING cinder.scheduler.manager [req-3ec34de1-b47c-4cde-a578-8a25055ad933 - - - - -] Task 'cinder.scheduler.flows.create_volume.ScheduleCreateVolumeTask;volume:create' (23668235-f 3c1-49a5-84a5-cebb6a2e0c1b) transitioned into state 'FAILURE' from state 'RUNNING' 2 predecessors (most recent first): Atom 'cinder.scheduler.flows.create_volume.ExtractSchedulerSpecTask;volume:create' {'intention': 'EXECUTE', 'state': 'SUCCESS', 'requires': {'volume': Volume(_name_id=None,admin_metadata=<?>,attach_status='det ached',availability_zone='nova',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2017-03-16T15:33:55Z,deleted=False,deleted_at=None,display_description=None,d isplay_name='tempest-TestVolumeBootPattern-volume-origin-572933441',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host=None,id=13e66533-18d9-4652-8727-c131bbf2e25d,launched_at=No ne,metadata={},migration_status=None,multiattach=False,previous_status=None,project_id='fdda37a061c04e6db4a370f07d576afd',provider_auth=None,provider_geometry=None,provider_id=None,provider_location=None,replica tion_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=None,size=1,snapshot_id=None,snapshots=<?>,source_volid=None,status='error',terminated_at=None,updated_at=None,user_id= '66f1853a846c42eda2770d027e16cc04',volume_attachment=<?>,volume_type=<?>,volume_type_id=None), 'image_id': u'f5786c35-8b03-4a4c-ac47-e74ebd68eea8', 'request_spec': RequestSpec(CG_backend=<?>,cgsnapshot_id=None,c onsistencygroup_id=None,group_backend=<?>,group_id=None,image_id=f5786c35-8b03-4a4c-ac47-e74ebd68eea8,snapshot_id=None,source_replicaid=None,source_volid=None,volume=Volume(13e66533-18d9-4652-8727-c131bbf2e25d), volume_id=13e66533-18d9-4652-8727-c131bbf2e25d,volume_properties=VolumeProperties,volume_type=None), 'context': <cinder.context.RequestContext object at 0x6ca7990>, 'snapshot_id': None}, 'provides': {'request_sp ec': RequestSpec(CG_backend=<?>,cgsnapshot_id=None,consistencygroup_id=None,group_backend=<?>,group_id=None,image_id=f5786c35-8b03-4a4c-ac47-e74ebd68eea8,snapshot_id=None,source_replicaid=None,source_volid=None, volume=Volume(13e66533-18d9-4652-8727-c131bbf2e25d),volume_id=13e66533-18d9-4652-8727-c131bbf2e25d,volume_properties=VolumeProperties,volume_type=None)}} |__Flow 'volume_create_scheduler' 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager Traceback (most recent call last): 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 53, in _execute_task 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager result = task.execute(**arguments) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/flows/create_volume.py", line 142, in execute 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager common.error_out(volume, reason=e) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__ 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager self.force_reraise() 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager six.reraise(self.type_, self.value, self.tb) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/flows/create_volume.py", line 124, in execute 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager filter_properties) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/filter_scheduler.py", line 109, in schedule_create_volume 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager backend = self._schedule(context, request_spec, filter_properties) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/filter_scheduler.py", line 620, in _schedule 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager filter_properties) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/filter_scheduler.py", line 343, in _get_weighted_candidates 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager filter_properties) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/host_manager.py", line 449, in get_filtered_backends 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager filter_classes = self._choose_backend_filters(filter_class_names) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager File "/usr/lib/python2.7/site-packages/cinder/scheduler/host_manager.py", line 415, in _choose_backend_filters 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager filter_name=", ".join(bad_filters)) 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager SchedulerHostFilterNotFound: Scheduler Host Filter AvailabilityZoneFilter, CapacityFilter, CapabilitiesFilter could not be found. 2017-03-16 15:33:55.845 290408 ERROR cinder.scheduler.manager 2017-03-16 15:33:55.848 290408 DEBUG cinder.scheduler.manager [req-3ec34de1-b47c-4cde-a578-8a25055ad933 - - - - -] Task 'cinder.scheduler.flows.create_volume.ScheduleCreateVolumeTask;volume:create' (23668235-f3c 1-49a5-84a5-cebb6a2e0c1b) transitioned into state 'REVERTING' from state 'FAILURE' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194 Version-Release number of selected component (if applicable): ------------------------------------------------------------- openstack-cinder-10.0.1-0.20170308012116.a7521f5.el7ost.noarch python-cinderclient-1.11.0-0.20170208174522.7d140d0.el7ost.noarch puppet-cinder-10.3.0-1.el7ost.noarch python-cinder-10.0.1-0.20170308012116.a7521f5.el7ost.noarch Steps to Reproduce: 1. Deploy RHOS-11 (build 2017-03-08.3) 2. Setup latest repos 3. Update undercloud 4. Update overcloud 5. Run tempest: ostester -p -r tempest.api.volume.admin Actual results: --------------- Failed tests. Traceback in log
This bugzilla has been removed from the release and needs to be reviewed and Triaged for another Target Release.
It appears that this error: "SchedulerHostFilterNotFound: Scheduler Host Filter AvailabilityZoneFilter, CapacityFilter, CapabilitiesFilter could not be found." comes from something at the python level that prevents these filters from loading correctly. (Missing dependencies, syntax error, etc.) I've reproduced this on my machine by intentionally breaking code in a filter, but Cinder does not log anything useful in this situation.
I'm not sure what is broken in your deployment, but this should tell us: Please uncomment "default_log_levels" in your cinder.conf on the node where the scheduler is erroring, and set it so that it contains "stevedore=DEBUG". This should result in something like: default_log_levels = amqp=WARN,amqplib=WARN,boto=WARN,qpid=WARN,sqlalchemy=WARN,suds=INFO,oslo.messaging=INFO,iso8601=WARN,requests.packages.urllib3.connectionpool=WARN,urllib3.connectionpool=WARN,websocket=WARN,requests.packages.urllib3.util.retry=WARN,urllib3.util.retry=WARN,keystonemiddleware=WARN,routes.middleware=WARN,stevedore=DEBUG,taskflow=INFO,keystoneauth=WARN,oslo.cache=INFO,dogpile.core.dogpile=INFO Then, restart openstack-cinder-scheduler, and look at the log. I believe the errors will be present without sending any requests, but they may be right at the beginning of the log, before lots of other output. In my staged failure, this resulted in an error like this: 2017-03-16 14:40:45.248 31351 DEBUG stevedore.extension [req-21652eae-7682-4913-a877-1283aba5a234 - - - - -] found extension EntryPoint.parse('CapabilitiesFilter = cinder.scheduler.filters.capabilities_filter:CapabilitiesFilter') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:157 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension [req-21652eae-7682-4913-a877-1283aba5a234 - - - - -] Could not load 'CapabilitiesFilter': No module named asldkfjalksdfnklsdnfklsndflskdf 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension Traceback (most recent call last): 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension File "/usr/lib/python2.7/site-packages/stevedore/extension.py", line 163, in _load_plugins 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension verify_requirements, 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension File "/usr/lib/python2.7/site-packages/stevedore/extension.py", line 193, in _load_one_plugin 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension plugin = ep.load(require=verify_requirements) 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension File "/usr/lib/python2.7/site-packages/pkg_resources.py", line 2260, in load 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension entry = __import__(self.module_name, globals(),globals(), ['__name__']) 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension File "/usr/lib/python2.7/site-packages/cinder/scheduler/filters/capabilities_filter.py", line 21, in <module> 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension import asldkfjalksdfnklsdnfklsndflskdf 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension ImportError: No module named asldkfjalksdfnklsdnfklsndflskdf 2017-03-16 14:40:45.250 31351 ERROR stevedore.extension
Hi Eric, Looks like some sort of misconfiguration/race condition. Restarting services and re-running tempest succeeded. I'll re-open bz if this occurs again. Thanks!
Enabling logging on stevedore didn't provide any additional information, as there were no errors there, so I manually modified stevedore's "stevedore.extension.ExtensionManager:list_entry_points" and setuptools' "pkg_resources:iter_entry_points" to see what was really going on after the update. Results is that stevedore as expected does not have the "cinder.scheduler.filters" entrypoints in the cache and calls pkg_resources to iterate through the entry points from group "cinder.scheduler.filters", and here's the surprise, setuptools can't find any entrypoints on the cinder 10.0.3, therefore there's nothing for stevedore to load. Same thing happens with the cinder weighers, no entry points are found. These were the relevant log entries that illustrate this: 2018-01-29 12:26:01.636 212830 INFO stevedore.extension [-] Getting cinder.scheduler.filters entrypoints 2018-01-29 12:26:01.637 212830 INFO pkg_resources [-] Reading entries for group cinder.scheduler.filters and name None 2018-01-29 12:26:01.681 212830 INFO pkg_resources [-] Entries for cinder 10.0.3 are {} 2018-01-29 12:26:01.688 212830 INFO stevedore.extension [-] Entrypoints for cinder.scheduler.filters entrypoints are: [] In my opinion this points in the direction of the RPM and setuptools more than Cinder itself.
OSP11 is now retired, see details at https://access.redhat.com/errata/product/191/ver=11/rhel---7/x86_64/RHBA-2018:1828