search

Azure / azure-sdk-for-python

This repository is for active development of the Azure SDK for Python. For consumers of the SDK we recommend visiting our public developer docs at https://learn.microsoft.com/python/azure/ or our versioned developer docs at https://azure.github.io/azure-sdk-for-python.
MIT License
4.63k stars 2.84k forks source link

ServiceBusError: Handler failed: 'NoneType' object has no attribute 'settle_messages' #30514

Closed pavelm10 closed 1 year ago

pavelm10 commented 1 year ago

Describe the bug Rarely I am receiving this error ServiceBusError with this traceback:

File "<string>", line 1, in <module>
  File "/app/app.py", line 82, in main
    message_handler.listen(
  File "/app/app.py", line 138, in listen
    for input_ in service_bus_receiver.receive(cancellation=cancellation):
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/possibler/sb/input/receiver.py", line 227, in receive
    sb_receiver.complete_message(message)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 289, in wrapped_f
    return self(f, *args, **kw)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 379, in __call__
    do = self.iter(retry_state=retry_state)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 314, in iter
    return fut.result()
  File "/root/.pyenv/versions/3.10.7/lib/python3.10/concurrent/futures/_base.py", line 451, in result
    return self.__get_result()
  File "/root/.pyenv/versions/3.10.7/lib/python3.10/concurrent/futures/_base.py", line 403, in __get_result
    raise self._exception
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 382, in __call__
    result = fn(*args, **kwargs)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/possibler/sb/input/receiver.py", line 114, in complete_message
    return self._entered_receiver.complete_message(*args, **kwargs)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 838, in complete_message
    self._settle_message_with_retry(message, MESSAGE_COMPLETE)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 476, in _settle_message_with_retry
    self._do_retryable_operation(
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 418, in _do_retryable_operation
    last_exception = self._handle_exception(exception)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 358, in _handle_exception
    raise error
  azure.servicebus.exceptions.ServiceBusError: Handler failed: 'NoneType' object has no attribute 'settle_messages'.

Traceback (most recent call last):
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 411, in _do_retryable_operation
    return operation(**kwargs)
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 497, in _settle_message
    self._amqp_transport.settle_message_via_receiver_link(
  File "/root/.cache/pypoetry/virtualenvs/app-9TtSrW0h-py3.10/lib/python3.10/site-packages/azure/servicebus/_transport/_pyamqp_transport.py", line 701, in settle_message_via_receiver_link
    return handler.settle_messages(message._delivery_id, 'accepted')
  AttributeError: 'NoneType' object has no attribute 'settle_messages'

I have the receiver.receive_messages() method wrapped with tenacity retrying which retries the operation on ServiceBusError, however this issue probably does not seem be solved with retrying.

To Reproduce Steps to reproduce the behavior:

  1. With ServiceBusReceiver receive messages from Service Bus topic subscription

Expected behavior The SDK should either handle such case or implement more robust retrying mechanism.

Additional context

kashifkhan commented 1 year ago

Thank you for the feedback @pavelm10. Can you please provide us with a sample repro to help us see the error happening.

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

pavelm10 commented 1 year ago

Hello @kashifkhan

The modified extract of the code I use:

from azure.servicebus import ServiceBusClient, ServiceBusReceiveMode
from azure.servicebus import ServiceBusReceiver as AzureServiceBusReceiver

class MyServiceBusReceiver:
    def __init__(self, service_bus_receiver: AzureServiceBusReceiver):
        self._receiver = service_bus_receiver
        self._entered_receiver = None

    def __enter__(self):
        self._entered_receiver = self._receiver.__enter__()
        return self

    def __exit__(self, *args):
        self._receiver.__exit__(*args)

    @tenacious_retrying
    def receive_messages(self, *args, **kwargs):
        return self._entered_receiver.receive_messages(*args, **kwargs)

    @tenacious_retrying
    def complete_message(self, *args, **kwargs):
        return self._entered_receiver.complete_message(*args, **kwargs)

def receive(namespace_fqn, topic_name, subscription_name, credential):
    sb_client = ServiceBusClient(
        fully_qualified_namespace=namespace_fqn(),
        credential=credential,
    )

    with sb_client as sb_client:
        sb_receiver = sb_client.get_subscription_receiver(
            topic_name=topic_name,
            subscription_name=subscription_name,
            receive_mode=ServiceBusReceiveMode.PEEK_LOCK,
        )

        sb_receiver = MyServiceBusReceiver(
            service_bus_receiver=sb_receiver,
        )

        with sb_receiver as sb_receiver:
            while True:
                messages = sb_receiver.receive_messages(
                    max_wait_time=120,
                    max_message_count=1,
                )

                if not messages:
                    continue
                yield messages

                for message in messages:
                    sb_receiver.complete_message(message)
kashifkhan commented 1 year ago

follow up question, at any point are your logs showing any other sort of errors such as time outs etc ? From the sounds of it, seems like the underlying handler is closing down due to the clients internal retries being used up.

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

pavelm10 commented 1 year ago

@kashifkhan When this error occurred there was no other errors, no time outs. Also this error is quite new to me, haven't seen it before until recently. Normally we get other errors such as server busy (can be probably fixed by using higher tier of service bus), or we see quite often this error uamqp.errors.LinkDetach: ErrorCodes.InternalServerError.

kashifkhan commented 1 year ago

Sorry for the delay @pavelm10. I havent been able to repro this issue. The reason I asked about errors etc is because the handler seems to close down for some reason so when that method is invoked, its not there anymore. Without any errors however is leaving me a bit confused.

Still digging, but its tough one to repro. Are you able to do so reliably ?

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

github-actions[bot] commented 1 year ago

Hi @pavelm10, we're sending this friendly reminder because we haven't heard back from you in 7 days. We need more information about this issue to help address it. Please be sure to give us your input. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!

pavelm10 commented 1 year ago

No I am not able to do it reliably, but every week this pops up at least 3 times in our production system, for the particular service bus it amounts to 45k messages/week. So as you can see it is rather rare. But since it keeps happening few times a week we pay attention to it.

swathipil commented 1 year ago

Hi @pavelm10 - Digging into this right now. Would you be able to turn on network level tracing by passing in logging_enable=True when creating the ServiceBusClient, then reply with the logs leading up to that error here?

Directions for turning on logging in this section of the README here: https://github.com/Azure/azure-sdk-for-python/tree/main/sdk/servicebus/azure-servicebus#logging

Since you're using 7.10.0, you will not need to enable any of the uamqp loggers, so feel free to ignore those.

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

pavelm10 commented 1 year ago

Hi, we migrated to premium service bus and since then we have not had this issue. So even if I enabled the logging I don't think we would be able to get the error again.

pavelm10 commented 1 year ago

Hello, so we got the same exception even with Premium service bus, unfortunately the servicebus client logging was not enabled. From the Azure Portal I can see in the service bus metrics that there were couple of server errors around that time when we got the exception. Both CPU and memory usage of the service bus were bellow 20%. Seems the issue is on the server side but SDK is not handling it correctly.

swathipil commented 1 year ago

Hi @pavelm10 - We've run stress tests and still haven't been able to reproduce the error. Unfortunately, we'll need either logging or a reliable repro to debug this. Despite the switch to premium, would you be able to keep an eye out for this error so that you can turn on debug logging as specified [here] and respond with those? Thanks!

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

pavelm10 commented 1 year ago

Hi, I will enable the logging for few weeks, hopefully it will occur again and we will catch it.

kashifkhan commented 1 year ago

@pavelm10 Thank you :) Debug logging & passing in logging_enable=True will give us the most amount of detail to help pin point the problem area. I would suggest running in this in a test environment as it will be a lot of logging

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

pavelm10 commented 1 year ago

We have not observed it in our dev environment, so it is also enabled in production. Hence I set the log level INFO: logging.getLogger('azure.servicebus').setLevel(logging.INFO). Please let me know if INFO is not sufficient. Also I noticed that when I first set logging_enable=True on the client, nothing was logged from the service bus client. Only after setting the level of azure.servicebus logger to INFO the logs appeared.

kashifkhan commented 1 year ago

@pavelm10 DEBUG would be better as we can see whats happening with a lot more detail, but understand thats not ideal in production. As you can see reproducing this seems like a game of chance :)

logging_enable & logging go hand in hand, so a logging level would be needed.

github-actions[bot] commented 1 year ago

Hi @pavelm10. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

github-actions[bot] commented 1 year ago

Hi @pavelm10, we're sending this friendly reminder because we haven't heard back from you in 7 days. We need more information about this issue to help address it. Please be sure to give us your input. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!

pavelm10 commented 1 year ago

Hello @kashifkhan , finally the issue occurred again. We have not enabled debug logs, only info. Hope it will be sufficient. Here are the logs:

2023-07-23 09:09:52 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.867031"}
2023-07-23 09:09:52 {"message": "Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.867453"}
2023-07-23 09:09:52 {"message": "CBS error occurred.", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.867619"}
2023-07-23 09:09:52 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.918279"}
2023-07-23 09:09:52 {"message": "Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.918521"}
2023-07-23 09:09:52 {"message": "Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_RCVD: 5>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.968779"}
2023-07-23 09:09:52 {"message": "Session state changed: <SessionState.END_RCVD: 5> -> <SessionState.UNMAPPED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.969136"}
2023-07-23 09:09:52 {"message": "Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.DISCARDING: 12>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.969453"}
2023-07-23 09:09:52 {"message": "Connection state changed: <ConnectionState.DISCARDING: 12> -> <ConnectionState.END: 13>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:52.969536"}
2023-07-23 09:09:52 {"message": "END frame received on invalid channel. Closing connection.", "logLevel": "ERROR", "logTime": "2023-07-23 09:09:52.969831"}
2023-07-23 09:09:53 {"message": "AMQP error occurred: (AMQPConnectionError('Error condition: ErrorCondition.ConnectionCloseForced\\n Error Description: Invalid channel number received')), condition: (<ErrorCondition.ConnectionCloseForced: b'amqp:connection:forced'>), description: ('Invalid channel number received').", "logLevel": "INFO", "logTime": "2023-07-23 09:09:53.020459"}
2023-07-23 09:09:53 {"message": "Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:53.020633"}
2023-07-23 09:09:54 {"message": "'servicebus.pysdk-61a18270' has an exception (ServiceBusConnectionError('Invalid channel number received Error condition: amqp:connection:forced.')). Retrying...", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.622483"}
2023-07-23 09:09:54 {"message": "Connection state changed: None -> <ConnectionState.START: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.689770"}
2023-07-23 09:09:54 {"message": "Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.693633"}
2023-07-23 09:09:54 {"message": "Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.693788"}
2023-07-23 09:09:54 {"message": "Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.694370"}
2023-07-23 09:09:54 {"message": "Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.694759"}
2023-07-23 09:09:54 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.695631"}
2023-07-23 09:09:54 {"message": "Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.695761"}
2023-07-23 09:09:54 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.696215"}
2023-07-23 09:09:54 {"message": "Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.696328"}
2023-07-23 09:09:54 {"message": "Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.696797"}
2023-07-23 09:09:54 {"message": "Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.747078"}
2023-07-23 09:09:54 {"message": "Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.800505"}
2023-07-23 09:09:54 {"message": "Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.850941"}
2023-07-23 09:09:54 {"message": "Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.851201"}
2023-07-23 09:09:54 {"message": "Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.901784"}
2023-07-23 09:09:54 {"message": "Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:54.901889"}
2023-07-23 09:09:55 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.168214"}
2023-07-23 09:09:55 {"message": "Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.171457"}
2023-07-23 09:09:55 {"message": "Message settling: 'complete' has encountered an exception (AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')) through management link", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.790844"}
2023-07-23 09:09:55 {"message": "AMQP error occurred: (AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')), condition: (<ErrorCondition.SocketError: b'amqp:socket-error'>), description: ('Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)').", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.790998"}
2023-07-23 09:09:55 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791248"}
2023-07-23 09:09:55 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791379"}
2023-07-23 09:09:55 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791504"}
2023-07-23 09:09:55 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791604"}
2023-07-23 09:09:55 {"message": "Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791686"}
2023-07-23 09:09:55 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791797"}
2023-07-23 09:09:55 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791897"}
2023-07-23 09:09:55 {"message": "Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.791964"}
2023-07-23 09:09:55 {"message": "An error occurred when ending the session: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.792064"}
2023-07-23 09:09:55 {"message": "Session state changed: <SessionState.MAPPED: 3> -> <SessionState.UNMAPPED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.792151"}
2023-07-23 09:09:55 {"message": "An error occurred when closing the connection: AMQPConnectionError('Error condition: ErrorCondition.SocketError\\n Error Description: Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396)')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.792255"}
2023-07-23 09:09:55 {"message": "Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.END: 13>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:55.792369"}
2023-07-23 09:09:57 {"message": "'servicebus.pysdk-97b6849f' has an exception (ServiceBusConnectionError('Can not send empty frame due to exception: EOF occurred in violation of protocol (_ssl.c:2396) Error condition: amqp:socket-error.')). Retrying...", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.394175"}
2023-07-23 09:09:57 {"message": "Message settling: 'complete' has encountered an exception (AttributeError(\"'NoneType' object has no attribute 'settle_messages'\")) through management link", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.394407"}
2023-07-23 09:09:57 {"message": "Unexpected error occurred (AttributeError(\"'NoneType' object has no attribute 'settle_messages'\")). Handler shutting down.", "logLevel": "ERROR", "logTime": "2023-07-23 09:09:57.394610"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.395607"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.395934"}
2023-07-23 09:09:57 {"message": "Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396040"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396304"}
2023-07-23 09:09:57 {"message": "Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396426"}
2023-07-23 09:09:57 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.InternalError\\n Error Description: Link already closed.')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396718"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396822"}
2023-07-23 09:09:57 {"message": "Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.396930"}
2023-07-23 09:09:57 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.InternalError\\n Error Description: Link already closed.')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397064"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397171"}
2023-07-23 09:09:57 {"message": "Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397281"}
2023-07-23 09:09:57 {"message": "An error occurred when detaching the link: AMQPConnectionError('Error condition: ErrorCondition.InternalError\\n Error Description: Link already closed.')", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397367"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397458"}
2023-07-23 09:09:57 {"message": "Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397553"}
2023-07-23 09:09:57 {"message": "Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397760"}
2023-07-23 09:09:57 {"message": "Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397888"}
2023-07-23 09:09:57 {"message": "Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.397984"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.398062"}
2023-07-23 09:09:57 {"message": "Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.398157"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.398227"}
2023-07-23 09:09:57 {"message": "Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.398339"}
2023-07-23 09:09:57 {"message": "Link state changed: <LinkState.DETACHED: 0> -> <LinkState.DETACHED: 0>", "logLevel": "INFO", "logTime": "2023-07-23 09:09:57.398452"}
2023-07-23 09:09:57 Traceback (most recent call last):
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 411, in _do_retryable_operation
2023-07-23 09:09:57     return operation(**kwargs)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 501, in _settle_message
2023-07-23 09:09:57     self._amqp_transport.settle_message_via_receiver_link(
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_transport/_pyamqp_transport.py", line 703, in settle_message_via_receiver_link
2023-07-23 09:09:57     return handler.settle_messages(message._delivery_id, 'accepted')
2023-07-23 09:09:57 AttributeError: 'NoneType' object has no attribute 'settle_messages'
2023-07-23 09:09:57 
2023-07-23 09:09:57 During handling of the above exception, another exception occurred:
2023-07-23 09:09:57 
2023-07-23 09:09:57 Traceback (most recent call last):
2023-07-23 09:09:57   File "<string>", line 1, in <module>
2023-07-23 09:09:57   File "/app/app.py", line 445, in main
2023-07-23 09:09:57     job()
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/possibler/jobs/job.py", line 49, in __call__
2023-07-23 09:09:57     self.handle()
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/possibler/jobs/job.py", line 134, in handle
2023-07-23 09:09:57     for input_ in self._receiver.receive(
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/possibler/sb/input/receiver.py", line 235, in receive
2023-07-23 09:09:57     sb_receiver.complete_message(message)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 289, in wrapped_f
2023-07-23 09:09:57     return self(f, *args, **kw)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 379, in __call__
2023-07-23 09:09:57     do = self.iter(retry_state=retry_state)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 314, in iter
2023-07-23 09:09:57     return fut.result()
2023-07-23 09:09:57   File "/root/.pyenv/versions/3.10.7/lib/python3.10/concurrent/futures/_base.py", line 451, in result
2023-07-23 09:09:57     return self.__get_result()
2023-07-23 09:09:57   File "/root/.pyenv/versions/3.10.7/lib/python3.10/concurrent/futures/_base.py", line 403, in __get_result
2023-07-23 09:09:57     raise self._exception
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/tenacity/__init__.py", line 382, in __call__
2023-07-23 09:09:57     result = fn(*args, **kwargs)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/possibler/sb/input/receiver.py", line 114, in complete_message
2023-07-23 09:09:57     return self._entered_receiver.complete_message(*args, **kwargs)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 842, in complete_message
2023-07-23 09:09:57     self._settle_message_with_retry(message, MESSAGE_COMPLETE)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_servicebus_receiver.py", line 480, in _settle_message_with_retry
2023-07-23 09:09:57     self._do_retryable_operation(
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 418, in _do_retryable_operation
2023-07-23 09:09:57     last_exception = self._handle_exception(exception)
2023-07-23 09:09:57   File "/root/.cache/pypoetry/virtualenvs/app-py3.10/lib/python3.10/site-packages/azure/servicebus/_base_handler.py", line 358, in _handle_exception
2023-07-23 09:09:57     raise error
2023-07-23 09:09:57 azure.servicebus.exceptions.ServiceBusError: Handler failed: 'NoneType' object has no attribute 'settle_messages'.
pavelm10 commented 1 year ago

@kashifkhan is there any update?

kashifkhan commented 1 year ago

@pavelm10 We are now able to reproduce this problem on our end successfully and will have a new release soon. Ill link the PR to this issue once its ready to go

pavelm10 commented 1 year ago

@kashifkhan Great, thank you.

sudharsan2020 commented 1 year ago

@kashifkhan I am facing the same issue too. Do you have any temporary workaround for this ? Thanks

kashifkhan commented 1 year ago

@sudharsan2020 a workaround would be to catch the AttibuteError and then try the completion operation again.

pavelm10 commented 1 year ago

@kashifkhan when do you plan next release with this fix included?

kashifkhan commented 1 year ago

@pavelm10 This upcoming release cycle. I have a PR here that needs to be merged in.

Actually, one that would be nice is if you can use my branch to generate a wheel and test out my patch in your environment ? This way we have an external confirmation of the fix working as well

kashifkhan commented 1 year ago

@pavelm10 We have just released a new version of the library with the fix :)

pavelm10 commented 1 year ago

@kashifkhan thanks for letting us know:)