search

agoragames / haigha

AMQP Python client
BSD 3-Clause "New" or "Revised" License
160 stars 41 forks source link

Unroutable message hangs haigha in publisher confirm mode #72

Closed vitaly-krugl closed 8 years ago

vitaly-krugl commented 9 years ago

Using RabbitMQ 3.5.1; running broker and test code on the same Mac OS X Yosemite MacBookPro

import sys

from haigha.connections.rabbit_connection import RabbitConnection
from haigha.message import Message

conn = RabbitConnection(debug=2)
ch = conn.channel()

ch.confirm.select(nowait=True)

def onAck(mid):
    print >> sys.stderr, "ACK-MID:", mid
def onNack(mid):
    printt >> sys.stderr, "NACK-MID:", mid

ch.basic.set_ack_listener(onAck)
ch.basic.set_nack_listener(onNack)

ch.basic.publish(Message("abcd"), exchange="", routing_key="unroutable-no-such-queue-blah-zzz", mandatory=True)

# Hangs here
# Wait for Ack
conn.read_frames()

According to https://www.rabbitmq.com/confirms.html, this should have resulted in a basic.return from the broker, followed by basic.ack from the broker. However, onAck never gets called, and conn.read_frames() just hangs.

vitaly-krugl commented 9 years ago

There are several bugs in haigha that cause this problem, as well as additional bugs that get exposed as the result:

  1. Haigha doesn't handle basic.return correctly: it doesn't consume basic.return's header and content frames; BasicClass._recv_return() is a NO-OP; also, especially when in "publisher acknowledgements" mode, haigha needs to communicate to the user that a message was undeliverable, since basic.return(s) will, by design, precede the corresponding basic.ack. There should probably be a user callback for returned messages, just like there are user callbacks for basic.Ack and basic.Nack.
  2. Following the above problem, the rest of the frame processing logic gets confused. It expects the next frame to be method frame and tries to access its method_id, but it's actually basic.return's HeaderFrame. That triggers AttributeError

  3. The above AttributeError causes Channel.process_frames() to call Channel.close(). At this point, the basic.return's ContentFrame hasn't been processed yet. Here, haigha violates AMQP stability rule for channel.close, and doesn't discard frames other than Close and Close-Ok, so it again trips up with AttributeError when it attempts to get class_id from the basic.returns's ContentFrame. The stability rule states:

    After sending this method, any received methods except Close and Close-OK MUST be discarded. The response to receiving a Close after sending Close must be to send Close-Ok

  4. The second AttributeError causes recursion into Channel.close(). At this point, there are no more channel frames coming from the broker, so Connection.read_frames() never returns. I don't know why Close-Ok is not arriving; in fact, I would have expected to see basic.ack method frame following the basic.return sequence of frames, too.
  5. Subsequently, when I hit Ctl-C, I would have expected the KeyboardInterrupt error (derived directly from BaseException) to propagate through all the layers and out of read_frames, but instead it ends up with AttributeError: 'HeaderFrame' object has no attribute 'method_id'. See the log traces below.

I instrumented some of the connection, channel, and SocketTransport code with additional logging, and got the following instructive output:

