Cinder

Olso messaging API error with publish_errors set to true

Bug #1346466 reported by Kurt Martin on 2014-07-21

This bug affects 2 people

Affects		Status	Importance	Assigned to	Milestone
	Cinder	Fix Released	Undecided	Flavio Percoco	Cinder 2014.2 "juno"
	oslo.messaging	Fix Released	Undecided	Tiantian Gao	oslo.messaging 1.10.0

Bug Description

I observed that when you have publish_error enabled and and the notification driver set as below:
notification_driver = cinder.openstack.common.notifier.rpc_notifier
publish_errors = true

You will get the following error when a purposely causing a error in cinder(for example, create volume from image and set the volume size something small that the image would not fit in)

2014-07-21 11:46:51.527 ERROR oslo.messaging.rpc.dispatcher [req-e3015168-bf95-4cea-af97-b13ed9edc141 231fdb65b4134c9b864767e851ad72db 5304a70aac9540a5b445cb6a6f62c917] Exception during message handling: info() takes exactly 4 arguments (3 given)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 337, in create_volume
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher _run_flow()
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 330, in _run_flow
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher flow_engine.run()
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 89, in run
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher for _state in self.run_iter():
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 130, in run_iter
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self._change_state(states.FAILURE)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/openstack/common/excutils.py", line 82, in __exit__
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/engine.py", line 120, in run_iter
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher for state in runner.run_iter(timeout=timeout):
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/runner.py", line 130, in run_iter
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher misc.Failure.reraise_if_any(failures)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 788, in reraise_if_any
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher failures[0].reraise()
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/utils/misc.py", line 795, in reraise
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher six.reraise(*self._exc_info)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/taskflow/engines/action_engine/executor.py", line 48, in _revert_task
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher result = task.revert(**kwargs)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/flows/manager/create_volume.py", line 193, in revert
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher LOG.error(_("Volume %s: create failed"), volume_id)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 1449, in error
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self.logger.error(msg, *args, **kwargs)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self._log(ERROR, msg, args, **kwargs)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self.handle(record)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self.callHandlers(record)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher hdlr.handle(record)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher self.emit(record)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher File Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 346, in fire_timers
    timer()
  File "/usr/lib/python2.7/dist-packages/eventlet/hubs/timer.py", line 56, in __call__
    cb(*args, **kw)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 197, in main
    self._resolve_links()
  File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 212, in _resolve_links
    f(self, *ca, **ckw)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/_executors/impl_eventlet.py", line 47, in complete
    thread.wait()
  File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 168, in wait
    return self._exit_event.wait()
  File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 120, in wait
    current.throw(*self._exc)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
    result = function(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 129, in <lambda>
    yield lambda: self._dispatch_and_reply(incoming)
  File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 143, in _dispatch_and_reply
    exc_info=exc_info)
  File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
    self.emit(record)
  File "/opt/stack/cinder/cinder/openstack/common/log_handler.py", line 29, in emit
    dict(error=record.msg))
TypeError: info() takes exactly 4 arguments (3 given)"/opt/stack/cinder/cinder/openstack/common/log_handler.py", line 29, in emit
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher dict(error=record.msg))
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher TypeError: info() takes exactly 4 arguments (3 given)
2014-07-21 11:46:51.527 TRACE oslo.messaging.rpc.dispatcher

I see that in /opt/stack/cinder/cinder/openstack/common/log_handler.py that that the notifier.info(...) code(line #28) is not passing in the context as the first parameter as expected in the API thus the takes 4 or 3 given error above.

rpc.get_notifier('error.publisher').info('error_notification', dict(error=record.msg))

Revision history for this message

Doug Hellmann (doug-hellmann) wrote on 2014-08-05:

Which version of cinder does this affect? The juno version should be using oslo.messaging, so you should use the logging notifier from the library instead of the incubated one.

Changed in oslo:
status:	New → Incomplete

Revision history for this message

Kurt Martin (kurt-f-martin) wrote on 2014-08-05:

Hi Doug, This occurred in Juno(trunk) around the 21st of July. Has cinder recently changed to use oslo.messaging vs the incubated version. How can I tell if I using one versus the other? The stack trace appears to be referencing oslo.messaging... Should the notification_driver be pointing to something else?
Thanks, Kurt

Revision history for this message

Kurt Martin (kurt-f-martin) wrote on 2014-08-05:

Doug this is from the cinder setup.cfg
metadata]
name = cinder
version = 2014.2
summary = OpenStack Block Storage
description-file =
    README.rst
