ServiceBus AMQP - idle_timeout is not used with NEXT_AVAILABLE session

[K3UL]

• Package Name: azure-servicebus
• Package Version: 0.50.2
• Operating System: Windows 10
• Python Version: 3.8.0

Describe the bug
I am using azure.servicebus.ServiceBusClient with session-enabled topics.
I create a Receiver with a certain idle_timeout (in seconds) and then call fetch_next with the same number for the argument timeout.

I am working on a topic where there is no message currently circulating, only me trying to listen.

• If I provide to the receiver a specific session ID (any GUID), fetch_next returns after the specified timeout.

• If instead I give NEXT_AVAILABLE for the session ID, fetch_next blocks for a minutem no matter the value of the timeout I provide. Also I receive a VendorLinkDetach('com.microsoft:timeout:...').

To Reproduce
Steps to reproduce the behavior:

1. Create a SubscriptionClient
2. Create a receiver receiver: Receiver = subscription_client.get_receiver(mode=ReceiveSettleMode.PeekLock, session=NEXT_AVAILABLE, idle_timeout=4)
3. Call receiver.fetch_next(1, timeout=4)

The method will return/throw after 1 minute instead of 4 seconds. It will behave correctly (use the 4 seconds timeout) if you pass a GUID instead of NEXT_AVAILABLE.

Expected behavior
Behavior consistent with GUID session IDs, fetch_next (or enter when using the context manager) returning after the timeout that is specified.

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context
Here is a snippet of code that can be used to reproduce the problem, and the output I get :

import logging
import time
import uuid
from datetime import timedelta

from azure.servicebus import ServiceBusClient, ReceiveSettleMode, NoActiveSession, NEXT_AVAILABLE
from azure.servicebus.receive_handler import Receiver

CONN_STRING = "Endpoint=sb://secret.servicebus.windows.net/;SharedAccessKeyName=agent;SharedAccessKey=secret"
logging.getLogger().setLevel(logging.WARNING)

if __name__ == "__main__":
    bus_client = ServiceBusClient.from_connection_string(CONN_STRING)
    subscription_client = bus_client.get_subscription("secret", "secret")
    for session_id in ("", NEXT_AVAILABLE):
        print("///////////////////////////////////////////////")
        print(f" USING SESSION {'NEXT_AVAILABLE' if session_id else 'GUID'}")
        print("///////////////////////////////////////////////")

        for i in range(1, 5):
            _session = session_id or str(uuid.uuid4())
            print("    -----------------------------------------------")
            print(f"    TIMEOUT SET TO {i}")
            start = time.monotonic_ns()
            receiver: Receiver = subscription_client.get_receiver(mode=ReceiveSettleMode.PeekLock,
                                                                  session=_session, idle_timeout=i)
            print("    Got receiver")
            try:
                receiver.fetch_next(1, timeout=i)
            except NoActiveSession:
                pass
            except Exception as err:
                print(err)
            finally:
                receiver.close()

            duration_ns = time.monotonic_ns() - start
            duration = timedelta(microseconds=duration_ns/1000)
            print(f"    EXECUTED IN {duration_ns} ns")
            print(f"    TIMEOUT {i} -- EXECUTED IN {duration}")

    print("Finished")

///////////////////////////////////////////////
 USING SESSION GUID
///////////////////////////////////////////////
    -----------------------------------------------
    TIMEOUT SET TO 1
    Got receiver
    EXECUTED IN 1765000000 ns
    TIMEOUT 1 -- EXECUTED IN 0:00:01.765000
    -----------------------------------------------
    TIMEOUT SET TO 2
    Got receiver
    EXECUTED IN 2766000000 ns
    TIMEOUT 2 -- EXECUTED IN 0:00:02.766000
    -----------------------------------------------
    TIMEOUT SET TO 3
    Got receiver
    EXECUTED IN 3765000000 ns
    TIMEOUT 3 -- EXECUTED IN 0:00:03.765000
    -----------------------------------------------
    TIMEOUT SET TO 4
    Got receiver
    EXECUTED IN 4782000000 ns
    TIMEOUT 4 -- EXECUTED IN 0:00:04.782000
///////////////////////////////////////////////
 USING SESSION NEXT_AVAILABLE
///////////////////////////////////////////////
    -----------------------------------------------
    TIMEOUT SET TO 1
    Got receiver
VendorLinkDetach('com.microsoft:timeout: The operation did not complete within the allocated time 00:01:00 for object attach. For more information on exception types and proper exception handling, please refer to http://go.microsoft.com/fwlink/?LinkId=
761101 TrackingId:secret, SystemTracker:gateway5, Timestamp:2020-01-10T17:14:54')
    EXECUTED IN 62640000000 ns
    TIMEOUT 1 -- EXECUTED IN 0:01:02.640000
    -----------------------------------------------
    TIMEOUT SET TO 2
    Got receiver
VendorLinkDetach('com.microsoft:timeout: The operation did not complete within the allotted timeout of 00:01:00. The time allotted to this operation may have been a portion of a longer timeout. For more information on exception types and proper excepti
on handling, please refer to http://go.microsoft.com/fwlink/?LinkId=761101 TrackingId:secret, SystemTracker:secret:Topic:secret|secret, Timestamp:2020-01-10T17:15:55 TrackingId:secret, SystemTracker:gateway5, Timestamp:2020-01-10T17:15:55')
    EXECUTED IN 60703000000 ns
    TIMEOUT 2 -- EXECUTED IN 0:01:00.703000
    -----------------------------------------------
    TIMEOUT SET TO 3
    Got receiver
VendorLinkDetach('com.microsoft:timeout: The operation did not complete within the allocated time 00:01:00 for object attach. For more information on exception types and proper exception handling, please refer to http://go.microsoft.com/fwlink/?LinkId=
761101 TrackingId:secret, SystemTracker:gateway5, Timestamp:2020-01-10T17:16:57')
    EXECUTED IN 62594000000 ns
    TIMEOUT 3 -- EXECUTED IN 0:01:02.594000
    -----------------------------------------------
    TIMEOUT SET TO 4
    Got receiver
VendorLinkDetach('com.microsoft:timeout: The operation did not complete within the allotted timeout of 00:01:00. The time allotted to this operation may have been a portion of a longer timeout. For more information on exception types and proper excepti
on handling, please refer to http://go.microsoft.com/fwlink/?LinkId=761101 TrackingId:secret, SystemTracker:secret:Topic:secret|secret, Timestamp:2020-01-10T17:17:58 TrackingId:secret, SystemTracker:gateway5, Timestamp:2020-01-10T17:17:58')
    EXECUTED IN 60797000000 ns
    TIMEOUT 4 -- EXECUTED IN 0:01:00.797000
Finished

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @jfggdl

[nemakam]

@mayurid ,
This seems to be a client side bug.
Could you please assign it to the appropriate team for investigating this on the python client side.

[yunhaoling]

@K3UL sorry for missing the issue here.
We're looking into the issue and will update you if we make any progress on this.
Thanks for your patience in advance.