2015-05-15 05:01:33,862 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 0, class_id: 10, method_id: 10, args: \x00\x0a\x00\x0a\x00\x09\x00\x00\x01\xb2\x0c\x63\x61\x70\x61\x62\x69\x6c\x69\x74\x69\x65\x73\x46\x00\x00\x00\xb5\x12\x70\x75\x62\x6c\x69\x73\x68\x65\x72\x5f\x63\x6f\x6e\x66\x69\x72\x6d\x73\x74\x01\x1a\x65\x78\x63\x68\x61\x6e\x67\x65\x5f\x65\x78\x63\x68\x61\x6e\x67\x65\x5f\x62\x69\x6e\x64\x69\x6e\x67\x73\x74\x01\x0a\x62\x61\x73\x69\x63\x2e\x6e\x61\x63\x6b\x74\x01\x16\x63\x6f\x6e\x73\x75\x6d\x65\x72\x5f\x63\x61\x6e\x63\x65\x6c\x5f\x6e\x6f\x74\x69\x66\x79\x74\x01\x12\x63\x6f\x6e\x6e\x65\x63\x74\x69\x6f\x6e\x2e\x62\x6c\x6f\x63\x6b\x65\x64\x74\x01\x13\x63\x6f\x6e\x73\x75\x6d\x65\x72\x5f\x70\x72\x69\x6f\x72\x69\x74\x69\x65\x73\x74\x01\x1c\x61\x75\x74\x68\x65\x6e\x74\x69\x63\x61\x74\x69\x6f\x6e\x5f\x66\x61\x69\x6c\x75\x72\x65\x5f\x63\x6c\x6f\x73\x65\x74\x01\x10\x70\x65\x72\x5f\x63\x6f\x6e\x73\x75\x6d\x65\x72\x5f\x71\x6f\x73\x74\x01\x0c\x63\x6c\x75\x73\x74\x65\x72\x5f\x6e\x61\x6d\x65\x53\x00\x00\x00\x1e\x72\x61\x62\x62\x69\x74\x40\x76\x6b\x72\x75\x67\x6c\x69\x6b\x6f\x76\x73\x2d\x4d\x61\x63\x42\x6f\x6f\x6b\x2d\x50\x72\x6f\x09\x63\x6f\x70\x79\x72\x69\x67\x68\x74\x53\x00\x00\x00\x27\x43\x6f\x70\x79\x72\x69\x67\x68\x74\x20\x28\x43\x29\x20\x32\x30\x30\x37\x2d\x32\x30\x31\x34\x20\x47\x6f\x50\x69\x76\x6f\x74\x61\x6c\x2c\x20\x49\x6e\x63\x2e\x0b\x69\x6e\x66\x6f\x72\x6d\x61\x74\x69\x6f\x6e\x53\x00\x00\x00\x35\x4c\x69\x63\x65\x6e\x73\x65\x64\x20\x75\x6e\x64\x65\x72\x20\x74\x68\x65\x20\x4d\x50\x4c\x2e\x20\x20\x53\x65\x65\x20\x68\x74\x74\x70\x3a\x2f\x2f\x77\x77\x77\x2e\x72\x61\x62\x62\x69\x74\x6d\x71\x2e\x63\x6f\x6d\x2f\x08\x70\x6c\x61\x74\x66\x6f\x72\x6d\x53\x00\x00\x00\x0a\x45\x72\x6c\x61\x6e\x67\x2f\x4f\x54\x50\x07\x70\x72\x6f\x64\x75\x63\x74\x53\x00\x00\x00\x08\x52\x61\x62\x62\x69\x74\x4d\x51\x07\x76\x65\x72\x73\x69\x6f\x6e\x53\x00\x00\x00\x05\x33\x2e\x35\x2e\x31\x00\x00\x00\x0e\x41\x4d\x51\x50\x4c\x41\x49\x4e\x20\x50\x4c\x41\x49\x4e\x00\x00\x00\x05\x65\x6e\x5f\x55\x53]
2015-05-15 05:01:33,863 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 0, class_id: 10, method_id: 30, args: \x00\x0a\x00\x1e\x00\x00\x00\x02\x00\x00\x02\x44]
2015-05-15 05:01:33,864 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 0, class_id: 10, method_id: 41, args: \x00\x0a\x00\x29\x00]
2015-05-15 05:01:33,864 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 1, class_id: 20, method_id: 11, args: \x00\x14\x00\x0b\x00\x00\x00\x00]
2015-05-15 05:01:33,865 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 1, class_id: 85, method_id: 11, args: \x00\x55\x00\x0b]
2015-05-15 05:01:33,866 - root(72021) - INFO - ZZZ dispatching frame MethodFrame[channel: 1, class_id: 60, method_id: 50, args: \x00\x3c\x00\x32\x01\x38\x08\x4e\x4f\x5f\x52\x4f\x55\x54\x45\x00\x21\x75\x6e\x72\x6f\x75\x74\x61\x62\x6c\x65\x2d\x6e\x6f\x2d\x73\x75\x63\x68\x2d\x71\x75\x65\x75\x65\x2d\x62\x6c\x61\x68\x2d\x7a\x7a\x7a]
2015-05-15 05:01:33,866 - root(72021) - INFO - ZZZ dispatching frame HeaderFrame[channel: 1, class_id: 60, weight: 0, size: 4, properties: {}]
2015-05-15 05:01:33,866 - root(72021) - ERROR - ZZZ frame dispatch exception processing frame HeaderFrame[channel: 1, class_id: 60, weight: 0, size: 4, properties: {}]
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 236, in process_frames
    self.dispatch(frame)
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 213, in dispatch
    klass.dispatch(method_frame)
  File "/Users/vkruglikov/ossdev/haigha/haigha/classes/protocol_class.py", line 77, in dispatch
    method = self.dispatch_map.get(method_frame.method_id)
