search

Azure / azure-uamqp-python

AMQP 1.0 client library for Python
MIT License
57 stars 47 forks source link

Connection in an unexpected error state with Solace Broker #52

Open hbsis-fernandomedeiros opened 5 years ago

hbsis-fernandomedeiros commented 5 years ago

Hi there,

I've been trying to use uAMQP for Python with a Solace Standard broker running in a local container - Nothing too complex, just the samples provided in this repository. No success so far, although I have a topic and queue set up. I rose the logging level to DEBUG, and it seems to be some issue related to DETACH frame in link protocol - but I'm out of ideas... any idea what could it possibly be? It would be much appreciated :)

Here's the log:

$ python send.py 
DEBUG:uamqp.c_uamqp:Creating SASL Mechanism 
DEBUG:uamqp.client:Opening client connection.  
DEBUG:uamqp:Initializing platform. 
INFO:uamqp.connection:Connection b'17f16ec1-306e-4046-ab48-8b21cfe8bdc9' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0> 
DEBUG:uamqp.c_uamqp:Wrapping value type: <AMQPType.CompositeType: 22>  
DEBUG:uamqp.c_uamqp:Wrapping value type: <AMQPType.CompositeType: 22>  
INFO:uamqp.sender:Message sender b'sender-link-af42104a-114a-48b1-a97c-b7bcab34c21e' state changed from <MessageSenderState.Idle: 0> to <MessageSenderState.Opening: 1> on  connection: b'17f16ec1-306e-4046-ab48-8b21cfe8bdc9' 
INFO:uamqp.connection:Connection b'17f16ec1-306e-4046-ab48-8b21cfe8bdc9' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0> 
INFO:uamqp.connection:Connection b'17f16ec1-306e-4046-ab48-8b21cfe8bdc9' state changed from <ConnectionState.START: 0> to <ConnectionState.END: 13>  
INFO:uamqp.connection:Connection with ID b'17f16ec1-306e-4046-ab48-8b21cfe8bdc9' unexpectedly in an error state. Closing: False, Error: None
INFO:uamqp.sender:Sender link failed to open - expecting to receive DETACH frame.  
WARNING:uamqp.connection:ConnectionClose('ErrorCodes.UnknownError: Connection in an unexpected error state.') 
Traceback (most recent call last): 
  File "send.py", line 39, in <module>
 uamqp_receive_simple()
  File "send.py", line 35, in uamqp_receive_simple
 cliente.send_message(Message(body=msg_content))  
  File "C:\Python37\lib\site-packages\uamqp\client.py", line 694, in send_message  
 running = self.do_work() 
  File "C:\Python37\lib\site-packages\uamqp\client.py", line 377, in do_work 
 if not self.client_ready(): 
  File "C:\Python37\lib\site-packages\uamqp\client.py", line 362, in client_ready  
 self._connection.work()  
  File "C:\Python37\lib\site-packages\uamqp\connection.py", line 252, in work
 raise self._error  