author = OpenStack
author-email = <email address hidden>
home-page = http://www.openstack.org/
classifier =
    Environment :: OpenStack
    Intended Audience :: Information Technology
    Intended Audience :: System Administrators
    License :: OSI Approved :: Apache Software License
    Operating System :: POSIX :: Linux
    Programming Language :: Python
    Programming Language :: Python :: 2
    Programming Language :: Python :: 2.7
    Programming Language :: Python :: 2.6

[global]
setup-hooks =
pbr.hooks.setup_hook

[files]
packages =
    cinder
scripts =
    bin/cinder-all
    bin/cinder-api
    bin/cinder-backup
    bin/cinder-clear-rabbit-queues
    bin/cinder-manage
    bin/cinder-rpc-zmq-receiver
    bin/cinder-rtstool
    bin/cinder-scheduler
    bin/cinder-volume
    bin/cinder-volume-usage-audit

[entry_points]
cinder.scheduler.filters =
    AvailabilityZoneFilter = cinder.openstack.common.scheduler.filters.availability_zone_filter:AvailabilityZoneFilter
    CapabilitiesFilter = cinder.openstack.common.scheduler.filters.capabilities_filter:CapabilitiesFilter
    CapacityFilter = cinder.scheduler.filters.capacity_filter:CapacityFilter
    DifferentBackendFilter = cinder.scheduler.filters.affinity_filter:DifferentBackendFilter
    JsonFilter = cinder.openstack.common.scheduler.filters.json_filter:JsonFilter
    RetryFilter = cinder.openstack.common.scheduler.filters.ignore_attempted_hosts_filter:IgnoreAttemptedHostsFilter
    SameBackendFilter = cinder.scheduler.filters.affinity_filter:SameBackendFilter
cinder.scheduler.weights =
    AllocatedCapacityWeigher = cinder.scheduler.weights.capacity:AllocatedCapacityWeigher
    CapacityWeigher = cinder.scheduler.weights.capacity:CapacityWeigher
    ChanceWeigher = cinder.scheduler.weights.chance:ChanceWeigher
    VolumeNumberWeigher = cinder.scheduler.weights.volume_number:VolumeNumberWeigher
console_scripts =
    cinder-rootwrap = oslo.rootwrap.cmd:main
# These are for backwards compat with Havana notification_driver configuration values
oslo.messaging.notify.drivers =
    cinder.openstack.common.notifier.log_notifier = oslo.messaging.notify._impl_log:LogDriver
    cinder.openstack.common.notifier.no_op_notifier = oslo.messaging.notify._impl_noop:NoOpDriver
    cinder.openstack.common.notifier.rpc_notifier2 = oslo.messaging.notify._impl_messaging:MessagingV2Driver
    cinder.openstack.common.notifier.rpc_notifier = oslo.messaging.notify._impl_messaging:MessagingDriver
    cinder.openstack.common.notifier.test_notifier = oslo.messaging.notify._impl_test:TestDriver

[build_sphinx]
all_files = 1
build-dir = doc/build
source-dir = doc/source

[egg_info]
tag_build =
tag_date = 0
tag_svn_revision = 0

[compile_catalog]
directory = cinder/locale
domain = cinder

[update_catalog]
domain = cinder
output_dir = cinder/locale
input_file = cinder/locale/cinder.pot

[extract_messages]
keywords = _ gettext ngettext l_ lazy_gettext
mapping_file = babel.cfg
output_file = cinder/locale/cinder.pot

Doug this is from the cinder setup.cfg
metadata]
name = cinder
version = 2014.2
summary = OpenStack Block Storage
description-file =
    README.rst
author = OpenStack
author-email = openstack-dev@lists.openstack.org
home-page = http://www.openstack.org/
classifier =
    Environment :: OpenStack
    Intended Audience :: Information Technology
    Intended Audience :: System Administrators
    License :: OSI Approved :: Apache Software License
    Operating System :: POSIX :: Linux
    Programming Language :: Python
    Programming Language :: Python :: 2
    Programming Language :: Python :: 2.7
    Programming Language :: Python :: 2.6

