ServiceBus SDK: Session-enabled queue receiver links detach immediately after successful attachment with "Session error"

ADevBelgie commented 1 day ago

Package Name: azure-servicebus
Package Version: 7.13.0
Dependencies:
- uamqp==1.6.4
- azure-core==1.29.5
Operating System: All (SDK Issue)
Python Version: 3.11

Describe the bug When working with session-enabled Service Bus queues, the receiver link initially attaches but immediately detaches with a "Session error". This occurs even after successful CBS authentication and initial link attachment.

To Reproduce

Create a session-enabled Service Bus queue

Create a ServiceBusReceiver with session_id:


from azure.servicebus import ServiceBusClient

client = ServiceBusClient( fully_qualified_namespace="your-namespace.servicebus.windows.net", credential=credential )

receiver = client.get_queue_receiver( queue_name="your-queue", session_id=NEXT_AVAILABLE_SESSION, max_wait_time=30 )

3. Attempt to receive messages:
```python
async with receiver:
    messages = await receiver.receive_messages(max_message_count=10)

Expected behavior The receiver should successfully establish and maintain a link with the session-enabled queue and be able to receive messages.

Actual behavior The link cycle shows:

Successful CBS authentication
Successful link attachment
Immediate link detachment
"Session error" logged

Logs showing the pattern:

20:20:20,862 - azure.servicebus._pyamqp.aio._cbs_async - INFO - CBS completed opening with status: <ManagementOpenResult.OK: 1>
20:20:21,065 - azure.servicebus._pyamqp.aio._link_async - INFO - Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
20:20:21,070 - azure.servicebus._pyamqp.aio._link_async - INFO - Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
20:20:21,121 - azure.servicebus._pyamqp.aio._link_async - INFO - Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
20:20:21,761 - src.azure.service_bus - ERROR - Session error

Technical Analysis The issue appears to be in the session handling lifecycle:

The link establishes correctly (unlike our previous assumption about source/target configuration)
However, something in the session initialization or lock acquisition is failing
This causes immediate detachment of an otherwise successfully attached link

The problem may be related to:

Session lock acquisition timing
Session state synchronization between client and server
Session filtering configuration in the attach frame

Workaround Attempts

Increased timeouts:

receiver = client.get_queue_receiver(
queue_name="your-queue",
session_id=NEXT_AVAILABLE_SESSION,
max_wait_time=30,
max_session_lock_renewal_duration=300
)

Using TransportType.Amqp:

client = ServiceBusClient.from_connection_string(
conn_str=connection_string,
transport_type=TransportType.Amqp
)

However, both still result in the same session error pattern.

Additional context The issue specifically affects session-enabled queues

The link successfully attaches but fails during session establishment
Management links work correctly, suggesting the basic AMQP connectivity is functional
The error occurs consistently across connection attempts Suggested debugging enhancements:
1. Enable AMQP frame-level logging to see the exact session detach frame contents
2. Add detailed error information from the session detach frame to the logs
3. Log the specific session filter configuration being used in the attach frame
4. Consider adding a session state machine diagram to help diagnose where the session lifecycle is failing

github-actions[bot] commented 1 day ago

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

kashifkhan commented 1 day ago

Thank you for the feedback @ADevBelgie , a few follow up questions

Are you using uamqp ? Doesnt look like it from the repo or the logs, but want to confirm.
Are there messages in the queue for that session at the time? If so, how big are they ?

This is the way to set up additional logging -> set logging to DEBUG and pass in logging_enable kwarg ... this will enable frame level logging

import logging
import sys

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

...

from azure.servicebus import ServiceBusClient

client = ServiceBusClient(..., logging_enable=True)

kashifkhan commented 1 day ago

Hi @ADevBelgie ,

I was unable to repro the issue with the following sample. I got back exactly 10 messages and my queue had 100 messages with a particular session.

the logs and sample are in sync, but the same happens in async. I even had it waiting on a completely empty queue for over a minute and didnt get that error.

20:20:21,761 - src.azure.service_bus - ERROR - Session error - where is this error coming from as its not our logging.


import os
from azure.servicebus import ServiceBusClient, ServiceBusMessage, NEXT_AVAILABLE_SESSION
from azure.identity import AzurePowerShellCredential

from dotenv import load_dotenv, find_dotenv

load_dotenv(find_dotenv())

FULLY_QUALIFIED_NAMESPACE = os.environ["SERVICEBUS_FULLY_QUALIFIED_NAMESPACE"]
SESSION_QUEUE_NAME = os.environ["SERVICEBUS_SESSION_QUEUE_NAME"]

import logging
import sys

log_fmt = logging.Formatter(fmt="%(asctime)s | %(threadName)s | %(levelname)s | %(name)s | %(message)s")
logger = logging.getLogger("azure")
logger.setLevel(logging.DEBUG)
file_handler = logging.FileHandler(filename="sample.log")
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(log_fmt)
logger.addHandler(file_handler)

if __name__ == "__main__":
    credential = AzurePowerShellCredential()
    servicebus_client = ServiceBusClient(FULLY_QUALIFIED_NAMESPACE, credential, logging_enable=True)
    with servicebus_client:

        receiver = servicebus_client.get_queue_receiver(queue_name=SESSION_QUEUE_NAME, session_id=NEXT_AVAILABLE_SESSION)
        with receiver:
            messages = receiver.receive_messages(max_message_count=10)
            print(f"Received {len(messages)} messages.")
            for idx, message in enumerate(messages):
                print(str(message))
                receiver.complete_message(message)
    print("Receive is done.")

2024-11-20 21:18:10,103 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: None -> <ConnectionState.START: 0>
2024-11-20 21:18:10,185 | MainThread | DEBUG | azure.servicebus._pyamqp._connection | -> Header(b'AMQP\x00\x01\x00\x00')
2024-11-20 21:18:10,186 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2024-11-20 21:18:10,186 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2024-11-20 21:18:10,186 | MainThread | DEBUG | azure.servicebus._pyamqp._connection | -> OpenFrame(container_id='SBReceiver-aabddf86-91c3-4097-939d-968c967a9003', hostname='****.servicebus.windows.net', max_frame_size=1048576, channel_max=65535, idle_timeout=None, outgoing_locales=None, incoming_locales=None, offered_capabilities=None, desired_capabilities=None, properties={'product': 'azsdk-python-servicebus', 'version': '7.13.0', 'framework': 'Python/3.11.10', 'platform': 'Linux-5.15.167.4-microsoft-standard-WSL2-x86_64-with-glibc2.35', 'user-agent': 'azsdk-python-servicebus/7.13.0 pyamqp/2.0.0a1 Python/3.11.10 (Linux-5.15.167.4-microsoft-standard-WSL2-x86_64-with-glibc2.35)'})
2024-11-20 21:18:10,187 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2024-11-20 21:18:10,187 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> BeginFrame(remote_channel=None, next_outgoing_id=0, incoming_window=65536, outgoing_window=65536, handle_max=4294967295, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,187 | MainThread | INFO | azure.servicebus._pyamqp.session | Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2024-11-20 21:18:10,188 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> AttachFrame(name='90919745-f55d-4367-ae1f-c4021113853b', handle=2, role=True, send_settle_mode=0, rcv_settle_mode=0, source=Source(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters=None, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,188 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-20 21:18:10,188 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-20 21:18:10,188 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> AttachFrame(name='ead150e4-f32f-4a59-9e8c-3d558247a90f', handle=1, role=False, send_settle_mode=0, rcv_settle_mode=0, source=Source(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters=None, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,189 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-20 21:18:10,189 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-20 21:18:10,227 | MainThread | DEBUG | azure.servicebus._pyamqp._connection | <- Header(b'AMQP\x00\x01\x00\x00')
2024-11-20 21:18:10,228 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2024-11-20 21:18:10,278 | MainThread | DEBUG | azure.servicebus._pyamqp._connection | <- OpenFrame(container_id=b'dd7d14dd2e9c4326932fa606fcba38d2_G0', hostname=None, max_frame_size=65536, channel_max=4999, idle_timeout=120000, outgoing_locales=None, incoming_locales=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,278 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2024-11-20 21:18:10,329 | MainThread | DEBUG | azure.servicebus._pyamqp.session | <- BeginFrame(remote_channel=1, next_outgoing_id=1, incoming_window=5000, outgoing_window=65536, handle_max=255, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,329 | MainThread | INFO | azure.servicebus._pyamqp.session | Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2024-11-20 21:18:10,380 | MainThread | DEBUG | azure.servicebus._pyamqp.link | <- AttachFrame(name=b'90919745-f55d-4367-ae1f-c4021113853b', handle=0, role=False, send_settle_mode=0, rcv_settle_mode=0, source=[b'$cbs', None, None, None, None, None, None, None, None, None, None], target=[b'$cbs', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=18446744073709551615, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,380 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-20 21:18:10,380 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-20 21:18:10,380 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> FlowFrame(next_incoming_id=1, incoming_window=65536, next_outgoing_id=0, outgoing_window=65536, handle=2, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2024-11-20 21:18:10,431 | MainThread | DEBUG | azure.servicebus._pyamqp.link | <- AttachFrame(name=b'ead150e4-f32f-4a59-9e8c-3d558247a90f', handle=1, role=True, send_settle_mode=0, rcv_settle_mode=0, source=[b'$cbs', None, None, None, None, None, None, None, None, None, None], target=[b'$cbs', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=18446744073709551615, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-20 21:18:10,431 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-20 21:18:10,431 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-20 21:18:10,431 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS completed opening with status: <ManagementOpenResult.OK: 1>
2024-11-20 21:18:10,432 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> FlowFrame(next_incoming_id=1, incoming_window=65536, next_outgoing_id=0, outgoing_window=65536, handle=1, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2024-11-20 21:18:13,196 | MainThread | INFO | azure.identity._internal.decorators | AzurePowerShellCredential.get_token succeeded
2024-11-20 21:18:13,197 | MainThread | DEBUG | azure.identity._internal.decorators | [Authenticated account] Client ID: 1950a258-227b-4e31-a9cf-717495945fc2. Tenant ID: 72f988bf-86f1-41af-91ab-2d7cd011db47. User Principal Name: kashifkhan@microsoft.com. Object ID (user): fa54e51e-ab45-4fa9-b655-4b8b601b82c4
2024-11-20 21:18:13,197 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> TransferFrame(handle=1, delivery_id=0, delivery_tag=b'\x00\x00\x00\x01', message_format=0, settled=False, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=None, payload=b'***')
2024-11-20 21:18:13,199 | MainThread | DEBUG | azure.servicebus._pyamqp.session | <- FlowFrame(next_incoming_id=0, incoming_window=5000, next_outgoing_id=1, outgoing_window=65536, handle=1, delivery_count=0, link_credit=100, available=0, drain=None, echo=False, properties=None)
2024-11-20 21:18:13,250 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS update in progress. Token put time: 1732137493
2024-11-20 21:18:13,250 | MainThread | DEBUG | azure.servicebus._pyamqp.session | <- DispositionFrame(role=True, first=0, last=None, settled=True, state={'accepted': []}, batchable=None)
2024-11-20 21:18:13,301 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS update in progress. Token put time: 1732137493
2024-11-20 21:18:13,421 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=0, delivery_id=0, delivery_tag=b'\x01\x00\x00\x00', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=False, payload=b'***')
2024-11-20 21:18:13,421 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2024-11-20 21:18:13,472 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,472 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> AttachFrame(name='863771c3-f490-4ace-b431-cdee52bc1c27', handle=3, role=True, send_settle_mode=0, rcv_settle_mode=1, source=Source(address='amqps://****.servicebus.windows.net/****-session-queue', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters={b'com.microsoft:session-filter': None}, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='receiver-link-863771c3-f490-4ace-b431-cdee52bc1c27', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=1048576, offered_capabilities=None, desired_capabilities=None, properties={b'com.microsoft:receiver-name': 'SBReceiver-aabddf86-91c3-4097-939d-968c967a9003'})
2024-11-20 21:18:13,472 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-20 21:18:13,516 | MainThread | DEBUG | azure.servicebus._pyamqp.link | <- AttachFrame(name=b'863771c3-f490-4ace-b431-cdee52bc1c27', handle=2, role=False, send_settle_mode=0, rcv_settle_mode=1, source=[b'amqps://****.servicebus.windows.net/****-session-queue', None, None, None, None, None, None, {b'com.microsoft:session-filter': b'test_session'}, None, None, None], target=[b'receiver-link-863771c3-f490-4ace-b431-cdee52bc1c27', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=1048576, offered_capabilities=b'SHARED-SUBS', desired_capabilities=None, properties={b'com.microsoft:receiver-name': b'SBReceiver-aabddf86-91c3-4097-939d-968c967a9003', b'app-id': b'1950a258-227b-4e31-a9cf-717495945fc2', b'auth-type': b'AAD', b'client-id': b'SBReceiver-aabddf86-91c3-4097-939d-968c967a9003', b'com.microsoft:timeout': 65000, b'client-ip': b'13.66.10.147', b'client-network-type': 1, b'client-auth-id': b'1950a258-227b-4e31-a9cf-717495945fc2', b'client-auth-type': 4, b'com.microsoft:locked-until-utc': 638677345934863086})
2024-11-20 21:18:13,517 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-20 21:18:13,517 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=0, available=None, drain=None, echo=None, properties=None)
2024-11-20 21:18:13,568 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,569 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=10, available=None, drain=None, echo=None, properties=None)
2024-11-20 21:18:13,570 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,612 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=1, delivery_tag=b'\xd6\x84\x905\xb2\x03\nE\x95\x934?\x12t\xdd\xcd', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,613 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,613 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=2, delivery_tag=b'\x81\xfb\xbb\xbd\x99@\xccA\xb6\xb4i\xffJ\x19:\xf8', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,613 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,613 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=3, delivery_tag=b'\x8f\xe9\x13\xd9.\x05\x92M\x896U\x14V\xabD\xa4', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,613 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=4, delivery_tag=b'5\x0b\xa6h\xeen\xa3O\xa3tj\x0b*Y\xe6=', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=5, delivery_tag=b'\xe2$\x85\\\xee\xd6\xe4N\xa1\xf7\xe6K\xe2ox^', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=6, delivery_tag=b'\xff\xf9\xbai\xf5v\x87M\xbf\x0f\x9c\x12vWz\xfe', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,614 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=7, delivery_tag=b'\x1a\xa2\n\x1a\xf3\xdfTD\x8aI\xffEb7\xf2\xdd', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=8, delivery_tag=b'\x1a\xf4\x9f\x0c\x86;^B\x94l\x7f\xd2\xbf\x99\xae\x1f', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=9, delivery_tag=b'\xe2\xc3\x86\xe2;\x86\xd2J\x86^z\xa5\x87\x8d5:', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.cbs | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-20 21:18:13,615 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | <- TransferFrame(handle=2, delivery_id=10, delivery_tag=b'\xac\x9aW\xbd\x97C\x18J\x87_\xf9\x04\xe1nD\x12', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 21, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 22, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 23, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 24, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 25, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,616 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 26, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,617 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 27, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,617 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 28, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,617 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 29, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,617 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 30, enqd-utc: datetime.datetime(2024, 11, 20, 20, 55, 39, 220000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-20 21:18:13,618 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=1, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,618 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=2, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,618 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=3, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,618 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=4, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,619 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=5, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,619 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=6, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,619 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=7, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,620 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=8, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,620 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=9, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,620 | MainThread | DEBUG | azure.servicebus._pyamqp.receiver | -> DispositionFrame(role=True, first=10, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-20 21:18:13,620 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> DetachFrame(handle=3, closed=True, error=None)
2024-11-20 21:18:13,621 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-20 21:18:13,621 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> DetachFrame(handle=2, closed=True, error=None)
2024-11-20 21:18:13,621 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-20 21:18:13,621 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-20 21:18:13,621 | MainThread | DEBUG | azure.servicebus._pyamqp.link | -> DetachFrame(handle=1, closed=True, error=None)
2024-11-20 21:18:13,621 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-20 21:18:13,621 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-20 21:18:13,621 | MainThread | DEBUG | azure.servicebus._pyamqp.session | -> EndFrame(error=None)
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.session | Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4>
2024-11-20 21:18:13,622 | MainThread | DEBUG | azure.servicebus._pyamqp._connection | -> CloseFrame(error=None)
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp._connection | Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.session | Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-20 21:18:13,622 | MainThread | INFO | azure.servicebus._pyamqp.management_link | Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-20 21:18:13,623 | MainThread | INFO | azure.servicebus._pyamqp.link | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>

github-actions[bot] commented 1 day ago

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

ADevBelgie commented 1 day ago

@kashifkhan Thank you for the quick response and sample. Some clarifications:

We're using pyamqp transport (visible in user-agent string from logs)
Yes, messages are present in the queue (confirmed via peek)
The "Session error" log is from our custom logging, capturing the receiver failure

The key difference I notice is that your sample uses synchronous code while we're using async. Our async implementation shows:

CBS auth succeeds
Queue peek works (we can see messages)
Receiver attachment succeeds briefly
But then immediately detaches

We've also tried your suggested logging config and can now see the frame-level details. Key sequence:

21:20:01,225 - Receiver attaches with session filter
21:20:01,230 - Link shows ATTACHED state
21:20:01,283 - Management links attach successfully
21:20:01,294 - Immediate detach frames sent

Looking at receiver creation:
```python
self._receiver = self._client.get_queue_receiver(
    queue_name=self.queue_name,
    session_id=session_id or NEXT_AVAILABLE_SESSION,
    max_wait_time=30,
    receive_mode=ServiceBusReceiveMode.PEEK_LOCK,
    prefetch_count=10,
    max_session_lock_renewal_duration=300
)

