azure-sdk-for-python icon indicating copy to clipboard operation
azure-sdk-for-python copied to clipboard

Published 20 hours ago • verified publisher icon Azure

Service Bus python SDK output log shows 3s interval before throw exception.

Open gujiams opened this issue 1 year ago • 24 comments

  • Package Name: azure_servicebus
  • Package Version: 7.11.2
  • Operating System:Azure Function App
  • Python Version: TBD

Describe the bug

  1. The latency issue occurs intermittently without any pattern when send message to service bus standard tier namesapce.
  2. When the code running without latency, the application log is like this: image
  3. When the code running with latency, I can see 2 exceptions, "AMQPConnectionError('Error condition: ErrorCondition.SocketError" and "AMQPLinkError("Error condition: amqp:link:detach-forced". The traffic is public to public, client side is without high cpu/memory

When the socket error occurred, the SDK output as following, there's a 3s delay between link sender state changed and exception throw

10/27/2023 5:58:02 AM | Executing 'Functions.enqueueData1' (Reason='This function was programmatically called via the host APIs.', Id=2f0b2079-75b7-4345-907e-90256c4fde97) 10/27/2023 5:58:02 AM | Python HTTP trigger function processed a request. 10/27/2023 5:58:02 AM | Message validation begins 10/27/2023 5:58:02 AM | Message validation completed 10/27/2023 5:58:02 AM | Sending message 10/27/2023 5:58:02 AM | Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4> 10/27/2023 5:58:02 AM | An error occurred when closing the connection: AMQPConnectionError('Error condition: ErrorCondition.SocketError\n Error Description: Can not send frame out due to exception: [Errno 104] Connection reset by peer') 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.END: 13> 10/27/2023 5:58:02 AM | Connection state changed: None -> <ConnectionState.START: 0> 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2> 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2> 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4> 10/27/2023 5:58:02 AM | Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1> 10/27/2023 5:58:02 AM | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:02 AM | Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:02 AM | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:02 AM | Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7> 10/27/2023 5:58:02 AM | Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9> 10/27/2023 5:58:02 AM | Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3> 10/27/2023 5:58:02 AM | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:02 AM | Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:02 AM | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:02 AM | Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:05 AM | AMQP error occurred: (AMQPLinkError("Error condition: amqp:link:detach-forced\n Error Description: The link 'G20:104524099:6f059c89-6e30-4486-9be2-37f33cd4d84a' is force detached. Code: publisher(link65173734). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.")), condition: (b'amqp:link:detach-forced'), description: (b"The link 'G20:104524099:6f059c89-6e30-4486-9be2-37f33cd4d84a' is force detached. Code: publisher(link65173734). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00."). 10/27/2023 5:58:05 AM | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4> 10/27/2023 5:58:05 AM | Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4> 10/27/2023 5:58:05 AM | Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4> 10/27/2023 5:58:05 AM | Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4> 10/27/2023 5:58:05 AM | Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11> 10/27/2023 5:58:05 AM | Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4> 10/27/2023 5:58:05 AM | Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13> 10/27/2023 5:58:05 AM | Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6> 10/27/2023 5:58:05 AM | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0> 10/27/2023 5:58:05 AM | Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0> 10/27/2023 5:58:05 AM | Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0> 10/27/2023 5:58:05 AM | Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0> 10/27/2023 5:58:06 AM | 'servicebus.pysdk-ad8e5bf4' has an exception (ServiceBusConnectionError("The link 'G20:104524099:6f059c89-6e30-4486-9be2-37f33cd4d84a' is force detached. Code: publisher(link65173734). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00. Error condition: amqp:link:detach-forced.")). Retrying... 10/27/2023 5:58:06 AM | Connection state changed: None -> <ConnectionState.START: 0> 10/27/2023 5:58:06 AM | Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2> 10/27/2023 5:58:06 AM | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4> 10/27/2023 5:58:06 AM | Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1> 10/27/2023 5:58:06 AM | Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2> 10/27/2023 5:58:06 AM | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:06 AM | Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:06 AM | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:06 AM | Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:06 AM | Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7> 10/27/2023 5:58:06 AM | Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9> 10/27/2023 5:58:06 AM | Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3> 10/27/2023 5:58:06 AM | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:06 AM | Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:06 AM | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:06 AM | Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:07 AM | Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1> 10/27/2023 5:58:07 AM | Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3> 10/27/2023 5:58:07 AM | Message sent successfully 10/27/2023 5:58:07 AM | Executed 'Functions.enqueueData1' (Succeeded, Id=2f0b2079-75b7-4345-907e-90256c4fde97, Duration=5085ms)

  1. found a smilar github bug Async Eventhub Consumer with Pyamqp: Link Detached after long idle period Results in High "User Errors" volume · Issue #28996 · Azure/azure-sdk-for-python · GitHub

  2. support ticket opened 2310260030004667

