dapper91 / pjrpc

python json-rpc client/server without boilerplate
https://pjrpc.readthedocs.io
The Unlicense
30 stars 3 forks source link

Sudden hang when examples/kombu_server.py and kombu_client.py communicate. #66

Closed bernhardkaindl closed 2 years ago

bernhardkaindl commented 2 years ago

When examples/kombu_server.py and kombu_client.py communicate, the communication suddenly stops:

while true;do python examples/kombu_client.py;echo;sleep 1;done

After a few iterations of the loop, the client no longer prints the output of the sum(1,2) RPC calls.

DEBUG:amqp:Start from server, version: 0.9, properties: {'capabilities': {'publisher_confirms': True, 'exchange_exchange_bindings': True, 'basic.nack': True, 'consumer_cancel_notify': True, 'connection.blocked': True, 'consumer_priorities': True, 'authentication_failure_close': True, 'per_consumer_qos': True, 'direct_reply_to': True}, 'cluster_name': 'rabbit@sf314', 'copyright': 'Copyright (c) 2007-2022 VMware, Inc. or its affiliates.', 'information': 'Licensed under the MPL 2.0. Website: https://rabbitmq.com', 'platform': 'Erlang/OTP 24.2.2', 'product': 'RabbitMQ', 'version': '3.9.13'}, mechanisms: [b'AMQPLAIN', b'PLAIN'], locales: ['en_US']
DEBUG:amqp:using channel_id: 1
DEBUG:amqp:Channel open
1 + 2 = 3

I see in the rabbitmq log that server and client stay connected, but the client does not continue sending requests:

In the kombu_server log, I see that the server sends the response for the sum method, but the client does not have any logger calls about sending requests or receiving responses.

This is with a kombu_client.py which requests one sum(1,2) and sends one tick(). The tick after the sum is not received:

DEBUG:pjrpc.server.request:request received: {"jsonrpc": "2.0", "method": "sum", "id": 1, "params": [1, 2]}
DEBUG:pjrpc.server.response:response sent: {"jsonrpc": "2.0", "id": 1, "result": 3}
DEBUG:pjrpc.server.request:request received: {"jsonrpc": "2.0", "method": "tick"}
received tick
DEBUG:pjrpc.server.request:request received: {"jsonrpc": "2.0", "method": "sum", "id": 1, "params": [1, 2]}
DEBUG:pjrpc.server.response:response sent: {"jsonrpc": "2.0", "id": 1, "result": 3}
DEBUG:amqp.connection.Connection.heartbeat_tick:heartbeat_tick : for connection 658eb70988e8400d9bdfb55a26b12b35
DEBUG:amqp.connection.Connection.heartbeat_tick:heartbeat_tick : for connection 658eb70988e8400d9bdfb55a26b12b35
DEBUG:amqp.connection.Connection.heartbeat_tick:heartbeat_tick : for connection 658eb70988e8400d9bdfb55a26b12b35

The server still receives heartbeats and and answers to other clients.

Just a suggestion / hint for diagnosis: I think logging of requests and responses shoud be added to the kombu client to aid in tracing, and

logging.basicConfig(level=logging.DEBUG)

should be added to server and client: For kombu, the even the debug logging is not too verbose.

dapper91 commented 2 years ago

I did some research and found out that kombu client creates a response queue implicitly after a request has been sent to the server. If the server finishes handling the request before the response queue is created then the response message will be lost. In such case the client hangs forever waiting for the response from the server.

The bug is fixed in https://github.com/dapper91/pjrpc/pull/76