The difference seems to be in how the async session receiver maintains its lifecycle. Could this be related to session lock acquisition timing in the async path?

ADevBelgie commented 1 day ago

@kashifkhan We've found the root cause and a solution. The issue was in the async receiver lifecycle management, specifically around how the session link is established and maintained.

Root Cause: The issue stems from how the async session receiver context is managed. The receiver would successfully establish a link but then immediately detach due to premature context closure. Specifically:

Receiver creation and link attachment succeeded
Session filter was correctly configured (visible in attach frame)
But the async context management caused immediate detachment

Solution: We modified the receiver initialization to properly manage the async context:

# Before - would cause immediate detachment
async with self._receiver:  # Context closes immediately after verification
    if await self._receiver._handler.client_ready_async():
        return self._receiver

# After - maintains the session
receiver = self._client.get_queue_receiver(...)
await receiver._open_with_retry()  # Start receiver without closing context
if hasattr(receiver, '_handler') and receiver._handler:
    if await receiver._handler.client_ready_async():
        self._receiver = receiver
        return receiver

This keeps the session link active while allowing the receiver to process messages.

Verification: Logs now show successful session establishment and message processing:

2024-11-21 00:50:11,988 - INFO - Message processed successfully
2024-11-21 00:50:11,989 - DEBUG - DispositionFrame role=True, settled=True