uamqp.errors.ConnectionClose: ErrorCodes.UnknownError: Connection in an unexpected error state.
DEBUG:uamqp.c_uamqp:Deallocating cMessage
DEBUG:uamqp.c_uamqp:Destroying cMessage  
DEBUG:uamqp.c_uamqp:Deallocating cTarget 
DEBUG:uamqp.c_uamqp:Destroying cTarget
DEBUG:uamqp.c_uamqp:Deallocating 'StringValue' 
DEBUG:uamqp.c_uamqp:Destroying 'StringValue'
DEBUG:uamqp.c_uamqp:Deallocating 'CompositeValue' 
DEBUG:uamqp.c_uamqp:Destroying 'CompositeValue'
DEBUG:uamqp.c_uamqp:Deallocating 'CompositeValue' 
DEBUG:uamqp.c_uamqp:Destroying 'CompositeValue'
DEBUG:uamqp.c_uamqp:Deallocating XIO  
DEBUG:uamqp.c_uamqp:Destroying XIO 
DEBUG:uamqp.c_uamqp:Deallocating SASLMechanism 
DEBUG:uamqp.c_uamqp:Destroying SASLMechanism
DEBUG:uamqp.c_uamqp:Deallocating XIO  
DEBUG:uamqp.c_uamqp:Destroying XIO 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
INFO:uamqp.c_uamqp:b'send called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_send_async':1181) 
INFO:uamqp.c_uamqp:b'Cannot send encoded bytes' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':268)
INFO:uamqp.c_uamqp:b'saslclientio_close called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_close_async':1130) 
INFO:uamqp.c_uamqp:b'xio_close failed' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':272)
INFO:uamqp.c_uamqp:Unknown connection state changed: 13 to 13 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
INFO:uamqp.c_uamqp:b'send called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_send_async':1181) 
INFO:uamqp.c_uamqp:b'Cannot send encoded bytes' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':268)
INFO:uamqp.c_uamqp:b'saslclientio_close called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_close_async':1130) 
INFO:uamqp.c_uamqp:b'xio_close failed' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':272)
INFO:uamqp.c_uamqp:Unknown connection state changed: 13 to 13 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
INFO:uamqp.c_uamqp:b'send called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_send_async':1181) 
INFO:uamqp.c_uamqp:b'Cannot send encoded bytes' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':268)
INFO:uamqp.c_uamqp:b'saslclientio_close called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_close_async':1130) 
INFO:uamqp.c_uamqp:b'xio_close failed' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':272)
INFO:uamqp.c_uamqp:Unknown connection state changed: 13 to 13 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
INFO:uamqp.c_uamqp:b'send called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_send_async':1181) 
INFO:uamqp.c_uamqp:b'Cannot send encoded bytes' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':268)
INFO:uamqp.c_uamqp:b'saslclientio_close called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_close_async':1130) 
INFO:uamqp.c_uamqp:b'xio_close failed' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':272)
INFO:uamqp.c_uamqp:Unknown connection state changed: 13 to 13 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
INFO:uamqp.c_uamqp:b'send called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_send_async':1181) 
INFO:uamqp.c_uamqp:b'Cannot send encoded bytes' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':268)
INFO:uamqp.c_uamqp:b'saslclientio_close called while not open' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\saslclientio.c':b'saslclientio_close_async':1130) 
INFO:uamqp.c_uamqp:b'xio_close failed' (b'C:\\Users\\antisch\\Documents\\GitHub\\azure-uamqp-python\\src\\vendor\\azure-uamqp-c\\src\\connection.c':b'on_bytes_encoded':272)
INFO:uamqp.c_uamqp:Unknown connection state changed: 13 to 13 
DEBUG:uamqp.c_uamqp:Deallocating Connection 
DEBUG:uamqp.c_uamqp:Destroying Connection
annatisch commented 5 years ago

Hi @hbsis-fernandomedeiros - sorry for the delay in getting back to you! It looks like the Connection is not even getting to the point of sending the AMQP header.

Could I possibly see a code snippet? This would only need to show how you are initializing the authentication and the client, what kind of auth/endpoint settings you're using etc (please make sure to remove any sensitive info - but it would still be good to see the formatting of the info, for example for an endpoint URL, something like amqps://[servicename].[servicesuffix]/[entityname]).

I suspect the root cause of this issue is the same as that for issue #44 that I still haven't had a chance to dig into.

hbsis-fernandomedeiros commented 5 years ago

Hi there @annatisch how have you been?

I should have been clearer in my post, sorry about that. Here are the steps to reproduce:

I'm running Docker version 18.09.0 on Windows 10 Pro.

1) On my local Docker, run an instance of the following docker image: https://hub.docker.com/r/solace/solace-pubsub-standard/ - remember to use -p 5672:5672 to bind and expose the AMQP port. More info on running Solace on containers: https://docs.solace.com/Solace-SW-Broker-Set-Up/Docker-Containers/Set-Up-Single-Win-Container.htm

2) I've set up a topic named topic-test-01

3) Run this snippet

import os
import logging
logging.basicConfig(level=logging.DEBUG)
try:
    from urlparse import urlparse
except ImportError:
    from urllib.parse import urlparse

import uamqp
from uamqp import authentication

uri = 'amqp://localhost:5672/topic-test-01'
key_name = 'admin'
access_key = 'admin'

def uamqp_send_simple():
    msg_content = b"Hello world"

    parsed_uri = urlparse(uri)
    plain_auth = authentication.SASLPlain(parsed_uri.hostname, key_name, access_key)

    uamqp.send_message(uri, msg_content, auth=plain_auth, debug=True)
    print("Message sent!")

if __name__ == "__main__":
    uamqp_send_simple()
annatisch commented 5 years ago

Perfect! Thanks @hbsis-fernandomedeiros so much for these repro steps. I will take a shot at this over the weekend. As for me - super busy as per usual. Thanks for asking! ;)

One thing that does occur to me - you could try passing in the port that you're using into the auth config:

plain_auth = authentication.SASLPlain(parsed_uri.hostname, key_name, access_key, port=parsed_uri.port)
hbsis-fernandomedeiros commented 5 years ago

Just tried that a couple combinations:

#plain_auth = authentication.SASLPlain(parsed_uri.hostname, key_name, access_key, port=parsed_uri.port)
    #plain_auth = authentication.SASLPlain('localhost:5672', key_name, access_key, port=parsed_uri.port)
    plain_auth = authentication.SASLPlain('localhost:5672', key_name, access_key)
    #plain_auth = authentication.SASLPlain(parsed_uri.hostname, key_name, access_key)

Same messages for all of them.

annatisch commented 5 years ago

Thanks for the update! Will take a look :)

hbsis-fernandomedeiros commented 5 years ago

Hey @annatisch , how have you been? :) Do you have any news on this issue? I tried updating my pip package, but it hadn't any releases for a while... Thanks!

leonardomira-zz commented 5 years ago

@annatisch and @hbsis-fernandomedeiros We managed to connect on Solace (at least the connection is displayed on Solace dashboard), but we are unable to publish or consume messages. On Solace it is always displayed an "Queue not found" error on the established connection.

With this, we are considering that the problem is related to the amqp connection string, that is wrong or missing some information.

Our example:

def uamqp_send_simple():
    uri = "amqps://<user>.messaging.solace.cloud/<solace_vpn>/queue_name/"
    port = os.environ.get("AMQP_PORT")
    key_name = os.environ.get("AMQP_USERNAME")
    access_key = os.environ.get("AMQP_PASSWORD")
    parsed_uri = urlparse(uri)
    plain_auth = authentication.SASLPlain(parsed_uri.hostname, key_name, access_key, port=port)
    t = uamqp.Target(uri)
    send_client = uamqp.SendClient(t, auth=plain_auth, debug=True, client_name="send_example_uamqp")
    try:
        message = uamqp.Message("content")
        send_client.queue_message(message)
        results = send_client.send_all_messages(close_on_done=False)
        assert not [m for m in results if m == uamqp.constants.MessageState.SendFailed]
    finally:
        send_client.close()
    print("Message sent!")

Log:

2019-09-18 11:19:11,145 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0>
2019-09-18 11:19:11,145 uamqp.sender INFO     Message sender b'sender-link-886d06d0-3dff-48ef-b567-6874093d296d' state changed from <MessageSenderState.Idle: 0> to <MessageSenderState.Opening: 1> on connection: b'send_example_uamqp'
2019-09-18 11:19:11,296 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.START: 0> to <ConnectionState.START: 0>
2019-09-18 11:19:11,881 uamqp.c_uamqp INFO     b'-> Header (AMQP 0.1.0.0)'
2019-09-18 11:19:11,881 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.START: 0> to <ConnectionState.HDR_SENT: 2>
2019-09-18 11:19:11,881 uamqp.c_uamqp INFO     b'<- Header (AMQP 0.1.0.0)'
2019-09-18 11:19:11,881 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.HDR_SENT: 2> to <ConnectionState.HDR_EXCH: 3>
2019-09-18 11:19:11,881 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.HDR_EXCH: 3> to <ConnectionState.OPEN_SENT: 7>
2019-09-18 11:19:12,209 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.OPEN_SENT: 7> to <ConnectionState.OPENED: 9>
2019-09-18 11:19:12,499 uamqp.sender INFO     Message sender b'sender-link-886d06d0-3dff-48ef-b567-6874093d296d' state changed from <MessageSenderState.Opening: 1> to <MessageSenderState.Open: 2> on connection: b'send_example_uamqp'
2019-09-18 11:19:12,645 uamqp.client INFO     Message error, not retrying. Error: MessageSendFailed('ErrorCodes.NotAllowed: SMF AD ack response error')
2019-09-18 11:19:12,645 uamqp.sender INFO     Message sender b'sender-link-886d06d0-3dff-48ef-b567-6874093d296d' state changed from <MessageSenderState.Open: 2> to <MessageSenderState.Closing: 3> on connection: b'send_example_uamqp'
2019-09-18 11:19:12,645 uamqp.connection INFO     Shutting down connection b'send_example_uamqp'.
2019-09-18 11:19:12,645 uamqp.connection INFO     Connection b'send_example_uamqp' state changed from <ConnectionState.OPENED: 9> to <ConnectionState.END: 13>
2019-09-18 11:19:12,645 uamqp.connection INFO     Connection shutdown complete b'send_example_uamqp'

EDIT: typos