oslo notify dispatcher, unexpected keyword argument

Bug #1360696 reported by Harm Weites
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Designate
Fix Released
High
Kiall Mac Innes

Bug Description

Hi,

Sink is reporting the following error upon instance creation, the TypeError is also printed an awful lot of times before receiving this message:

2014-08-23 23:16:45.213 32698 DEBUG oslo.messaging._drivers.amqpdriver [-] received {u'_context_roles': [u'admin', u'_member_'], u'_context_request_id': u'req-fcdf0b7d-9ce7-4a4c-96ad-fe93dc8b497b', u'_context_read_deleted': u'no', u'event_type': u'port.create.end', u'_context_user_name': u'quantum', u'_context_project_name': u'service', u'timestamp': u'2014-08-23 21:16:45.146723', u'_context_tenant_id': u'1882fcb652104a85b836cb9ad426ac0e', u'_context_tenant': u'1882fcb652104a85b836cb9ad426ac0e', u'message_id': u'57193147-fb89-4f0b-8f42-44203122afcf', u'_unique_id': u'365f0e179cec473a89a45cd62b893070', u'_context_is_admin': True, u'_context_timestamp': u'2014-08-23 21:16:44.588184', u'_context_project_id': u'1882fcb652104a85b836cb9ad426ac0e', u'_context_tenant_name': u'service', u'_context_user': u'97bd6db2672d4c0d93e22f2bacf61b7f', u'_context_user_id': u'97bd6db2672d4c0d93e22f2bacf61b7f', u'publisher_id': u'network.bruticus.dummy.net', u'payload': {u'port': {u'status': u'DOWN', u'binding:host_id': u'devastator.dummy.net', u'name': u'', u'allowed_address_pairs': [], u'admin_state_up': True, u'network_id': u'65c863c2-039d-4201-a20f-f0ff446b3eed', u'tenant_id': u'04826ef02a00466da4af5e70ddc67038', u'binding:vif_details': {u'port_filter': True, u'ovs_hybrid_plug': True}, u'binding:vnic_type': u'normal', u'binding:vif_type': u'ovs', u'device_owner': u'compute:None', u'mac_address': u'fa:16:3e:fa:3e:1e', u'binding:profile': {}, u'fixed_ips': [{u'subnet_id': u'9c3b0082-3344-4cf7-808b-db841da8833c', u'ip_address': u'192.168.168.10'}, {u'subnet_id': u'3e818cd7-2eb7-4b7e-8628-3b73d00d1d01', u'ip_address': u'2001:470:d2a7:dead::5'}], u'id': u'f9cbdf0a-9871-4db7-93bf-2b789df42c43', u'security_groups': [u'41218df0-78f9-4b08-b69a-ab0bd98851af'], u'device_id': u'3ab6ddfb-e8ea-4edb-821c-89b9941fbab0'}}, u'priority': u'INFO'} _safe_log /usr/lib/python2.6/site-packages/oslo/messaging/_drivers/common.py:290
2014-08-23 23:16:45.217 32698 DEBUG oslo.messaging._drivers.amqp [-] unpacked context: {'tenant': u'1882fcb652104a85b836cb9ad426ac0e', 'project_name': u'service', 'user_id': u'97bd6db2672d4c0d93e22f2bacf61b7f', 'roles': [u'admin', u'_member_'], 'tenant_id': u'1882fcb652104a85b836cb9ad426ac0e', 'timestamp': u'2014-08-23 21:16:44.588184', 'is_admin': True, 'user': u'97bd6db2672d4c0d93e22f2bacf61b7f', 'request_id': u'req-fcdf0b7d-9ce7-4a4c-96ad-fe93dc8b497b', 'tenant_name': u'service', 'project_id': u'1882fcb652104a85b836cb9ad426ac0e', 'user_name': u'quantum', 'read_deleted': u'no'} _safe_log /usr/lib/python2.6/site-packages/oslo/messaging/_drivers/common.py:290
2014-08-23 23:16:45.220 32698 ERROR oslo.messaging.notify.dispatcher [-] Exception during message handling
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher Traceback (most recent call last):
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/notify/dispatcher.py", line 85, in _dispatch_and_handle_error
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher return self._dispatch(incoming.ctxt, incoming.message)
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher File "/usr/lib/python2.6/site-packages/oslo/messaging/notify/dispatcher.py", line 101, in _dispatch
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher ctxt = self.serializer.deserialize_context(ctxt)
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher File "/usr/lib/python2.6/site-packages/designate/rpc.py", line 172, in deserialize_context
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher return designate.context.DesignateContext.from_dict(context)
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher File "/usr/lib/python2.6/site-packages/designate/context.py", line 78, in from_dict
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher return cls(**values)
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher TypeError: __init__() got an unexpected keyword argument 'read_deleted'
2014-08-23 23:16:45.220 32698 TRACE oslo.messaging.notify.dispatcher

