Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Handler failed: Received invalid frame type: 49, expected: 0 on upgrading to azure-servicebus 7.12.3 #37547

Closed
gareththackeray opened this issue Sep 24, 2024 · 10 comments
Assignees
Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. Messaging Messaging crew question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus

Comments

@gareththackeray
Copy link

  • Package Name: azure-servicebus
  • Package Version: 7.12.3
  • Operating System: Linux
  • Python Version: 3.12

Describe the bug
After upgrading, we received the error Caught exception: ServiceBusError('Handler failed: Received invalid frame type: 49, expected: 0.') repeatedly. Stack trace:

ValueError: Received invalid frame type: 49, expected: 0
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py", line 260, in _do_retryable_operation
    return await operation(**kwargs)
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_servicebus_sender_async.py", line 221, in _open
    await self._handler.open_async(connection=self._connection)
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_client_async.py", line 262, in open_async
    await self._connection.open()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py", line 881, in open
    await self._connect()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py", line 225, in _connect
    await self._transport.negotiate()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py", line 124, in negotiate
    await self._negotiate()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py", line 70, in _negotiate
    _, returned_header = await self.receive_frame()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py", line 76, in receive_frame
    header, channel, payload = await asyncio.wait_for(
  File "asyncio/tasks.py", line 520, in wait_for
    return await fut
  File "/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py", line 115, in read
    raise ValueError(

ServiceBusError: Handler failed: Received invalid frame type: 49, expected: 0.
  File "granular_backend/app/messaging/client.py", line 157, in send
    async with sender:
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_servicebus_sender_async.py", line 160, in __aenter__
    await self._open_with_retry()
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py", line 410, in _open_with_retry
    return await self._do_retryable_operation(self._open)
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py", line 267, in _do_retryable_operation
    last_exception = await self._handle_exception(exception)
  File "/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py", line 208, in _handle_exception
    raise error

To Reproduce
Steps to reproduce the behavior:

  1. upgrade lbibrary
  2. call receive_messages

Expected behavior
Successfully receive messages.

@github-actions github-actions bot added Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus labels Sep 24, 2024
Copy link

Thank you for your feedback. Tagging and routing to the team member best able to assist.

@kashifkhan kashifkhan added the Messaging Messaging crew label Sep 24, 2024
@kashifkhan
Copy link
Member

kashifkhan commented Sep 24, 2024

Hi @gareththackeray, I am not able to reproduce that error on my side. Would you be able to share some logs or steps to reproduce the problem. Simply calling receive_messages on async is not raising that error for me.

debug logs with tracing enable will also help. If you look at the sample below setting up debug along with logging_enable=True will also help us in debugging. Could you also specify the size of your messages please?

The sample I used:

import os
import asyncio
from azure.servicebus.aio import ServiceBusClient
from azure.identity.aio import DefaultAzureCredential

FULLY_QUALIFIED_NAMESPACE = os.environ['SERVICEBUS_FULLY_QUALIFIED_NAMESPACE']
QUEUE_NAME = os.environ["SERVICEBUS_QUEUE_NAME"]

import logging
import sys

log_fmt = logging.Formatter("%(asctime)s | %(levelname)s | %(threadName)s | %(name)s | %(message)s")
logger = logging.getLogger("azure")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(stream=sys.stdout)
handler.setFormatter(log_fmt)
logger.addHandler(handler)


async def main():
    credential = DefaultAzureCredential()
    servicebus_client = ServiceBusClient(FULLY_QUALIFIED_NAMESPACE, credential)

    async with servicebus_client:
        receiver = servicebus_client.get_queue_receiver(queue_name=QUEUE_NAME)
        async with receiver:
            received_msgs = await receiver.receive_messages(max_message_count=20, max_wait_time=5)
            logger.debug(f"Received {len(received_msgs)} messages")
            for idx, msg in enumerate(received_msgs):
                print(f"Id: {idx}")
                await receiver.complete_message(msg)


asyncio.run(main())

@kashifkhan kashifkhan added the needs-author-feedback Workflow: More information is needed from author to address the issue. label Sep 24, 2024
@github-actions github-actions bot removed the needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team label Sep 24, 2024
Copy link

Hi @gareththackeray. 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.

@gareththackeray
Copy link
Author

Hi @kashifkhan thanks for the response and sorry it took a while to respond. I set up logging as you specified, and passed logging_enable=True to ServiceBusClient. Result below. These logs then repeat pretty much:

2024-10-01T14:27:31.675Z,"AZURE | 2024-10-01 14:27:31,673 | INFO | MainThread | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,679 | INFO | MainThread | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,679 | INFO | MainThread | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,682 | INFO | MainThread | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,683 | DEBUG | MainThread | azure.servicebus._pyamqp.aio._transport_async | Received invalid frame type: 49, expected: 0"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,683 | ERROR | MainThread | azure.servicebus.aio._base_handler_async | Unexpected error occurred (ValueError('Received invalid frame type: 49, expected: 0')). Handler shutting down."
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py"", line 260, in _do_retryable_operation"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/aio/_servicebus_receiver_async.py"", line 394, in _open"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_client_async.py"", line 262, in open_async"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py"", line 881, in open"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py"", line 225, in _connect"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py"", line 124, in negotiate"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py"", line 70, in _negotiate"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py"", line 76, in receive_frame"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py"", line 115, in read"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,770 | DEBUG | MainThread | azure.servicebus._pyamqp.aio._transport_async | Received invalid frame type: 49, expected: 0"
2024-10-01T14:27:32.676Z,"AZURE | 2024-10-01 14:27:31,770 | ERROR | MainThread | azure.servicebus.aio._base_handler_async | Unexpected error occurred (ValueError('Received invalid frame type: 49, expected: 0')). Handler shutting down."
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/aio/_base_handler_async.py"", line 260, in _do_retryable_operation"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/aio/_servicebus_receiver_async.py"", line 394, in _open"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_client_async.py"", line 262, in open_async"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py"", line 881, in open"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_connection_async.py"", line 225, in _connect"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py"", line 124, in negotiate"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_sasl_async.py"", line 70, in _negotiate"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py"", line 76, in receive_frame"
2024-10-01T14:27:32.676Z,"File ""/venv/lib/python3.12/site-packages/azure/servicebus/_pyamqp/aio/_transport_async.py"", line 115, in read"

@github-actions github-actions bot added needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team and removed needs-author-feedback Workflow: More information is needed from author to address the issue. labels Oct 1, 2024
@kashifkhan
Copy link
Member

kashifkhan commented Oct 1, 2024

@gareththackeray will you be able to share some of the logs before this 2024-10-01T14:27:31.675Z,"AZURE | 2024-10-01 14:27:31,673 | INFO | MainThread | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>" please ?

What Im trying to understand is that why this error is showing up before transfers take place. Are you able to share the data you are pulling in or sending ?

Also are you by any chance using one instance of the async client with multiple coroutines ? The library is not coroutine safe so you would need a lock around it.

Essentially Im looking for a way to repro on my side because Im not able to do so simply using receive. I also noticed your init stack trace was on the sender and not on receive, so curious.

@kashifkhan kashifkhan added the needs-author-feedback Workflow: More information is needed from author to address the issue. label Oct 1, 2024
Copy link

github-actions bot commented Oct 1, 2024

Hi @gareththackeray. 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 github-actions bot removed the needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team label Oct 1, 2024
@annatisch
Copy link
Member

Hi @gareththackeray - I think I've managed to repro this.
There was a fix merged into the most recent servicebus release to fix a bug where port information on the supplied endpoint was being ignored:
https://github.com/Azure/azure-sdk-for-python/pull/37095/files#diff-47bfe6c566fd15b0ff90a63de85851072ff821ff81c9951e3bec76de994138ee

I've noticed that depending on where you're retrieving your endpoint information, an HTTP port may be automatically appended. For example, I deployed my ServiceBus namespace with bicep, and the endpoint output is generated in the format:
"https://accountname.servicebus.windows.net:443/"

Previously the scheme and port were being discarded in the case of connection via AMQP. However with the recent patch that's no longer the case. This HTTP endpoint would function correctly if you attempt to connect using websockets.

I think to resolve this, the SDK should be updated so that we don't attempt to establish an AMQP connection over a known HTTP port. In the meantime, if you think the port is same issue you encountered, you should be able to be unblocked by either stripping the http port from the endpoint, or connecting over websockets (requires extra dependency installation):
client = ServiceBusClient(namespace_endponit, credential, transport_type=azure.servicebus.TransportType.AmqpOverWebsocket

@annatisch annatisch removed the needs-author-feedback Workflow: More information is needed from author to address the issue. label Oct 7, 2024
@github-actions github-actions bot added the needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team label Oct 7, 2024
@gareththackeray
Copy link
Author

That's fixed it - excellent deduction and thanks so much @annatisch.

@kashifkhan
Copy link
Member

This has been addressed in the latest release of Service Bus

@kashifkhan kashifkhan added the issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. label Nov 12, 2024
Copy link

Hi @gareththackeray. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text "/unresolve" to remove the "issue-addressed" label and continue the conversation.

@github-actions github-actions bot removed the needs-team-attention Workflow: This issue needs attention from Azure service team or SDK team label Nov 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. issue-addressed Workflow: The Azure SDK team believes it to be addressed and ready to close. Messaging Messaging crew question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus
Projects
None yet
Development

No branches or pull requests

5 participants