[global]
setup-hooks =
    pbr.hooks.setup_hook

[build_sphinx]
all_files = 1
build-dir = doc/build
source-dir = doc/source

[egg_info]
tag_build = 
tag_date = 0
tag_svn_revision = 0

[compile_catalog]
directory = cinder/locale
domain = cinder

[update_catalog]
domain = cinder
output_dir = cinder/locale
input_file = cinder/locale/cinder.pot

[extract_messages]
keywords = _ gettext ngettext l_ lazy_gettext
mapping_file = babel.cfg
output_file = cinder/locale/cinder.pot

Revision history for this message

Ben Nemec (bnemec) wrote on 2014-08-06:

notification_driver = cinder.openstack.common.notifier.rpc_notifier

^ seems likely to be your problem. Now that cinder is using oslo.messaging the notification_driver needs to be the oslo.messaging one. I think that would be something like oslo.messaging.notify.notifier

Revision history for this message

Kurt Martin (kurt-f-martin) wrote on 2014-08-08:

So, I changed the notification_driver to the following:
notification_driver = oslo.messaging.notify.notifier.rpc_notifier

And I continue to get the same error as shown below, I believe this olso-messaging port commit https://review.openstack.org/#/c/71873/ that introduced this problem, with this change https://review.openstack.org/#/c/71873/24/cinder/openstack/common/log_handler.py
is the cause, so this maybe be a cinder issue with backwards compatibility as the note indicates from flapper87 in the commit

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/poll.py", line 97, in wait
    readers.get(fileno, noop).cb(fileno)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
    result = function(*args, **kwargs)
  File "/opt/stack/cinder/cinder/openstack/common/service.py", line 483, in run_service
    service.start()
  File "/opt/stack/cinder/cinder/service.py", line 107, in start
    self.manager.init_host()
  File "/opt/stack/cinder/cinder/volume/manager.py", line 211, in init_host
    {'name': self.driver.__class__.__name__})
  File "/usr/lib/python2.7/logging/__init__.py", line 1436, in error
    self.logger.error(msg, *args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1166, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1258, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1268, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1308, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 748, in handle
    self.emit(record)
  File "/opt/stack/cinder/cinder/openstack/common/log_handler.py", line 29, in emit
    dict(error=record.msg))
TypeError: info() takes exactly 4 arguments (3 given)

Doug Hellmann (doug-hellmann) on 2014-08-12

affects:

oslo → oslo.messaging

Flavio Percoco (flaper87) on 2014-08-22

Changed in oslo.messaging:
assignee:	nobody → Flavio Percoco (flaper87)

Revision history for this message

Eric Harney (eharney) wrote on 2014-08-22:

https://review.openstack.org/#/c/116330/

OpenStack Infra (hudson-openstack) on 2014-08-25

Changed in cinder:
assignee:	nobody → Flavio Percoco (flaper87)
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2014-08-29: Fix merged to cinder (master)

Reviewed: https://review.openstack.org/116330
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=dbab8843ef33e0bb6745ae3ad5951fd86446c1a3
Submitter: Jenkins
Branch: master

commit dbab8843ef33e0bb6745ae3ad5951fd86446c1a3
Author: Flavio Percoco <email address hidden>
Date: Fri Aug 22 18:33:07 2014 +0200

Pass an empty context to the notifier

    The notifier API expects a context as a first parameter. During the port
    to oslo.messaging, a bug was introduced here and the first argument in
    the notifier call was removed. This patch puts it back.

Change-Id: Id2f47757ee4af8f8c39a8a1e6b11dcad163f5b7b
Closes-bug: #1346466

Changed in cinder:
status:	In Progress → Fix Committed

Thierry Carrez (ttx) on 2014-09-04

Changed in cinder:
milestone:	none → juno-3
status:	Fix Committed → Fix Released

Thierry Carrez (ttx) on 2014-10-16

Changed in cinder:
milestone:	juno-3 → 2014.2

Revision history for this message

Tiantian Gao (gtt116) wrote on 2015-03-24:

Download full text (12.6 KiB)

This bug happen again in kilo-3.