The CBS token remains valid and the session stays active for continuous message processing.

This seems to be a key difference in how session receivers need to be managed in the async path compared to sync. Would it be worth documenting this pattern for other async users?

kashifkhan commented 14 hours ago

Hi @ADevBelgie , thank you for your response and some clarifications. We were wondering why a Session error was showing up at the customer level and your code snippet makes that clear.

We would not document or suggest that as a pattern for customers to use since its using private methods at the deepest levels of the library, which can be changed at any time and lead to apps being broken. There is no need to be using those methods publicly.

The recommended approach for async is below a long with the logs. It works similar to sync and I have tested the following scenarios

A queue filled with messages for different sessions
An empty queue, code waits for message. On message it delivers it

import os
import asyncio
from azure.servicebus.aio import ServiceBusClient
from azure.servicebus import NEXT_AVAILABLE_SESSION
from azure.identity.aio import AzurePowerShellCredential

from dotenv import load_dotenv, find_dotenv

load_dotenv(find_dotenv())

FULLY_QUALIFIED_NAMESPACE = os.environ["SERVICEBUS_FULLY_QUALIFIED_NAMESPACE"]
SESSION_QUEUE_NAME = os.environ["SERVICEBUS_SESSION_QUEUE_NAME"]

import logging
import sys

log_fmt = logging.Formatter(fmt="%(asctime)s | %(threadName)s | %(levelname)s | %(name)s | %(message)s")
logger = logging.getLogger("azure")
logger.setLevel(logging.DEBUG)
file_handler = logging.FileHandler(filename="sample.log")
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(log_fmt)
logger.addHandler(file_handler)