To Reproduce Steps to reproduce the behavior:

  1. code we are using `---------------------------------------------------------------------------------- shared code

def get_service_bus_queue_sender(self, conn, queue): client = ServiceBusClient.from_connection_string(conn, retry_mode= "exponential" , retry_backoff_factor= 0.5) logging.info("Service bus sender initializing") sender = client.get_queue_sender(queue) logging.info("Service bus sender initialization completed") return sender

Application code

import os import sys import json import azure.functions as func import logging from Common.shared_code.error_response_helper import ErrorResponse from azure.servicebus import ServiceBusMessage from datetime import timezone import datetime as dt from Common.shared_code.shared import Shared, Trace

msg_expiry_time = os.environ['MSG_EXPIRY_TIME_IN_HOURS']

from pathlib import Path script_location = Path(file).absolute().parents[1]

sender = None sender_001= None sender_002= None sender_003= None sender_004= None sender_005= None sender_006= None sender_007= None sender_008= None

class Enqueue: """ Enqueue class to get json output""" def init(self): self.error = None global sender global sender_001 global sender_002 global sender_003 global sender_004 global sender_005 global sender_006 global sender_007 global sender_008

    self.__queue_001 = "ellipsefoundation001"
    self.__queue_002 = "ellipsefoundation002"
    self.__queue_003 = "ellipsefoundation003"
    self.__queue_004 = "ellipsefoundation004"
    self.__queue_005 = "ellipsefoundation005"
    self.__queue_006 = "ellipsefoundation006"
    self.__queue_007 = "ellipsefoundation007"
    self.__queue_008 = "ellipsefoundation008"

    self.__api_name = "enqueueData1"

    self.__is_valid = True
    
    if sender_001 is None:
        sender_001 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation001"], self.__queue_001)
    
    if sender_002 is None:
        sender_002 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation002"], self.__queue_002)
    
    if sender_003 is None:
        sender_003 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation003"], self.__queue_003)

    if sender_004 is None:
        sender_004 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation004"], self.__queue_004)

    if sender_005 is None:
        sender_005 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation005"], self.__queue_005)

    if sender_006 is None:
        sender_006 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation006"], self.__queue_006)

    if sender_007 is None:
        sender_007 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation007"], self.__queue_007)

    if sender_008 is None:
        sender_008 = Shared().get_service_bus_queue_sender(os.environ["SERVICE_BUS_CONNECTION_STR_ellipsefoundation008"], self.__queue_008)

def push_data(self, input_json):
    """ function which send output response """

    try:
        req_data = json.loads(input_json)

        # Validating the request payload
        schema = script_location /'enqueueData'/'request_payload_schema.json'
        with open(schema) as f:
            schema = json.load(f)
        logging.info("Message validation begins")
        self.__is_valid = Shared().validate_json(req_data, schema)
        logging.info("Message validation completed")

        if self.__is_valid[0]:
            configured_tables = list(dict(os.environ).keys())
            table = req_data["control"]["table"]

            if table in configured_tables:
                table_config = os.environ[table]
            else:
                table_config = os.environ["ELLIPSE_TABLES"]

            queue_name = table_config
            session_id = table

            correlation_id = req_data["messageContext"]["correlationId"]
            message_id = req_data["messageContext"]["messageId"]

            if queue_name == self.__queue_001:
                sender = sender_001
            elif queue_name == self.__queue_002:
                sender = sender_002
            elif queue_name == self.__queue_003:
                sender = sender_003
            elif queue_name == self.__queue_004:
                sender = sender_004
            elif queue_name == self.__queue_005:
                sender = sender_005
            elif queue_name == self.__queue_006:
                sender = sender_006
            elif queue_name == self.__queue_007:
                sender = sender_007
            elif queue_name == self.__queue_008:
                sender = sender_008

            current_time = dt.datetime.utcnow()
            current_time = current_time.replace(tzinfo=timezone(dt.timedelta(hours= 0), name="GMT"))
            insertion_time = current_time.strftime(f"%A, %d %b %Y %H:%M:%S %Z")
            expiry_time = current_time + dt.timedelta(hours= int(msg_expiry_time))
            expiry_time = expiry_time.strftime(f"%A, %d %b %Y %H:%M:%S %Z")

            logging.info("Sending message")
            sender.send_messages(ServiceBusMessage(input_json, session_id=session_id, correlation_id=correlation_id, message_id= message_id, content_type='application/json', time_to_live= dt.timedelta(hours= int(msg_expiry_time))))
            logging.info("Message sent successfully")

            response_file = script_location /'enqueueData'/'sample_response.json'
            with open(response_file) as f:
                response = json.load(f)
            response["queue"]["queueName"] = queue_name
            response["queue"]["queueMessagesList"][0]["queueMessage"]["messageId"] = message_id
            response["queue"]["queueMessagesList"][0]["queueMessage"]["insertionTime"] = insertion_time
            response["queue"]["queueMessagesList"][0]["queueMessage"]["expirationTime"] = expiry_time
            response =json.dumps(response)
            Trace().trace_attributes(self.__api_name, message_id, table, queue_name)
            return func.HttpResponse(response, status_code=201, mimetype = 'application/json; charset=utf8') 
        else:
            self.error = self.__is_valid[1]
            error_json = {
                        "message": self.error.message,
                        "path":  self.error.json_path
                        }
            error_json = json.dumps(error_json)
            return func.HttpResponse(error_json, status_code=400)
            
    except Exception:
        retmsg = 'Error - Error Info :' +  str(sys.exc_info()) 
        logging.error(f"{retmsg}")
        return ErrorResponse().error_log('Internal Server Error',500)  `

Expected behavior when there's link detach error, the retry should soon success without 3s interval.

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

Additional context Add any other context about the problem here.

gujiams avatar Nov 07 '23 05:11 gujiams

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

kashifkhan avatar Nov 07 '23 14:11 kashifkhan

@gujiams are you able to run with debug logs and logging_enable set to true ? This can provide us with some further details as to whats happening behind the scenes

Turn on Debug Logging

import logging
import sys

logger = logging.getLogger('azure.servicebus')
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(stream=sys.stdout)
logger.addHandler(handler)

servicebus_client = ServiceBusClient.from_connection_string(conn_str=CONNECTION_STR, logging_enable=True)

kashifkhan avatar Nov 07 '23 15:11 kashifkhan

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

github-actions[bot] avatar Nov 07 '23 15:11 github-actions[bot]