AttributeError: 'HeaderFrame' object has no attribute 'method_id'
2015-05-15 05:01:33,868 - root(72021) - ERROR - ZZZ traceback:
  File "/Users/vkruglikov/Library/Python/2.7/bin/ipython", line 9, in <module>
    load_entry_point('ipython==1.1.0', 'console_scripts', 'ipython')()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/__init__.py", line 118, in start_ipython
    return launch_new_instance(argv=argv, **kwargs)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/config/application.py", line 545, in launch_instance
    app.start()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/ipapp.py", line 362, in start
    self.shell.mainloop()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 436, in mainloop
    self.interact(display_banner=display_banner)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 555, in interact
    self.run_cell(source_raw, store_history=True)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-84f91d8a6054>", line 1, in <module>
    get_ipython().magic(u'paste ')
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2172, in magic
    return self.run_line_magic(magic_name, magic_arg_s)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2093, in run_line_magic
    result = fn(*args,**kwargs)
  File "<string>", line 2, in paste
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/magic.py", line 191, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 235, in paste
    self.store_or_execute(block, name)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 97, in store_or_execute
    self.shell.run_cell(b)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-a9349a4905f8>", line 23, in <module>
    conn.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 438, in read_frames
    self._transport.process_channels(p_channels)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.py", line 40, in process_channels
    channel.process_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 247, in process_frames
    self.logger.error("ZZZ traceback:\n%s", "".join(traceback.format_stack()))

2015-05-15 05:01:33,868 - root(72021) - INFO - ZZZ dispatching frame ContentFrame[channel: 1, payload: \x61\x62\x63\x64]
2015-05-15 05:01:33,868 - root(72021) - ERROR - ZZZ frame dispatch exception processing frame ContentFrame[channel: 1, payload: \x61\x62\x63\x64]
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 236, in process_frames
    self.dispatch(frame)
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 211, in dispatch
    klass = self._class_map.get(method_frame.class_id)
AttributeError: 'ContentFrame' object has no attribute 'class_id'
2015-05-15 05:01:33,869 - root(72021) - ERROR - ZZZ traceback:
  File "/Users/vkruglikov/Library/Python/2.7/bin/ipython", line 9, in <module>
    load_entry_point('ipython==1.1.0', 'console_scripts', 'ipython')()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/__init__.py", line 118, in start_ipython
    return launch_new_instance(argv=argv, **kwargs)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/config/application.py", line 545, in launch_instance
    app.start()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/ipapp.py", line 362, in start
    self.shell.mainloop()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 436, in mainloop
    self.interact(display_banner=display_banner)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 555, in interact
    self.run_cell(source_raw, store_history=True)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-84f91d8a6054>", line 1, in <module>
    get_ipython().magic(u'paste ')
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2172, in magic
    return self.run_line_magic(magic_name, magic_arg_s)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2093, in run_line_magic
    result = fn(*args,**kwargs)
  File "<string>", line 2, in paste
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/magic.py", line 191, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 235, in paste
    self.store_or_execute(block, name)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 97, in store_or_execute
    self.shell.run_cell(b)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-a9349a4905f8>", line 23, in <module>
    conn.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 438, in read_frames
    self._transport.process_channels(p_channels)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.py", line 40, in process_channels
    channel.process_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 250, in process_frames
    self.close(500, "Failed to dispatch %s" % (str(frame)))
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 189, in close
    self.channel.close(reply_code, reply_text, class_id, method_id)
  File "/Users/vkruglikov/ossdev/haigha/haigha/classes/channel_class.py", line 128, in close
    self.channel.add_synchronous_cb(self._recv_close_ok)
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 321, in add_synchronous_cb
    self.connection.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 438, in read_frames
    self._transport.process_channels(p_channels)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.py", line 40, in process_channels
    channel.process_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 247, in process_frames
    self.logger.error("ZZZ traceback:\n%s", "".join(traceback.format_stack()))