oslo.log at commit: b9aa6120d843f09c07b20862dc0aa0958ca2aa58 ( Sat Mar 21 14:18:28 2015 +0000 )
oslo.messaging at commit: ec1fb8c76026b05d71979e2ecd1a97e97e081a7c ( Sat Mar 21 00:17:01 2015 +0000 )
nova at commit: 59356a4d80d1a9db41cc0bbc56735fd7cd742be6 ( Fri Mar 20 02:19:40 2015 +0000 )

Adding below content in nova.conf

[DEFAULT]
+ publish_errors=True
+ notification_driver=messaging

When exception happen, logging file show below content:

2015-03-24 07:33:39.752 13656 ERROR oslo_messaging.notify._impl_messaging [-] Could not send notification to notifications. Payload={'priority': 'ERROR', '_unique_id': '60d89ad0d0e24944acdb9938f768fb18', 'event_type': 'error_notification', 'timestamp': u'2015-03-24 07:33:39.044089', 'publisher_id': 'error.publisher', 'payload': {'error': u'Could not send notification to %(topic)s. Payload=%(message)s'}, 'message_id': u'ec5d699d-9f2d-4ec0-bf87-d95ad113c7d0'}
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging Traceback (most recent call last):
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo_messaging/notify/_impl_messaging.py", line 48, in notify
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo_messaging/transport.py", line 97, in _send_notification
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqpdriver.py", line 354, in send_notification
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging envelope=(version == 2.0), notify=True, retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqpdriver.py", line 315, in _send
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging rpc_amqp.pack_context(msg, context)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqp.py", line 225, in pack_context
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging context_d = six.iteritems(context.to_dict())
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging File "/usr/local/lib/python2.7/dist-packages/six.py", line 576, in iteritems
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging return iter(d.iteritems(**kw))
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging AttributeError: 'NoneType' object has no attribute 'iteritems'
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging
2015-03-24 07:33:39.758 13656 DEBUG oslo_messaging._drivers.amqp [-] UNIQUE_ID is c95728d0c835488eb07fdd289aac67e2. _add_unique_id /opt/stack/oslo.messaging/oslo_messaging/_drivers/amqp.py:264

2015-03-24 07:35:06.303 15641 ERROR oslo_messaging.notify.notifier [-] Pro...

This bug happen again in kilo-3.

Adding below content in nova.conf

[DEFAULT]
+ publish_errors=True
+ notification_driver=messaging

When exception happen, logging file show below content:

2015-03-24 07:33:39.752 13656 ERROR oslo_messaging.notify._impl_messaging [-] Could not send notification to notifications. Payload={'priority': 'ERROR', '_unique_id': '60d89ad0d0e24944acdb9938f768fb18', 'event_type': 'error_notification', 'timestamp': u'2015-03-24 07:33:39.044089', 'publisher_id': 'error.publisher', 'payload': {'error': u'Could not send notification to %(topic)s. Payload=%(message)s'}, 'message_id': u'ec5d699d-9f2d-4ec0-bf87-d95ad113c7d0'}
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging Traceback (most recent call last):
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/opt/stack/oslo.messaging/oslo_messaging/notify/_impl_messaging.py", line 48, in notify
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/opt/stack/oslo.messaging/oslo_messaging/transport.py", line 97, in _send_notification
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqpdriver.py", line 354, in send_notification
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     envelope=(version == 2.0), notify=True, retry=retry)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqpdriver.py", line 315, in _send
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     rpc_amqp.pack_context(msg, context)
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/opt/stack/oslo.messaging/oslo_messaging/_drivers/amqp.py", line 225, in pack_context
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     context_d = six.iteritems(context.to_dict())
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging   File "/usr/local/lib/python2.7/dist-packages/six.py", line 576, in iteritems
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging     return iter(d.iteritems(**kw))
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging AttributeError: 'NoneType' object has no attribute 'iteritems'
2015-03-24 07:33:39.752 13656 TRACE oslo_messaging.notify._impl_messaging 
2015-03-24 07:33:39.758 13656 DEBUG oslo_messaging._drivers.amqp [-] UNIQUE_ID is c95728d0c835488eb07fdd289aac67e2. _add_unique_id /opt/stack/oslo.messaging/oslo_messaging/_drivers/amqp.py:264

