Cinder service not logging exceptions from stevedore library

[Cian O'Driscoll]

After upgrading my cinder-scheduler service, I tried to create a volume and got the following exception

2013-02-21 17:51:29.538 WARNING cinder.scheduler.manager [req-1e82836e-f811-4698-9674-e884955f3c23 51544779289768 44926822131636] Failed to schedule_create_volume: Scheduler Host Filter AvailabilityZoneFilter could not be found.
2013-02-21 17:51:29.571 1362 ERROR cinder.openstack.common.rpc.amqp [-] Exception during message handling
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py", line 275, in _process_data
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/dispatcher.py", line 145, in dispatch
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/manager.py", line 115, in create_volume
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp context, ex, request_spec)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp self.gen.next()
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/manager.py", line 104, in create_volume
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp filter_properties)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/filter_scheduler.py", line 67, in schedule_create_volume
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp filter_properties)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/filter_scheduler.py", line 204, in _schedule
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp filter_properties)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/host_manager.py", line 224, in get_filtered_hosts
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp filter_classes = self._choose_host_filters(filter_class_names)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/dist-packages/cinder/scheduler/host_manager.py", line 191, in _choose_host_filters
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp raise exception.SchedulerHostFilterNotFound(filter_name=msg)
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp SchedulerHostFilterNotFound: Scheduler Host Filter AvailabilityZoneFilter could not be found.
2013-02-21 17:51:29.571 1362 TRACE cinder.openstack.common.rpc.amqp

This however wasn't the real exception being thrown. The real exception was in the python-stevedore lib but because the cinder scheduler service was ignoring the log from this library it never got printed to log.

I'd edited the following line to get cinder to handle the stevedore logs and got the real exception

import logging

- LOG = logging.getLogger("__name__)
+ LOG = logging.getLogger("cinder.%s" % __name__)

After change:

2013-02-21 18:05:51.050 13533 ERROR cinder.stevedore.extension [-] Could not load 'CapacityWeigher': rtslib>=2.1.fb27
2013-02-21 18:05:51.050 13533 ERROR cinder.stevedore.extension [-] rtslib>=2.1.fb27
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension Traceback (most recent call last):
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension File "/usr/lib/python2.7/dist-packages/stevedore/extension.py", line 75, in _load_plugins
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension invoke_kwds,
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension File "/usr/lib/python2.7/dist-packages/stevedore/extension.py", line 87, in _load_one_plugin
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension plugin = ep.load()
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 1988, in load
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension if require: self.require(env, installer)
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 2001, in require
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension working_set.resolve(self.dist.requires(self.extras),env,installer))
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension File "/usr/lib/python2.7/dist-packages/pkg_resources.py", line 584, in resolve
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension raise DistributionNotFound(req)
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension DistributionNotFound: rtslib>=2.1.fb27
2013-02-21 18:05:51.050 13533 TRACE cinder.stevedore.extension

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/24289

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/24289
Committed: http://github.com/openstack/cinder/commit/2b66a382aae3e1c80342feb32549c427677d39c6
Submitter: Jenkins
Branch: master

commit 2b66a382aae3e1c80342feb32549c427677d39c6
Author: Zhiteng Huang <email address hidden>
Date: Wed Mar 13 13:58:27 2013 +0800

    Pull Oslo log fix to enable root logger initialization

    Previous log module in Oslo doesn't initialize root logger, which results
    in lacking of log message for non-openstack library (such as stevedore).
    This patch pull latest log module from Oslo, which has recently merged a
    change to enable root logger initialization.

    Notice that this change also includes one log modules fix in Oslo which
    'unignore' log_format setting. As a result, one may experience log format
    change when using devstack. To get old log format back, simply assign
    a NULL string (aka nothing) to 'log_format' configure option in cinder.conf.
    For example, just append cinder.conf with one new line 'log_format = '.

    Fix bug: # 1131322

    Change-Id: I86396f15ca152512ce6d18d6d424a855b27f495e

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: milestone-proposed
Review: https://review.openstack.org/25106

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/25106
Committed: http://github.com/openstack/cinder/commit/6af4d65e975366b4a0df3bc41ae531eafe5e14b7
Submitter: Jenkins
Branch: milestone-proposed

commit 6af4d65e975366b4a0df3bc41ae531eafe5e14b7
Author: Zhiteng Huang <email address hidden>
Date: Wed Mar 13 13:58:27 2013 +0800

    Pull Oslo log fix to enable root logger initialization

    Previous log module in Oslo doesn't initialize root logger, which results
    in lacking of log message for non-openstack library (such as stevedore).
    This patch pull latest log module from Oslo, which has recently merged a
    change to enable root logger initialization.

    Notice that this change also includes one log modules fix in Oslo which
    'unignore' log_format setting. As a result, one may experience log format
    change when using devstack. To get old log format back, simply assign
    a NULL string (aka nothing) to 'log_format' configure option in cinder.conf.
    For example, just append cinder.conf with one new line 'log_format = '.

    Fix bug: # 1131322

    Change-Id: I86396f15ca152512ce6d18d6d424a855b27f495e
    (cherry picked from commit 2b66a382aae3e1c80342feb32549c427677d39c6)

[Brian Cline (briancline)]

I'm still seeing this issue using the latest packages on a clean 12.04.2 LTS system, but I'm getting the same exception as above, with no further details as to which packages may be missing.

I've verified that python-stevedore 0.8-2 is installed (the updated package built by jdanjou). I've also verified that the actual installed code for cinder affected by the above patch is actually the patched version.

Is there any way I can determine the cause of this message in this case?

Full exception and cinder config are here: https://gist.github.com/briancline/5428045

[Cian O'Driscoll (dricco)]

Hi Brian,

The real exception is thrown on service startup. Can you tail the scheduler log and restart the service and see if you can see what package is missing.

Thanks,
Cian