2015-05-15 05:11:13,865 - root(72021) - ERROR - ZZZ exception from sock.recv
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/socket_transport.py", line 71, in read
    self._sock.getsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF))
timeout: timed out
2015-05-15 05:11:13,869 - root(72021) - INFO - ZZZ dispatching frame HeartbeatFrame[channel: 0]
2015-05-15 05:20:53,865 - root(72021) - ERROR - ZZZ exception from sock.recv
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/socket_transport.py", line 71, in read
    self._sock.getsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF))
timeout: timed out
2015-05-15 05:20:53,876 - root(72021) - INFO - ZZZ dispatching frame HeartbeatFrame[channel: 0]
^C2015-05-15 05:25:57,399 - root(72021) - ERROR - ZZZ exception from sock.recv
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/socket_transport.py", line 71, in read
    self._sock.getsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF))
KeyboardInterrupt
2015-05-15 05:25:57,400 - root(72021) - ERROR - ZZZ exception from trasnport.read
Traceback (most recent call last):
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 409, in read_frames
    data = self._transport.read(self._heartbeat)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/socket_transport.py", line 71, in read
    self._sock.getsockopt(socket.SOL_SOCKET, socket.SO_RCVBUF))
KeyboardInterrupt
2015-05-15 05:25:57,400 - root(72021) - ERROR - ZZZ traceback:
  File "/Users/vkruglikov/Library/Python/2.7/bin/ipython", line 9, in <module>
    load_entry_point('ipython==1.1.0', 'console_scripts', 'ipython')()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/__init__.py", line 118, in start_ipython
    return launch_new_instance(argv=argv, **kwargs)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/config/application.py", line 545, in launch_instance
    app.start()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/ipapp.py", line 362, in start
    self.shell.mainloop()
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 436, in mainloop
    self.interact(display_banner=display_banner)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 555, in interact
    self.run_cell(source_raw, store_history=True)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-84f91d8a6054>", line 1, in <module>
    get_ipython().magic(u'paste ')
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2172, in magic
    return self.run_line_magic(magic_name, magic_arg_s)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2093, in run_line_magic
    result = fn(*args,**kwargs)
  File "<string>", line 2, in paste
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/magic.py", line 191, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 235, in paste
    self.store_or_execute(block, name)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/terminal/interactiveshell.py", line 97, in store_or_execute
    self.shell.run_cell(b)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2667, in run_cell
    interactivity=interactivity, compiler=compiler)
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2777, in run_ast_nodes
    if self.run_code(code):
  File "/Users/vkruglikov/Library/Python/2.7/lib/python/site-packages/IPython/core/interactiveshell.py", line 2827, in run_code
    exec code_obj in self.user_global_ns, self.user_ns
  File "<ipython-input-16-a9349a4905f8>", line 23, in <module>
    conn.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 438, in read_frames
    self._transport.process_channels(p_channels)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.py", line 40, in process_channels
    channel.process_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 250, in process_frames
    self.close(500, "Failed to dispatch %s" % (str(frame)))
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 189, in close
    self.channel.close(reply_code, reply_text, class_id, method_id)
  File "/Users/vkruglikov/ossdev/haigha/haigha/classes/channel_class.py", line 128, in close
    self.channel.add_synchronous_cb(self._recv_close_ok)
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 321, in add_synchronous_cb
    self.connection.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 438, in read_frames
    self._transport.process_channels(p_channels)
  File "/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.py", line 40, in process_channels
    channel.process_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 250, in process_frames
    self.close(500, "Failed to dispatch %s" % (str(frame)))
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 189, in close
    self.channel.close(reply_code, reply_text, class_id, method_id)
  File "/Users/vkruglikov/ossdev/haigha/haigha/classes/channel_class.py", line 128, in close
    self.channel.add_synchronous_cb(self._recv_close_ok)
  File "/Users/vkruglikov/ossdev/haigha/haigha/channel.py", line 321, in add_synchronous_cb
    self.connection.read_frames()
  File "/Users/vkruglikov/ossdev/haigha/haigha/connection.py", line 412, in read_frames
    self.logger.error("ZZZ traceback:\n%s", "".join(traceback.format_stack()))

