[QPID-5700] heartbeat interleaved with message frames causes decode error

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 0.26
• Fix Version/s: 0.28, 0.29
• Component/s: Python Client
• Assignee: Gordon Sim
• Reporter: Gordon Sim
• Created: 15/Apr/14 09:18
• Updated: 03/Jun/14 15:35
• Resolved: 15/Apr/14 19:48

Description

Heartbeat controls are sent on a separate 'track' from the message transfer command and accompanying header and content segments.

The OpDecoder is fed the segments as they occur, but does not account for the possibility of interleaving of assemblies on different tracks.

Example data and exception below:

2014-04-13 04:10:21.866 3963 DEBUG qpid.messaging.io.raw [-] READ[477e7a0]: '\x0b\x01\x00\x16\x00\x01\x00\x00\x00\x00\x00\x00\x04\x01\x01\x00\x07\x00\x010\x01\x00\x0f\x00\x00\x10\x00\x00\x00\x00\x00\x00\x00\x00\x01\n\x00\x00\x03\x02\x00\x95\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00K\x04\x03\x10\x01\x08amqp/map\x00\x00\x00:\x00\x00\x00\x01\x0cqpid.subject\x95\x00&reply_9fc61f642ec14f8785ebc4ca7635b4e6\x00\x00\x006\x04\x01\x00\x03\namq.direct&reply_9fc61f642ec14f8785ebc4ca7635b4e6\x07\x03\x01\xcb\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x01\xbb\x00\x00\x00\x02\x0coslo.message\x95\x01\x94{"_unique_id": "a4b5b02a187c4313826f647627e82200", "failure": null, "result": {"binary": "nova-compute", "deleted": 0, "created_at": "2014-03-16T21:22:19.000000", "updated_at": "2014-04-13T09:10:21.862224", "report_count": 210969, "topic": "compute", "host": "nova51.rhelpoc.local", "disabled": false, "deleted_at": null, "disabled_reason": null, "id": 42}, "_msg_id": "4135f2273eb3459fbc5cba773faac851"}\x0coslo.version\x95\x00\x032.0' readable /usr/lib/python2.6/site-packages/qpid/messaging/driver.py:434
2014-04-13 04:10:21.879 3963 ERROR root [-] Unexpected exception occurred 1 time(s)... retrying.
2014-04-13 04:10:21.879 3963 TRACE root Traceback (most recent call last):
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
2014-04-13 04:10:21.879 3963 TRACE root     return infunc(*args, **kwargs)
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 698, in _consumer_thread
2014-04-13 04:10:21.879 3963 TRACE root     self.consume()
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 689, in consume
2014-04-13 04:10:21.879 3963 TRACE root     it.next()
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 606, in iterconsume
2014-04-13 04:10:21.879 3963 TRACE root     yield self.ensure(_error_callback, _consume)
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 540, in ensure
2014-04-13 04:10:21.879 3963 TRACE root     return method(*args, **kwargs)
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/nova/openstack/common/rpc/impl_qpid.py", line 597, in _consume
2014-04-13 04:10:21.879 3963 TRACE root     nxt_receiver = self.session.next_receiver(timeout=timeout)
2014-04-13 04:10:21.879 3963 TRACE root   File "<string>", line 6, in next_receiver
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py", line 665, in next_receiver
2014-04-13 04:10:21.879 3963 TRACE root     if self._ecwait(lambda: self.incoming, timeout):
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py", line 50, in _ecwait
2014-04-13 04:10:21.879 3963 TRACE root     result = self._ewait(lambda: self.closed or predicate(), timeout)
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py", line 571, in _ewait
2014-04-13 04:10:21.879 3963 TRACE root     result = self.connection._ewait(lambda: self.error or predicate(), timeout)
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py", line 214, in _ewait
2014-04-13 04:10:21.879 3963 TRACE root     self.check_error()
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/endpoints.py", line 207, in check_error
2014-04-13 04:10:21.879 3963 TRACE root     raise self.error
2014-04-13 04:10:21.879 3963 TRACE root InternalError: Traceback (most recent call last):
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/messaging/driver.py", line 667, in write
2014-04-13 04:10:21.879 3963 TRACE root     self._op_dec.write(*self._seg_dec.read())
2014-04-13 04:10:21.879 3963 TRACE root   File "/usr/lib/python2.6/site-packages/qpid/framing.py", line 269, in write
2014-04-13 04:10:21.879 3963 TRACE root     if self.op.headers is None:
2014-04-13 04:10:21.879 3963 TRACE root AttributeError: 'NoneType' object has no attribute 'headers'