2015-03-24 07:35:06.303 15641 ERROR oslo_messaging.notify.notifier [-] Problem 'maximum recursion depth exceeded while calling a Python object' attempting to send to notification system. Payloa
d={'error': u'error calling %r: %s'}
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier Traceback (most recent call last):
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 177, in do_notify
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     ext.obj.notify(ctxt, msg, priority, retry or self.retry)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/_impl_messaging.py", line 52, in notify
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     dict(topic=topic, message=message))
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1185, in exception
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.error(msg, *args, **kwargs)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._log(ERROR, msg, args, **kwargs)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.callHandlers(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     hdlr.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.emit(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/log_handler.py", line 39, in emit
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     dict(error=record.msg))
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 256, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._notify(ctxt, event_type, payload, 'ERROR')
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 184, in _notify
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._driver_mgr.map(do_notify)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 224, in map
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._invoke_one_plugin(response.append, func, e, args, kwds)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 260, in _invoke_one_plugin
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     LOG.error('error calling %r: %s', e.name, err)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._log(ERROR, msg, args, **kwargs)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.callHandlers(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     hdlr.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.emit(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/log_handler.py", line 39, in emit
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     dict(error=record.msg))
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 256, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._notify(ctxt, event_type, payload, 'ERROR')
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 184, in _notify
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._driver_mgr.map(do_notify)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 224, in map
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._invoke_one_plugin(response.append, func, e, args, kwds)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 260, in _invoke_one_plugin
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     LOG.error('error calling %r: %s', e.name, err)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._log(ERROR, msg, args, **kwargs)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1271, in _log
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1281, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.callHandlers(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1321, in callHandlers
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     hdlr.handle(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 749, in handle
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self.emit(record)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/log_handler.py", line 39, in emit
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     dict(error=record.msg))
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 256, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._notify(ctxt, event_type, payload, 'ERROR')
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/opt/stack/oslo.messaging/oslo_messaging/notify/notifier.py", line 184, in _notify
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._driver_mgr.map(do_notify)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 224, in map
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._invoke_one_plugin(response.append, func, e, args, kwds)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/local/lib/python2.7/dist-packages/stevedore/extension.py", line 260, in _invoke_one_plugin
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     LOG.error('error calling %r: %s', e.name, err)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1178, in error
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     self._log(ERROR, msg, args, **kwargs)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1270, in _log
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier   File "/usr/lib/python2.7/logging/__init__.py", line 1244, in makeRecord
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier     rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier RuntimeError: maximum recursion depth exceeded while calling a Python object
2015-03-24 07:35:06.303 15641 TRACE oslo_messaging.notify.notifier

Changed in oslo.messaging:
status:	Incomplete → Confirmed

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-03-24: Fix proposed to oslo.messaging (master)

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

Changed in oslo.messaging:
assignee:	Flavio Percoco (flaper87) → Tiantian Gao (gtt116)
status:	Confirmed → In Progress

Revision history for this message

Tiantian Gao (gtt116) wrote on 2015-03-24:

#10

The pretty logging pasted here:

http://paste.openstack.org/show/195811/

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2015-03-30: Fix merged to oslo.messaging (master)

#11

Reviewed: https://review.openstack.org/167130
Committed: https://git.openstack.org/cgit/openstack/oslo.messaging/commit/?id=fb8c431ad6c7dd663ec1f251f55ba73067c3b6f5
Submitter: Jenkins
Branch: master

commit fb8c431ad6c7dd663ec1f251f55ba73067c3b6f5
Author: gtt116 <email address hidden>
Date: Tue Mar 24 07:43:34 2015 +0000

Make notify driver messaging play well with publish_errors

When publish_errors is True, and using `messaging` notify driver,
produces a infinite loop that report sending notification error.

    The reason is we always passing None to the content argument in
    logger handlers (LoggingNotificationHandler, LoggingErrorNotificationHandler),
    when pack the context object which expected as a dict, raise TypeError
    exception, so result in infinite retry looping.

To match what document said, passing a empty dict rather than None. Also
modify unittests to make sure context is a empty dict.

Change-Id: Ic2c4c43f5bbafa8107ea370ba959da16cfa4a24c
Closes-bug: #1346466

Changed in oslo.messaging:
status:	In Progress → Fix Committed

Doug Hellmann (doug-hellmann) on 2015-04-21

Changed in oslo.messaging:
milestone:	none → 1.10.0
status:	Fix Committed → Fix Released

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.