---------------------------------------------------------------------------
AttributeError                            Traceback (most recent call last)
<ipython-input-16-a9349a4905f8> in <module>()
     21 # Hangs here
     22 # Wait for Ack
---> 23 conn.read_frames()

/Users/vkruglikov/ossdev/haigha/haigha/connection.pyc in read_frames(self)
    436                                     self._close_info['reply_text']))
    437 
--> 438         self._transport.process_channels(p_channels)
    439 
    440         # HACK: read the buffer contents and re-buffer.  Would prefer to pass

/Users/vkruglikov/ossdev/haigha/haigha/transports/transport.pyc in process_channels(self, channels)
     38         '''
     39         for channel in channels:
---> 40             channel.process_frames()
     41 
     42     def read(self, timeout=None):

/Users/vkruglikov/ossdev/haigha/haigha/channel.py in process_frames(self)
    234                 frame = self._frame_buffer.popleft()
    235                 self.logger.info("ZZZ dispatching frame %r", frame)
--> 236                 self.dispatch(frame)
    237             except ProtocolClass.FrameUnderflow:
    238                 return

/Users/vkruglikov/ossdev/haigha/haigha/channel.py in dispatch(self, method_frame)
    211         klass = self._class_map.get(method_frame.class_id)
    212         if klass:
--> 213             klass.dispatch(method_frame)
    214         else:
    215             raise Channel.InvalidClass(

/Users/vkruglikov/ossdev/haigha/haigha/classes/protocol_class.pyc in dispatch(self, method_frame)
     75         Dispatch a method for this protocol.
     76         '''
---> 77         method = self.dispatch_map.get(method_frame.method_id)
     78         if method:
     79             callback = self.channel.clear_synchronous_cb(method)

AttributeError: 'HeaderFrame' object has no attribute 'method_id'
vitaly-krugl commented 9 years ago

NOTE that PR #73 addresses the root cause of this issue to the extent that the code in the description section succeeds.

However, it does NOT address the side-effect issues. I recommend that a new issue be created to address the bugs summarized below and described in more detail in this issues's description section and subsequent comments.

  1. the recursion of Channel.close due to violation of the stability rule that caused additional exception:

    After sending this method, any received methods except Close and Close-OK MUST be discarded. The response to receiving a Close after sending Close must be to send Close-Ok

  2. Once Connection.read_frames() became hung, when I hit Ctl-C, I would have expected the KeyboardInterrupt error (derived directly from BaseException) to propagate through all the layers and out of read_frames, but instead it ends up with AttributeError: 'HeaderFrame' object has no attribute 'method_id'. See the log traces below.

The way to reproduce these secondary issues after PR #73 is to replace the body of BasicClass._recv_return() with pass and then run the code from the description section of this issue.

vitaly-krugl commented 9 years ago

@awestendorf: PRs #73 and #74 together should fully address the primary and side-effect issues described here.

vitaly-krugl commented 8 years ago

Both #73 and #74 have been merged into master, so closing this issue.