So Oslo unpacked the above and shows this:

2014-08-23 23:16:45.217 32698 DEBUG oslo.messaging._drivers.amqp [-] unpacked context: {'tenant': u'1882fcb652104a85b836cb9ad426ac0e', 'project_name': u'service', 'user_id': u'97bd6db2672d4c0d93e22f2bacf61b7f', 'roles': [u'admin', u'_member_'], 'tenant_id': u'1882fcb652104a85b836cb9ad426ac0e', 'timestamp': u'2014-08-23 21:16:44.588184', 'is_admin': True, 'user': u'97bd6db2672d4c0d93e22f2bacf61b7f', 'request_id': u'req-fcdf0b7d-9ce7-4a4c-96ad-fe93dc8b497b', 'tenant_name': u'service', 'project_id': u'1882fcb652104a85b836cb9ad426ac0e', 'user_name': u'quantum', 'read_deleted': u'no'} _safe_log /usr/lib/python2.6/site-packages/oslo/messaging/_drivers/common.py:290

And here we can clearly see the keyword: 'read_deleted': u'no'

I'm guessing it should never bail on these sort of things, though at the same time I don't know -what- this kind of thing actually is :) I was hoping Designate would have added some records to some zone and in the process of exploring the configuration and such, this started showing up.

This is on an Icehouse deployment.

Revision history for this message
Harm Weites (harmw) wrote :

hm, weird... After removing the read_deleted key it fails with the next key in the list:

TypeError: __init__() got an unexpected keyword argument 'project_name'

Revision history for this message
Harm Weites (harmw) wrote :

Great, after reverting from 2014.1.2b2 to the icehouse-stable tarball designate-sink is not picking up anything from Rabbit anymore...

Revision history for this message
Harm Weites (harmw) wrote :

Digging a little further, back at 2014.2.b2:

This is what's inside ctxt:
"""
 'read_deleted': u'no',i
 'project_name': u'wts',
 'user_id': u'30f8cf93273345d1b7dc4e22da05536d',
 'roles': [u'admin', u'_member_'],
 'tenant_id': u'04826ef02a00466da6af5e70ddc67038',
 'request_id': u'req-652a0d29-5c04-452e-84d0-5de80dbeffef',
 'is_admin': True,
 'user': u'30f8cf9a273345d1b7dc4e22da05536d',
 'timestamp': u'2014-08-30 21:11:03.794764',
 'tenant_name': u'wts',
 'project_id': u'04826ef02a00466dcdaf5e70ddc67038',
 'user_name': u'master',
 'tenant': u'04826ef02a00466da4af9e70ddc67038'
"""
A number of these are indeed not in class DesignateContext()'s __init__(), so I'm wondering if this is something within Designate or simply my Icehouse setup thats not compatible.

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to designate (master)

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

Changed in designate:
assignee: nobody → Kiall Mac Innes (kiall)
status: New → In Progress
Kiall Mac Innes (kiall)
Changed in designate:
milestone: none → juno-3
importance: Undecided → High
Revision history for this message
Harm Weites (harmw) wrote :
Changed in designate:
status: In Progress → Fix Committed
Revision history for this message
Kiall Mac Innes (kiall) wrote :

Not quite comitted yet ;)

Changed in designate:
status: Fix Committed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to designate (master)

Reviewed: https://review.openstack.org/118060
Committed: https://git.openstack.org/cgit/openstack/designate/commit/?id=0997eec4158e8055ac95eb5b5011d8bef317b418
Submitter: Jenkins
Branch: master

commit 0997eec4158e8055ac95eb5b5011d8bef317b418
Author: Kiall Mac Innes <email address hidden>
Date: Sun Aug 31 20:58:57 2014 +0100

    Received notifications context is not a DesignateContext

    Nova/Neutron's notifcations context contains fields which we do not
    know how to handle in DesignateContext. We should treat received
    context's as simple dict's rather than attempting to munge into
    a DesignateContext.

    Change-Id: Ieda187679171333be69e98d6301c64a14187a5d7
    Closes-Bug: 1360696

Changed in designate:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in designate:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in designate:
milestone: juno-3 → 2014.2
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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