async def main():
    credential = AzurePowerShellCredential()
    servicebus_client = ServiceBusClient(FULLY_QUALIFIED_NAMESPACE, credential, logging_enable=True)
    receiver = servicebus_client.get_queue_receiver(queue_name=SESSION_QUEUE_NAME, session_id=NEXT_AVAILABLE_SESSION)
    async with receiver:
        messages = await receiver.receive_messages(max_message_count=10)
        print(f"Received {len(messages)} messages.")
        for idx, message in enumerate(messages):
            print(str(message))
            await receiver.complete_message(message)
    print("Receive is done.")

asyncio.run(main())

2024-11-21 14:28:43,089 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: None -> <ConnectionState.START: 0>
2024-11-21 14:28:43,158 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._connection_async | -> Header(b'AMQP\x00\x01\x00\x00')
2024-11-21 14:28:43,158 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2024-11-21 14:28:43,159 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2024-11-21 14:28:43,159 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._connection_async | -> OpenFrame(container_id='SBReceiver-081a0dba-4ce6-45b8-81e2-3fa9e0676725', hostname='****.servicebus.windows.net', max_frame_size=1048576, channel_max=65535, idle_timeout=None, outgoing_locales=None, incoming_locales=None, offered_capabilities=None, desired_capabilities=None, properties={'product': 'azsdk-python-servicebus', 'version': '7.13.0', 'framework': 'Python/3.11.10', 'platform': 'Linux-5.15.167.4-microsoft-standard-WSL2-x86_64-with-glibc2.35', 'user-agent': 'azsdk-python-servicebus/7.13.0 pyamqp/2.0.0a1 Python/3.11.10 (Linux-5.15.167.4-microsoft-standard-WSL2-x86_64-with-glibc2.35)'})
2024-11-21 14:28:43,159 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2024-11-21 14:28:43,159 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> BeginFrame(remote_channel=None, next_outgoing_id=0, incoming_window=65536, outgoing_window=65536, handle_max=4294967295, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,160 | MainThread | INFO | azure.servicebus._pyamqp.aio._session_async | Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2024-11-21 14:28:43,160 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> AttachFrame(name='e33e55bd-9389-496e-b10d-0ab98070b156', handle=2, role=True, send_settle_mode=0, rcv_settle_mode=0, source=Source(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters=None, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,160 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-21 14:28:43,160 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-21 14:28:43,161 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> AttachFrame(name='6df3e435-3a3a-46f3-ad28-0fe058396eff', handle=1, role=False, send_settle_mode=0, rcv_settle_mode=0, source=Source(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters=None, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='$cbs', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,161 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-21 14:28:43,161 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-21 14:28:43,193 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._connection_async | <- Header(b'AMQP\x00\x01\x00\x00')
2024-11-21 14:28:43,193 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2024-11-21 14:28:43,244 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._connection_async | <- OpenFrame(container_id=b'52a139e9f93743d7b0ce32db98b64ce0_G10', hostname=None, max_frame_size=65536, channel_max=4999, idle_timeout=120000, outgoing_locales=None, incoming_locales=None, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,245 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2024-11-21 14:28:43,295 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | <- BeginFrame(remote_channel=1, next_outgoing_id=1, incoming_window=5000, outgoing_window=65536, handle_max=255, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,296 | MainThread | INFO | azure.servicebus._pyamqp.aio._session_async | Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2024-11-21 14:28:43,346 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | <- AttachFrame(name=b'e33e55bd-9389-496e-b10d-0ab98070b156', handle=0, role=False, send_settle_mode=0, rcv_settle_mode=0, source=[b'$cbs', None, None, None, None, None, None, None, None, None, None], target=[b'$cbs', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=18446744073709551615, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,347 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-21 14:28:43,347 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-21 14:28:43,347 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> FlowFrame(next_incoming_id=1, incoming_window=65536, next_outgoing_id=0, outgoing_window=65536, handle=2, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2024-11-21 14:28:43,398 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | <- AttachFrame(name=b'6df3e435-3a3a-46f3-ad28-0fe058396eff', handle=1, role=True, send_settle_mode=0, rcv_settle_mode=0, source=[b'$cbs', None, None, None, None, None, None, None, None, None, None], target=[b'$cbs', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=18446744073709551615, offered_capabilities=None, desired_capabilities=None, properties=None)
2024-11-21 14:28:43,398 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-21 14:28:43,399 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-21 14:28:43,399 | MainThread | INFO | azure.servicebus._pyamqp.aio._cbs_async | CBS completed opening with status: <ManagementOpenResult.OK: 1>
2024-11-21 14:28:43,399 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> FlowFrame(next_incoming_id=1, incoming_window=65536, next_outgoing_id=0, outgoing_window=65536, handle=1, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2024-11-21 14:28:45,981 | MainThread | INFO | azure.identity.aio._internal.decorators | AzurePowerShellCredential.get_token succeeded
2024-11-21 14:28:45,981 | MainThread | DEBUG | azure.identity.aio._internal.decorators | [Authenticated account] Client ID: 1950a258-227b-4e31-a9cf-717495945fc2. Tenant ID: 72f988bf-86f1-41af-91ab-2d7cd011db47. User Principal Name: kashifkhan@microsoft.com. Object ID (user): fa54e51e-ab45-4fa9-b655-4b8b601b82c4
2024-11-21 14:28:45,982 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> TransferFrame(handle=1, delivery_id=0, delivery_tag=b'\x00\x00\x00\x01', message_format=0, settled=False, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=None, payload=b'***')
2024-11-21 14:28:45,982 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | <- FlowFrame(next_incoming_id=0, incoming_window=5000, next_outgoing_id=1, outgoing_window=65536, handle=1, delivery_count=0, link_credit=100, available=0, drain=None, echo=False, properties=None)
2024-11-21 14:28:46,033 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS update in progress. Token put time: 1732199325
2024-11-21 14:28:46,034 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | <- DispositionFrame(role=True, first=0, last=None, settled=True, state={'accepted': []}, batchable=None)
2024-11-21 14:28:46,085 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS update in progress. Token put time: 1732199325
2024-11-21 14:28:46,085 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=0, delivery_id=0, delivery_tag=b'\x01\x00\x00\x00', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=False, payload=b'***')
2024-11-21 14:28:46,086 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2024-11-21 14:28:46,136 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,136 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> AttachFrame(name='df33ec07-b36c-4a20-a058-f9136645917c', handle=3, role=True, send_settle_mode=0, rcv_settle_mode=1, source=Source(address='amqps://****.servicebus.windows.net/****-session-queue', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, distribution_mode=None, filters={b'com.microsoft:session-filter': None}, default_outcome=None, outcomes=None, capabilities=None), target=Target(address='receiver-link-df33ec07-b36c-4a20-a058-f9136645917c', durable=None, expiry_policy=None, timeout=None, dynamic=None, dynamic_node_properties=None, capabilities=None), unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=1048576, offered_capabilities=None, desired_capabilities=None, properties={b'com.microsoft:receiver-name': 'SBReceiver-081a0dba-4ce6-45b8-81e2-3fa9e0676725'})
2024-11-21 14:28:46,137 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2024-11-21 14:28:46,173 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | <- AttachFrame(name=b'df33ec07-b36c-4a20-a058-f9136645917c', handle=2, role=False, send_settle_mode=0, rcv_settle_mode=1, source=[b'amqps://****.servicebus.windows.net/****-session-queue', None, None, None, None, None, None, {b'com.microsoft:session-filter': b'hi'}, None, None, None], target=[b'receiver-link-df33ec07-b36c-4a20-a058-f9136645917c', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=0, max_message_size=1048576, offered_capabilities=b'SHARED-SUBS', desired_capabilities=None, properties={b'com.microsoft:receiver-name': b'SBReceiver-081a0dba-4ce6-45b8-81e2-3fa9e0676725', b'app-id': b'1950a258-227b-4e31-a9cf-717495945fc2', b'auth-type': b'AAD', b'client-id': b'SBReceiver-081a0dba-4ce6-45b8-81e2-3fa9e0676725', b'com.microsoft:timeout': 65000, b'client-ip': b'13.66.10.149', b'client-network-type': 1, b'client-auth-id': b'1950a258-227b-4e31-a9cf-717495945fc2', b'client-auth-type': 4, b'com.microsoft:locked-until-utc': 638677964261447280})
2024-11-21 14:28:46,173 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2024-11-21 14:28:46,173 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=0, available=None, drain=None, echo=None, properties=None)
2024-11-21 14:28:46,224 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,224 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=10, available=None, drain=None, echo=None, properties=None)
2024-11-21 14:28:46,225 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,260 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=1, delivery_tag=b'\x84\xf5Q\xfd$\xb4\xa7J\x96\xa6\x92I)\xd9\xc1=', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,260 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,261 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=2, delivery_tag=b'\xccu\xf4 <7\x9bH\x88\xd5\x00\xb6\x13o\xe89', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,261 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,261 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=3, delivery_tag=b'\xd0JK9\xc0\x1a\xaeH\xb5\x8e\x93D\x81t\xfb\x81', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=4, delivery_tag=b' \xa7i\xc0\xee\xec\xa1O\xb4\x90\xba6s\x9e\xe3\x02', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=5, delivery_tag=b'\x7fk\xc5\xa1\x9dE\x01K\x81Z\xb8/\x9e\x81"z', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,262 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=6, delivery_tag=b'>b\x8e=\xa3\x00IH\xa6\x02:\xa0\xf4\x0f\x8a\xe0', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=7, delivery_tag=b'\x1f\xe1\x1e0\xa0\xed\xe1G\xaa\x82\xbb\xb8\xa9 \xdd\xd0', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=8, delivery_tag=b'\xc3\xb36\x8c\xaf\tVI\x85\xef\xd5\xe5\x8b\xccQS', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,263 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=9, delivery_tag=b'\xe8\x87\xc8\xa6\x9e\xf3\xd8K\xa8"\x03\x14\xa7\xda{\xfd', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._cbs_async | CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | <- TransferFrame(handle=2, delivery_id=10, delivery_tag=b'\\\x0b\x14"@\xda\x9dD\xa5^v\x00\xa0L\xfd%', message_format=0, settled=None, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=True, payload=b'***')
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 253, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 254, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 255, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,264 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 256, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 257, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 258, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 259, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 260, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 261, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,265 | MainThread | DEBUG | azure.servicebus._transport._pyamqp_transport | Received message: seq-num: 262, enqd-utc: datetime.datetime(2024, 11, 21, 14, 28, 2, 206000, tzinfo=datetime.timezone.utc), lockd-til-utc: None, ttl: None, dlvry-cnt: 0
2024-11-21 14:28:46,266 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=1, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,266 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=2, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,266 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=3, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,267 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=4, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,267 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=5, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,267 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=6, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,268 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=7, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,268 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=8, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,268 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=9, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,269 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._receiver_async | -> DispositionFrame(role=True, first=10, last=None, settled=True, state=Accepted(), batchable=None)
2024-11-21 14:28:46,269 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> DetachFrame(handle=3, closed=True, error=None)
2024-11-21 14:28:46,269 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-21 14:28:46,269 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> DetachFrame(handle=2, closed=True, error=None)
2024-11-21 14:28:46,270 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-21 14:28:46,270 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-21 14:28:46,270 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._link_async | -> DetachFrame(handle=1, closed=True, error=None)
2024-11-21 14:28:46,270 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-21 14:28:46,270 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2024-11-21 14:28:46,270 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._session_async | -> EndFrame(error=None)
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._session_async | Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4>
2024-11-21 14:28:46,271 | MainThread | DEBUG | azure.servicebus._pyamqp.aio._connection_async | -> CloseFrame(error=None)
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._connection_async | Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._session_async | Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._management_link_async | Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2024-11-21 14:28:46,271 | MainThread | INFO | azure.servicebus._pyamqp.aio._link_async | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>

github-actions[bot] commented 14 hours ago

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

Azure / azure-sdk-for-python

ServiceBus SDK: Session-enabled queue receiver links detach immediately after successful attachment with "Session error" #38629