Thanks @kashifkhan I‘m collecting the information will get back to you shortly.

gujiams avatar Nov 08 '23 08:11 gujiams

I faced the same issue lately, here are my debug logs if it helps

2023-11-08 10:02:43 [3419366] [INFO] Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4>
2023-11-08 10:02:43 [3419366] [INFO] An error occurred when closing the connection: AMQPConnectionError('Error condition: ErrorCondition.SocketError\n Error Description: Can not send frame out due to exception: [Errno 104] Connection reset by peer')
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.END: 13>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: None -> <ConnectionState.START: 0>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2023-11-08 10:02:43 [3419366] [INFO] Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2023-11-08 10:02:43 [3419366] [INFO] Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:43 [3419366] [INFO] Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:43 [3419366] [INFO] Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:43 [3419366] [INFO] Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2023-11-08 10:02:43 [3419366] [INFO] Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2023-11-08 10:02:43 [3419366] [INFO] Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2023-11-08 10:02:43 [3419366] [INFO] Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:43 [3419366] [INFO] Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:43 [3419366] [INFO] Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:43 [3419366] [INFO] Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:43 [3419366] [DEBUG] CBS completed opening with status: <ManagementOpenResult.OK: 1>
2023-11-08 10:02:43 [3419366] [DEBUG] CBS update in progress. Token put time: 1699437763
2023-11-08 10:02:43 [3419366] [DEBUG] CBS update in progress. Token put time: 1699437763
2023-11-08 10:02:43 [3419366] [DEBUG] CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2023-11-08 10:02:43 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:45 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:48 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:48 [3419366] [INFO] AMQP error occurred: (AMQPLinkError("Error condition: amqp:link:detach-forced\n Error Description: The link 'G3S1:124519395:6eaa421c-6ba2-4c1b-8e01-bc03db2aab94' is force detached. Code: publisher(link12197474). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.")), condition: (b'amqp:link:detach-forced'), description: (b"The link 'G3S1:124519395:6eaa421c-6ba2-4c1b-8e01-bc03db2aab94' is force detached. Code: publisher(link12197474). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.").
2023-11-08 10:02:48 [3419366] [INFO] Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-08 10:02:48 [3419366] [INFO] Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-08 10:02:48 [3419366] [INFO] Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-08 10:02:48 [3419366] [INFO] Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-08 10:02:48 [3419366] [INFO] Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4>
2023-11-08 10:02:48 [3419366] [INFO] Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11>
2023-11-08 10:02:48 [3419366] [INFO] Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13>
2023-11-08 10:02:48 [3419366] [INFO] Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6>
2023-11-08 10:02:48 [3419366] [INFO] Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-08 10:02:48 [3419366] [INFO] Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-08 10:02:48 [3419366] [INFO] Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-08 10:02:48 [3419366] [INFO] Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-08 10:02:50 [3419366] [INFO] 'servicebus.pysdk-e01dcf65' has an exception (ServiceBusConnectionError("The link 'G3S1:124519395:6eaa421c-6ba2-4c1b-8e01-bc03db2aab94' is force detached. Code: publisher(link12197474). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00. Error condition: amqp:link:detach-forced.")). Retrying...
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: None -> <ConnectionState.START: 0>
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2023-11-08 10:02:50 [3419366] [INFO] Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2023-11-08 10:02:50 [3419366] [INFO] Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2023-11-08 10:02:50 [3419366] [INFO] Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:50 [3419366] [INFO] Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:50 [3419366] [INFO] Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:50 [3419366] [DEBUG] CBS completed opening with status: <ManagementOpenResult.OK: 1>
2023-11-08 10:02:50 [3419366] [DEBUG] CBS update in progress. Token put time: 1699437770
2023-11-08 10:02:50 [3419366] [DEBUG] CBS update in progress. Token put time: 1699437770
2023-11-08 10:02:50 [3419366] [DEBUG] CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2023-11-08 10:02:50 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-08 10:02:50 [3419366] [INFO] Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-08 10:02:50 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:50 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:50 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-08 10:02:50 [3419366] [DEBUG] CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False

nagarajjadhav avatar Nov 08 '23 13:11 nagarajjadhav

@nagarajjadhav @gujiams Do yall happen to know the python versions that is being used for the script ? Is this running on Ubuntu ?

kashifkhan avatar Nov 09 '23 16:11 kashifkhan

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

github-actions[bot] avatar Nov 09 '23 16:11 github-actions[bot]

Hi @kashifkhan,

Here's the information: Python version: 3.9 system: Linux (detail tbd)

Please let me know if you need any other infomation.

gujiams avatar Nov 15 '23 11:11 gujiams

Hi @kashifkhan python version : 3.9.5 operating system : Ubuntu 20.04.2 LTS

nagarajjadhav avatar Nov 15 '23 12:11 nagarajjadhav

Thank you for the info @nagarajjadhav , @gujiams

Would yall be able to get DEBUG logs with logging_enable=True passed in to the init ? I'm having some difficulty with reproducing this and maybe seeing the AMQP frames will give me more insights.

kashifkhan avatar Nov 16 '23 15:11 kashifkhan

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

github-actions[bot] avatar Nov 16 '23 15:11 github-actions[bot]

Hi @kashifkhan Im able to reproduce it with following code snippet

from azure.servicebus import ServiceBusClient, ServiceBusMessage
import logging
import sys

logger = logging.getLogger('azure.servicebus')
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(stream=sys.stdout)
formatter = logging.Formatter("%(asctime)s;%(levelname)s;%(message)s")
handler.setFormatter(formatter)
logger.addHandler(handler)

connection_string = "xxxxxxxxxxx"

queue = "xxxxxxx"

