Creating sender connection is taking 8-10 seconds after the connection is closed after idle connection timeout.

[fhzhang]

• Package Name: azure-servicebus
• Package Version: 7.12.1
• Operating System: Windows
• Python Version: 3.12.3

Describe the bug
For the first time when we create the sender object, it is ONLY taking 1-2 seconds, but after sleeping for 660 seconds, the connection is closed automatically and try to create sender object again with following code.
logger.info("getting queue sender")
asb_sender = asb_client.get_queue_sender(queue_name=QUEUE_NAME)

It will take 8-10 seconds to create the sender.

My question is how come it will take ONLY 1-2 seconds for the first time, but it takes more than 8 seconds after the connection is closed after the idle connection timeout.

To Reproduce
Steps to reproduce the behavior:

1. Please refer to following python code.

from datetime import datetime
import logging
import sys
import time
#import pandas as pd
from azure.servicebus import ServiceBusClient, ServiceBusMessage, ServiceBusSender, TransportType

WAIT_SECONDS = 660
RETRIES = 5
CLOSE_SENDER = False
CONN_STR = "Endpoint=sb://xxx.servicebus.windows.net/;SharedAccessKeyName=RootManageSharedAccessKey;SharedAccessKey=xxxxabcxxxx=;TransportType=AmqpWebSockets"
QUEUE_NAME = "1234"

file_name = datetime.now().strftime(f"{RETRIES}retries_{WAIT_SECONDS}wait_between_retries")
if CLOSE_SENDER:
    file_name += "_closing_sender"

def __set_logger():
    """
    Sets module logger
    """
    log_fmt = logging.Formatter(fmt="%(asctime)s | %(levelname)s | %(name)s | %(message)s")
    logger = logging.getLogger("ServiceBus")
    logger.setLevel(logging.INFO)

    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setLevel(logging.INFO)
    console_handler.setFormatter(log_fmt)

    file_handler = logging.FileHandler(f"{file_name}.log")
    file_handler.setLevel(logging.INFO)
    file_handler.setFormatter(log_fmt)
    
    logger.addHandler(console_handler)
    logger.addHandler(file_handler)

    return logger


logger = __set_logger()

logger.info("Connecting to sb...")
asb_client = ServiceBusClient.from_connection_string(
                    conn_str=CONN_STR, 
                    transport_type=TransportType.AmqpOverWebsocket
                )
logger.info("Service Bus connected")

logger.info("Creating sender...")
asb_sender = asb_client.get_queue_sender(queue_name=QUEUE_NAME)
logger.info("Sender created")

csv_rows = []
for n in range(RETRIES):
    msg = ServiceBusMessage("test")

    logger.info("Sending message")
    start = time.time()
    if CLOSE_SENDER:
        logger.info("getting queue sender")
        asb_sender = asb_client.get_queue_sender(queue_name=QUEUE_NAME)
    asb_sender.send_messages(msg)
    if CLOSE_SENDER:
        asb_sender.close()
    end = time.time()
    elapsed = end-start
    logger.info("Message sent")
    csv_rows.append({
        'message': n,
        'time': elapsed
    })
    asb_sender.create_message_batch(max_size_in_bytes=None)
    time.sleep(660)

#pd.DataFrame.from_records(csv_rows).to_csv(f"{file_name}.csv", index=False)

Expected behavior
Since it is taking 1-2 seconds for the first time sender connection, it should take 1-2 seconds after the idle connection timeout.

Screenshots
2024-04-18 18:07:11,270 | INFO | ServiceBus | Connecting to sb...
2024-04-18 18:07:11,271 | INFO | ServiceBus | Service Bus connected
2024-04-18 18:07:11,271 | INFO | ServiceBus | Creating sender...
2024-04-18 18:07:11,377 | INFO | ServiceBus | Sender created
2024-04-18 18:07:11,377 | INFO | ServiceBus | Sending message
2024-04-18 18:07:14,875 | INFO | ServiceBus | Message sent
2024-04-18 18:18:14,878 | INFO | ServiceBus | Sending message
2024-04-18 18:18:25,748 | INFO | ServiceBus | Message sent

Additional context
Add any other context about the problem here.

[github-actions]

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

[kashifkhan]

Thank you for the feedback @fhzhang. We will investigate and get back to you asap.

[kashifkhan]

@fhzhang Looking at the repro, there are a few changes that need to be made to determine the amount of time it takes to connect to ServiceBus

Taking a look at the snippet below, no connection activity happens until the first action is executed, which in this case is send_messages. The entire process of creating the client and then the sender do not open a connection.

So the proper way to update the snippet above would be to calculate the start time after send messages, as it will first check if the connection is open, then open it and then send the message. After a connection detach, there is some clean up that needs to happen and that can take some time too. If you set the log level to DEBUG youll see when the connection activity starts

asb_client = ServiceBusClient.from_connection_string(
                    conn_str=CONN_STR, 
                    transport_type=TransportType.AmqpOverWebsocket
                )
asb_sender = asb_client.get_queue_sender(queue_name=QUEUE_NAME)
msg = ServiceBusMessage("test")

asb_sender.send_messages(msg)

[github-actions]

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

[fhzhang]

I have two questions here.

1. I am wondering if it is expected or by design to wait 9-10 seconds to get the sender connection after the idle connection timeout?
2. The main idea here is to keep the sender connection open forever.
   Currently there is NO way to configure the idle timeout, the ONLY possible option seems to be schedule a message and cancel the scheduled message right away.
   In this way we can keep the sender connection open.
   Is there any better to achieve the goal?

[kashifkhan]

@fhzhang Im taking a look at # 1 and see if there is something going on that is causing it wait 9 to 10 seconds.

for question 2, there is no other way to keep the connection open. The timeout is set by the service itself and the easiest way to show activity over the connection is to do exactly as you described.

[jonathan-fileread]

Hey @kashifkhan - we're seeing something similar as well

self.sender_dict[queue] = self.get_queue_sender(self.client, queue) self.sender_dict[queue].send_messages(ServiceBusMessage(message_base64))

After a 10 minute wait from the previous message send - we notice that our traces jump to 7-8 seconds to get a message sent through. what would the solution be for this? we'd like to maintain a good latency with sending messages to queues

[l0lawrence]

Hi @fhzhang this latency has been addressed and a fix will be out in our next release.

[github-actions]

Hi @fhzhang. 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]

Hi @fhzhang, since you haven’t asked that we /unresolve the issue, we’ll close this out. If you believe further discussion is needed, please add a comment /unresolve to reopen the issue.