servicebus_client = ServiceBusClient.from_connection_string(conn_str=connection_string,  logging_enable=True)
sender = servicebus_client.get_queue_sender(queue)
single_message = ServiceBusMessage("Single message")
sender.send_messages(single_message)

# wait for 10 minutes till link detaches then send one more message

sender.send_messages(single_message)

Here are my debug logs

2023-11-16 17:20:28,924;INFO;Connection state changed: None -> <ConnectionState.START: 0>
2023-11-16 17:20:28,926;DEBUG;-> Header(b'AMQP\x00\x01\x00\x00')
2023-11-16 17:20:28,926;INFO;Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2023-11-16 17:20:28,926;INFO;Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2023-11-16 17:20:28,926;DEBUG;-> OpenFrame(container_id='SBSender-f6a89c8f-39a1-48ee-b5b5-54824c2e5b1c', hostname='commons-workers.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.11.4', 'framework': 'Python/3.9.5', 'platform': 'Linux-5.15.0-1037-azure-x86_64-with-glibc2.31', 'user-agent': 'azsdk-python-servicebus/7.11.4 pyamqp/2.0.0a1 Python/3.9.5 (Linux-5.15.0-1037-azure-x86_64-with-glibc2.31)'})
2023-11-16 17:20:28,927;INFO;Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2023-11-16 17:20:28,927;DEBUG;-> 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)
2023-11-16 17:20:28,927;INFO;Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2023-11-16 17:20:28,928;DEBUG;-> AttachFrame(name='639b1d9f-5283-405b-abb4-56a8f3edd176', 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)
2023-11-16 17:20:28,928;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:20:28,928;INFO;Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:20:28,928;DEBUG;-> AttachFrame(name='746858f6-1c34-4cff-97bc-8e095119c32f', 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)
2023-11-16 17:20:28,929;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:20:28,929;INFO;Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:20:28,929;DEBUG;<- Header(b'AMQP\x00\x01\x00\x00')
2023-11-16 17:20:28,929;INFO;Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2023-11-16 17:20:28,979;DEBUG;<- OpenFrame(container_id=b'f0afceeb6e9e415193d3728ebf96f6ea_G20', 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)
2023-11-16 17:20:28,980;INFO;Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2023-11-16 17:20:29,030;DEBUG;<- 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)
2023-11-16 17:20:29,030;INFO;Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2023-11-16 17:20:29,081;DEBUG;<- AttachFrame(name=b'639b1d9f-5283-405b-abb4-56a8f3edd176', 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)
2023-11-16 17:20:29,081;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:20:29,081;INFO;Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:20:29,081;DEBUG;-> 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)
2023-11-16 17:20:29,132;DEBUG;<- AttachFrame(name=b'746858f6-1c34-4cff-97bc-8e095119c32f', 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)
2023-11-16 17:20:29,132;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:20:29,133;INFO;Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:20:29,133;DEBUG;CBS completed opening with status: <ManagementOpenResult.OK: 1>
2023-11-16 17:20:29,133;DEBUG;-> 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)
2023-11-16 17:20:29,184;DEBUG;-> 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'***')
2023-11-16 17:20:29,185;DEBUG;<- 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)
2023-11-16 17:20:29,235;DEBUG;CBS update in progress. Token put time: 1700155229
2023-11-16 17:20:29,235;DEBUG;<- DispositionFrame(role=True, first=0, last=None, settled=True, state={'accepted': []}, batchable=None)
2023-11-16 17:20:29,286;DEBUG;CBS update in progress. Token put time: 1700155229
2023-11-16 17:20:29,286;DEBUG;<- 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'***')
2023-11-16 17:20:29,286;DEBUG;CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2023-11-16 17:20:29,337;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:20:29,337;DEBUG;-> AttachFrame(name='4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6', handle=3, role=False, send_settle_mode=0, rcv_settle_mode=1, source=Source(address='sender-link-4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6', 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='amqps://commons-workers.servicebus.windows.net/t_queue', 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=1048576, offered_capabilities=None, desired_capabilities=None, properties=None)
2023-11-16 17:20:29,338;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:20:29,341;DEBUG;<- AttachFrame(name=b'4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6', handle=2, role=True, send_settle_mode=0, rcv_settle_mode=0, source=[b'sender-link-4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6', None, None, None, None, None, None, None, None, None, None], target=[b'amqps://commons-workers.servicebus.windows.net/t_queue', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=262144, offered_capabilities=None, desired_capabilities=None, properties=None)
2023-11-16 17:20:29,341;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:20:29,341;DEBUG;-> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2023-11-16 17:20:29,391;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:20:29,392;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:20:29,392;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:20:29,392;DEBUG;-> TransferFrame(handle=3, delivery_id=1, 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'***')
2023-11-16 17:20:29,393;DEBUG;<- FlowFrame(next_incoming_id=1, incoming_window=5000, next_outgoing_id=2, outgoing_window=65535, handle=2, delivery_count=0, link_credit=1000, available=0, drain=None, echo=False, properties=None)
2023-11-16 17:20:29,393;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:20:29,403;DEBUG;<- DispositionFrame(role=True, first=1, last=None, settled=True, state={'accepted': []}, batchable=None)

In [2]: 2023-11-16 17:20:58,960;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:21:29,195;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:21:29,195;DEBUG;<- DispositionFrame(role=False, first=0, last=None, settled=True, state={'released': []}, batchable=None)
2023-11-16 17:21:59,429;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:21:59,429;DEBUG;-> EmptyFrame()
2023-11-16 17:22:29,664;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:22:59,899;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:22:59,899;DEBUG;-> EmptyFrame()
2023-11-16 17:23:30,133;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:23:30,133;DEBUG;<- FlowFrame(next_incoming_id=2, incoming_window=5000, next_outgoing_id=2, outgoing_window=65535, handle=None, delivery_count=None, link_credit=None, available=None, drain=None, echo=True, properties=None)
2023-11-16 17:24:00,367;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:24:00,367;DEBUG;-> EmptyFrame()
2023-11-16 17:24:30,602;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:25:00,836;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:25:00,836;DEBUG;-> EmptyFrame()
2023-11-16 17:25:31,071;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:26:01,306;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:26:01,306;DEBUG;-> EmptyFrame()
2023-11-16 17:26:31,540;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:26:31,541;DEBUG;<- FlowFrame(next_incoming_id=2, incoming_window=5000, next_outgoing_id=2, outgoing_window=65535, handle=None, delivery_count=None, link_credit=None, available=None, drain=None, echo=True, properties=None)
2023-11-16 17:27:01,775;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:27:01,775;DEBUG;-> EmptyFrame()
2023-11-16 17:27:32,009;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:28:02,242;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:28:02,242;DEBUG;-> EmptyFrame()
2023-11-16 17:28:32,475;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:29:02,710;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:29:02,710;DEBUG;-> EmptyFrame()
2023-11-16 17:29:32,943;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:29:32,943;DEBUG;<- FlowFrame(next_incoming_id=2, incoming_window=5000, next_outgoing_id=2, outgoing_window=65535, handle=None, delivery_count=None, link_credit=None, available=None, drain=None, echo=True, properties=None)
2023-11-16 17:30:03,178;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:30:03,178;DEBUG;-> EmptyFrame()
2023-11-16 17:30:33,411;DEBUG;Keeping 'SendClient' connection alive.
2023-11-16 17:30:33,412;DEBUG;<- DetachFrame(handle=2, closed=True, error=[b'amqp:link:detach-forced', b"The link 'G20:678714327:4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6' is force detached. Code: publisher(link55215490). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.", None])
2023-11-16 17:30:33,412;DEBUG;-> DetachFrame(handle=3, closed=True, error=None)
2023-11-16 17:30:33,412;INFO;Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
In [2]:

In [2]: sender.send_messages(single_message)
2023-11-16 17:30:52,214;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:52,214;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:53,816;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:57,020;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:57,020;INFO;AMQP error occurred: (AMQPLinkError("Error condition: amqp:link:detach-forced\n Error Description: The link 'G20:678714327:4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6' is force detached. Code: publisher(link55215490). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.")), condition: (b'amqp:link:detach-forced'), description: (b"The link 'G20:678714327:4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6' is force detached. Code: publisher(link55215490). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00.").
2023-11-16 17:30:57,020;DEBUG;-> DetachFrame(handle=2, closed=True, error=None)
2023-11-16 17:30:57,020;INFO;Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-16 17:30:57,021;INFO;Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-16 17:30:57,021;DEBUG;-> DetachFrame(handle=1, closed=True, error=None)
2023-11-16 17:30:57,021;INFO;Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-16 17:30:57,021;INFO;Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACH_SENT: 4>
2023-11-16 17:30:57,021;DEBUG;-> EndFrame(error=None)
2023-11-16 17:30:57,021;INFO;Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_SENT: 4>
2023-11-16 17:30:57,022;DEBUG;-> CloseFrame(error=None)
2023-11-16 17:30:57,022;INFO;Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_SENT: 11>
2023-11-16 17:30:57,022;INFO;Connection state changed: <ConnectionState.CLOSE_SENT: 11> -> <ConnectionState.END: 13>
2023-11-16 17:30:57,022;INFO;Session state changed: <SessionState.END_SENT: 4> -> <SessionState.DISCARDING: 6>
2023-11-16 17:30:57,022;INFO;Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-16 17:30:57,022;INFO;Management link sender state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-16 17:30:57,022;INFO;Link state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-16 17:30:57,022;INFO;Management link receiver state changed: <LinkState.DETACH_SENT: 4> -> <LinkState.DETACHED: 0>
2023-11-16 17:30:57,022;INFO;Link state changed: <LinkState.ERROR: 6> -> <LinkState.DETACHED: 0>
2023-11-16 17:30:59,041;INFO;'servicebus.pysdk-4e124198' has an exception (ServiceBusConnectionError("The link 'G20:678714327:4ba3edc0-5f93-44d3-bfd7-ef40a6e3ddf6' is force detached. Code: publisher(link55215490). Details: AmqpMessagePublisher.IdleTimerExpired: Idle timeout: 00:10:00. Error condition: amqp:link:detach-forced.")). Retrying...
2023-11-16 17:30:59,061;INFO;Connection state changed: None -> <ConnectionState.START: 0>
2023-11-16 17:30:59,062;DEBUG;-> Header(b'AMQP\x00\x01\x00\x00')
2023-11-16 17:30:59,062;INFO;Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
2023-11-16 17:30:59,063;INFO;Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
2023-11-16 17:30:59,063;DEBUG;-> OpenFrame(container_id='SBSender-f6a89c8f-39a1-48ee-b5b5-54824c2e5b1c', hostname='commons-workers.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.11.4', 'framework': 'Python/3.9.5', 'platform': 'Linux-5.15.0-1037-azure-x86_64-with-glibc2.31', 'user-agent': 'azsdk-python-servicebus/7.11.4 pyamqp/2.0.0a1 Python/3.9.5 (Linux-5.15.0-1037-azure-x86_64-with-glibc2.31)'})
2023-11-16 17:30:59,063;INFO;Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
2023-11-16 17:30:59,063;DEBUG;-> 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)
2023-11-16 17:30:59,063;INFO;Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
2023-11-16 17:30:59,064;DEBUG;-> AttachFrame(name='6719d84a-a73c-4f8b-93b0-28cbc5a62edf', 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)
2023-11-16 17:30:59,064;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:30:59,064;INFO;Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:30:59,064;DEBUG;-> AttachFrame(name='8fcc60af-0bc1-40ef-834f-54f50be447d3', 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)
2023-11-16 17:30:59,064;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:30:59,064;INFO;Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:30:59,064;DEBUG;<- Header(b'AMQP\x00\x01\x00\x00')
2023-11-16 17:30:59,065;INFO;Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
2023-11-16 17:30:59,115;DEBUG;<- OpenFrame(container_id=b'f0afceeb6e9e415193d3728ebf96f6ea_G20', 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)
2023-11-16 17:30:59,115;INFO;Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
2023-11-16 17:30:59,166;DEBUG;<- 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)
2023-11-16 17:30:59,166;INFO;Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
2023-11-16 17:30:59,217;DEBUG;<- AttachFrame(name=b'6719d84a-a73c-4f8b-93b0-28cbc5a62edf', 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)
2023-11-16 17:30:59,217;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:30:59,217;INFO;Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:30:59,217;DEBUG;-> 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)
2023-11-16 17:30:59,268;DEBUG;<- AttachFrame(name=b'8fcc60af-0bc1-40ef-834f-54f50be447d3', 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)
2023-11-16 17:30:59,268;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:30:59,268;INFO;Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:30:59,268;DEBUG;CBS completed opening with status: <ManagementOpenResult.OK: 1>
2023-11-16 17:30:59,268;DEBUG;-> 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)
2023-11-16 17:30:59,319;DEBUG;-> 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'***')
2023-11-16 17:30:59,320;DEBUG;<- 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)
2023-11-16 17:30:59,370;DEBUG;CBS update in progress. Token put time: 1700155859
2023-11-16 17:30:59,371;DEBUG;<- DispositionFrame(role=True, first=0, last=None, settled=True, state={'accepted': []}, batchable=None)
2023-11-16 17:30:59,421;DEBUG;CBS update in progress. Token put time: 1700155859
2023-11-16 17:30:59,422;DEBUG;<- 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'***')
2023-11-16 17:30:59,422;DEBUG;CBS Put token result (<ManagementExecuteOperationResult.OK: 0>), status code: 202, status_description: b'Accepted'.
2023-11-16 17:30:59,472;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:59,473;DEBUG;-> AttachFrame(name='1d248f74-b0c7-4b94-b6f4-2c5a8b27b450', handle=3, role=False, send_settle_mode=0, rcv_settle_mode=1, source=Source(address='sender-link-1d248f74-b0c7-4b94-b6f4-2c5a8b27b450', 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='amqps://commons-workers.servicebus.windows.net/t_queue', 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=1048576, offered_capabilities=None, desired_capabilities=None, properties=None)
2023-11-16 17:30:59,473;INFO;Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
2023-11-16 17:30:59,476;DEBUG;<- AttachFrame(name=b'1d248f74-b0c7-4b94-b6f4-2c5a8b27b450', handle=2, role=True, send_settle_mode=0, rcv_settle_mode=0, source=[b'sender-link-1d248f74-b0c7-4b94-b6f4-2c5a8b27b450', None, None, None, None, None, None, None, None, None, None], target=[b'amqps://commons-workers.servicebus.windows.net/t_queue', None, None, None, None, None, None], unsettled=None, incomplete_unsettled=None, initial_delivery_count=None, max_message_size=262144, offered_capabilities=None, desired_capabilities=None, properties=None)
2023-11-16 17:30:59,476;INFO;Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
2023-11-16 17:30:59,476;DEBUG;-> FlowFrame(next_incoming_id=2, incoming_window=65535, next_outgoing_id=1, outgoing_window=65535, handle=3, delivery_count=0, link_credit=10000, available=None, drain=None, echo=None, properties=None)
2023-11-16 17:30:59,526;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:59,527;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:59,527;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:59,527;DEBUG;-> TransferFrame(handle=3, delivery_id=1, 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'***')
2023-11-16 17:30:59,527;DEBUG;<- FlowFrame(next_incoming_id=1, incoming_window=5000, next_outgoing_id=2, outgoing_window=65535, handle=2, delivery_count=0, link_credit=1000, available=0, drain=None, echo=False, properties=None)
2023-11-16 17:30:59,527;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:30:59,547;DEBUG;<- DispositionFrame(role=True, first=1, last=None, settled=True, state={'accepted': []}, batchable=None)

In [3]: sender.send_messages(single_message)
2023-11-16 17:31:28,761;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:31:28,761;DEBUG;CBS status check: state == <CbsAuthState.OK: 0>, expired == False, refresh required == False
2023-11-16 17:31:28,762;DEBUG;-> TransferFrame(handle=3, delivery_id=2, delivery_tag=b'\x00\x00\x00\x02', message_format=0, settled=False, more=False, rcv_settle_mode=None, state=None, resume=None, aborted=None, batchable=None, payload=b'***')
2023-11-16 17:31:28,775;DEBUG;<- DispositionFrame(role=True, first=2, last=None, settled=True, state={'accepted': []}, batchable=None)

In [4]: 2023-11-16 17:31:29,095;DEBUG;Keeping 'SendClient' connection alive.

As you can see from the logs. Once the link is detached it takes close to 7 seconds to re-establish link and send message

nagarajjadhav avatar Nov 16 '23 17:11 nagarajjadhav

logs__fndat6001.csv Hi @kashifkhan , upload the debug log in Funtion App env, please let me know if you need any further infomation

gujiams avatar Nov 22 '23 08:11 gujiams

Hi @kashifkhan any update on this

gujiams avatar Dec 04 '23 02:12 gujiams

Hi @gujiams , I'm seeing the behavior on my end but it is seeming to look like the regular retry behavior of the client library after a disconnect event from the service. The reason why there is a lag is because the exception shows up after all the retries have exhausted on the client side.

kashifkhan avatar Dec 04 '23 14:12 kashifkhan

Hi @kashifkhan thank you for the update! looks like the time is consuming on the CBS status check, is it a by design retry or we have any workaround to reduce the time? image

gujiams avatar Dec 05 '23 19:12 gujiams

Hi @gujiams,

sorry for the delay in response, but seems from the logs that this is just the normal back & forth happening between the sdk and service.

  • The CBS status check is for authentication and it runs in a background thread to make sure the token being used is not expired and tries to refresh it before that happens.
  • When the AMQP Link Error happens at 11/21/2023, 9:09:47.279 AM, its coming from the service and on the next line the sdk sends a detach to start disconnecting.
  • The client then starts through the process of closing the connection, session etc. as part of the clean up process.
  • At 9:09:48 AM the sdk starts retrying and re-establishing a connection with the service.
  • As soon as that handshake and other back n forth is done with the service, at 11/21/2023, 9:09:49.069 AM then message is sent successfully.

The 3 second difference here is just the normal flow between service and client (especially as it experienced a disconnect while an operation happened).

Since this ~3s is the amount of time it takes for the service to go through the detach process, there is nothing the client can do to speed up that service side process. We can only reduce the number of retries or change the retry type, but in this case won't help.

kashifkhan avatar Dec 13 '23 22:12 kashifkhan

Hi @kashifkhan, thank you very much for your analysis. We agree that the latency is by design, currently the errors occurs frequently among the day and there are always active sending message requests, we are not sure where this error coming from, do you have any idea on how to decrease this error?
the errors on sender app image the incoming messages image

gujiams avatar Jan 05 '24 18:01 gujiams

Hi @gujiams - Although you're seeing messages be sent continuously, it seems that only some of the senders are being utilized and others inactive. The senders don't share a connection, so inactive senders would cause idle connections and force detaches to be sent by the service. To try to minimize this error, please ensure that all senders are active and being used within the idle timeout period.

swathipil avatar Jan 09 '24 18:01 swathipil

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

github-actions[bot] avatar Jan 10 '24 14:01 github-actions[bot]

Hi @kashifkhan @swathipil , thank you very much for your assistance. We found the same issue in production env which is latency is more than 2 mins, as production unable to have any code change, we do not have debug level log, could you help to advise on why?

the log shows "Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>" but after 3 mins, it shows "Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>"

image

gujiams avatar Jan 12 '24 01:01 gujiams

Hi @gujiams, Based on the error to the bottom of the logs, it seems that this is related to the idle connections/inactive senders/network issues. If you are still seeing this after you fix the inactive connections issue, we would need the debug logs or a sample to repro as there could be a number of errors that would cause this link state change. Thanks!

swathipil avatar Jan 12 '24 18:01 swathipil

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

github-actions[bot] avatar Jan 12 '24 18:01 github-actions[bot]

Hi @swathipil thanks for the reply, the log is all SDK activities and it is similar to the previous debug log we provided, it seems that when there was idle connection exception, the SDK has some logic spend 3s up to 2 mins to perform retry, 3s is acceptable but 2mins is too long waiting for an exception to retry, could you provide any possiable cause for this or is there any logic/configuration we can try to reduce this time

TimeGenerated Message
1/8/2024 10:33:34 PM Executing 'Functions.enqueueData3' (Reason='This function was programmatically called via the host APIs.', Id=47c66bb1-2691-4265-a7d8-21fc686f3e6d)
1/8/2024 10:33:34 PM Python HTTP trigger function processed a request.
1/8/2024 10:33:34 PM Message validation begins
1/8/2024 10:33:34 PM Message validation completed
1/8/2024 10:33:34 PM Sending message
1/8/2024 10:33:34 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>
1/8/2024 10:33:34 PM Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>
1/8/2024 10:33:34 PM CBS error occurred.
1/8/2024 10:33:34 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>
1/8/2024 10:33:34 PM Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>
1/8/2024 10:33:34 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.DETACHED: 0>
1/8/2024 10:33:34 PM Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_RCVD: 5>
1/8/2024 10:33:34 PM Session state changed: <SessionState.END_RCVD: 5> -> <SessionState.UNMAPPED: 0>
1/8/2024 10:33:34 PM Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_RCVD: 10>
1/8/2024 10:33:34 PM Connection state changed: <ConnectionState.CLOSE_RCVD: 10> -> <ConnectionState.END: 13>
1/8/2024 10:33:35 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4>
1/8/2024 10:33:36 PM Connection state changed: None -> <ConnectionState.START: 0>
1/8/2024 10:33:36 PM Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:33:36 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:33:36 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
1/8/2024 10:33:36 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
1/8/2024 10:33:36 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:33:36 PM Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:33:36 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:33:36 PM Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:33:36 PM Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
1/8/2024 10:33:36 PM Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
1/8/2024 10:33:36 PM Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
1/8/2024 10:33:36 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:33:36 PM Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:33:36 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:33:36 PM Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:34:36 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:34:36 PM Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:34:36 PM CBS error occurred.
1/8/2024 10:34:36 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:34:36 PM Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:34:36 PM Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_RCVD: 5>
1/8/2024 10:34:36 PM Session state changed: <SessionState.END_RCVD: 5> -> <SessionState.UNMAPPED: 0>
1/8/2024 10:34:36 PM Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_RCVD: 10>
1/8/2024 10:34:36 PM Connection state changed: <ConnectionState.CLOSE_RCVD: 10> -> <ConnectionState.END: 13>
1/8/2024 10:34:36 PM Connection closed with error: [b'amqp:connection:forced', b"The connection was inactive for more than the allowed 60000 milliseconds and is closed by container 'LinkTracker'. TrackingId:15421d8e36ac469c94a85aaa16f38123_G5, SystemTracker:gateway7, Timestamp:2024-01-08T22:34:36", None]
1/8/2024 10:34:38 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4>
1/8/2024 10:34:38 PM Connection state changed: None -> <ConnectionState.START: 0>
1/8/2024 10:34:38 PM Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:34:38 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:34:38 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
1/8/2024 10:34:38 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
1/8/2024 10:34:38 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:34:38 PM Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:34:38 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:34:38 PM Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:34:38 PM Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
1/8/2024 10:34:38 PM Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
1/8/2024 10:34:38 PM Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
1/8/2024 10:34:38 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:34:38 PM Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:34:38 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:34:38 PM Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:38 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:35:38 PM Management link receiver state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:35:38 PM CBS error occurred.
1/8/2024 10:35:38 PM Link state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:35:38 PM Management link sender state changed: <LinkState.ATTACHED: 3> -> <LinkState.ERROR: 6>
1/8/2024 10:35:38 PM Session state changed: <SessionState.MAPPED: 3> -> <SessionState.END_RCVD: 5>
1/8/2024 10:35:38 PM Session state changed: <SessionState.END_RCVD: 5> -> <SessionState.UNMAPPED: 0>
1/8/2024 10:35:38 PM Connection state changed: <ConnectionState.OPENED: 9> -> <ConnectionState.CLOSE_RCVD: 10>
1/8/2024 10:35:38 PM Connection state changed: <ConnectionState.CLOSE_RCVD: 10> -> <ConnectionState.END: 13>
1/8/2024 10:35:38 PM Connection closed with error: [b'amqp:connection:forced', b"The connection was inactive for more than the allowed 60000 milliseconds and is closed by container 'LinkTracker'. TrackingId:08a9f492ba0e4725b7c3ab861a1ff8bf_G80, SystemTracker:gateway7, Timestamp:2024-01-08T22:35:38", None]
1/8/2024 10:35:38 PM AMQP error occurred: (AMQPConnectionError("Error condition: amqp:connection:forced\n Error Description: The connection was inactive for more than the allowed 60000 milliseconds and is closed by container 'LinkTracker'. TrackingId:08a9f492ba0e4725b7c3ab861a1ff8bf_G80, SystemTracker:gateway7, Timestamp:2024-01-08T22:35:38")), condition: (b'amqp:connection:forced'), description: (b"The connection was inactive for more than the allowed 60000 milliseconds and is closed by container 'LinkTracker'. TrackingId:08a9f492ba0e4725b7c3ab861a1ff8bf_G80, SystemTracker:gateway7, Timestamp:2024-01-08T22:35:38").
1/8/2024 10:35:38 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.END_SENT: 4>
1/8/2024 10:35:39 PM 'servicebus.pysdk-cccda0f9' has an exception (ServiceBusConnectionError("The connection was inactive for more than the allowed 60000 milliseconds and is closed by container 'LinkTracker'. TrackingId:08a9f492ba0e4725b7c3ab861a1ff8bf_G80, SystemTracker:gateway7, Timestamp:2024-01-08T22:35:38 Error condition: amqp:connection:forced.")). Retrying...
1/8/2024 10:35:39 PM Connection state changed: None -> <ConnectionState.START: 0>
1/8/2024 10:35:39 PM Connection state changed: <ConnectionState.START: 0> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:35:39 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.HDR_SENT: 2>
1/8/2024 10:35:39 PM Connection state changed: <ConnectionState.HDR_SENT: 2> -> <ConnectionState.OPEN_PIPE: 4>
1/8/2024 10:35:39 PM Session state changed: <SessionState.UNMAPPED: 0> -> <SessionState.BEGIN_SENT: 1>
1/8/2024 10:35:39 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:35:39 PM Management link receiver state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:35:39 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:35:39 PM Management link sender state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:35:39 PM Connection state changed: <ConnectionState.OPEN_PIPE: 4> -> <ConnectionState.OPEN_SENT: 7>
1/8/2024 10:35:39 PM Connection state changed: <ConnectionState.OPEN_SENT: 7> -> <ConnectionState.OPENED: 9>
1/8/2024 10:35:39 PM Session state changed: <SessionState.BEGIN_SENT: 1> -> <SessionState.MAPPED: 3>
1/8/2024 10:35:40 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:40 PM Management link receiver state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:40 PM Management link sender state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:40 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:40 PM Link state changed: <LinkState.DETACHED: 0> -> <LinkState.ATTACH_SENT: 1>
1/8/2024 10:35:40 PM Link state changed: <LinkState.ATTACH_SENT: 1> -> <LinkState.ATTACHED: 3>
1/8/2024 10:35:40 PM Message sent successfully
1/8/2024 10:35:40 PM Executed 'Functions.enqueueData3' (Succeeded, Id=47c66bb1-2691-4265-a7d8-21fc686f3e6d, Duration=125593ms)

gujiams avatar Jan 15 '24 12:01 gujiams

Discussion moved over to IcM, issue was moved over to service team and cx response.

kashifkhan avatar May 29 '24 21:05 kashifkhan