[azure-eventhub] Failure: sending socket failed. errno=104 (Connection reset by peer). [too many error logs]

[kalyanb9119]

• azure-eventhub==5.7.0, azure-identity=1.9.0:
• Linux:
• 3.9:

Describe the bug We are getting tons of errors like below frequently. Don't see any issues with Eventhub publish functionality - but lots of logs like below are quite noisy and distracting. can you please help check what's happening ?

engineapi | INFO [2022-07-27 07:00:50,104] connection.py:260 b'Failure: sending socket failed. errno=104 (Connection reset by peer).' (b'/data/src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/adapters/socketio_berkeley.c':b'socketio_send':944) engineapi | INFO [2022-07-27 07:00:50,104] connection.py:260 b'Error in xio_send.' (b'/data/src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/adapters/tlsio_openssl.c':b'write_outgoing_bytes':702) engineapi | INFO [2022-07-27 07:00:50,104] connection.py:260 b'Error in write_outgoing_bytes.' (b'/data/src/vendor/azure-uamqp-c/deps/azure-c-shared-utility/adapters/tlsio_openssl.c':b'tlsio_openssl_send':1553) engineapi | INFO [2022-07-27 07:00:50,105] connection.py:260 b'Cannot send encoded bytes' (b'/data/src/vendor/azure-uamqp-c/src/connection.c':b'on_bytes_encoded':268) engineapi | INFO [2022-07-27 07:00:50,105] connection.py:260 b'xio_send failed' (b'/data/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_send_async':1190) engineapi | INFO [2022-07-27 07:00:50,106] connection.py:177 Connection b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181' state changed from <ConnectionState.OPENED: 9> to <ConnectionState.END: 13> engineapi | INFO [2022-07-27 07:00:50,106] connection.py:181 Connection with ID b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181' unexpectedly in an error state. Closing: False, Error: None engineapi | INFO [2022-07-27 07:00:50,106] connection.py:260 CBS error occurred on connection b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'. engineapi | INFO [2022-07-27 07:00:50,106] sender.py:268 Message sender b'sender-link-dbafd928-afe1-4904-9daa-052f85b379d5' state changed from <MessageSenderState.Open: 3> to <MessageSenderState.Idle: 1> on connection: b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181' engineapi | WARNING [2022-07-27 07:00:50,106] connection.py:256 ConnectionClose('ErrorCodes.UnknownError: Connection in an unexpected error state.') engineapi | INFO [2022-07-27 07:00:50,106] connection.py:129 Shutting down connection b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'. engineapi | INFO [2022-07-27 07:00:50,106] cbs_auth.py:86 Shutting down CBS session on connection: b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'. engineapi | INFO [2022-07-27 07:00:50,106] cbs_auth.py:90 Auth closed, destroying session on connection: b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'. engineapi | INFO [2022-07-27 07:00:50,106] cbs_auth.py:93 Finished shutting down CBS session on connection: b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'. engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'send called while not open' (b'/data/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_send_async':1181) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'saslclientio_close called while not open' (b'/data/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_close_async':1130) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'Cannot send encoded bytes' (b'/data/src/vendor/azure-uamqp-c/src/connection.c':b'on_bytes_encoded':268) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'xio_close failed' (b'/data/src/vendor/azure-uamqp-c/src/connection.c':b'on_bytes_encoded':272) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:177 Connection b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181' state changed from <ConnectionState.END: 13> to <ConnectionState.END: 13> engineapi | INFO [2022-07-27 07:00:50,107] connection.py:177 Connection b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181' state changed from <ConnectionState.END: 13> to <ConnectionState.END: 13> engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'saslclientio_close called while not open' (b'/data/src/vendor/azure-uamqp-c/src/saslclientio.c':b'saslclientio_close_async':1130) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:134 b'xio_close failed' (b'/data/src/vendor/azure-uamqp-c/src/connection.c':b'connection_close':1437) engineapi | INFO [2022-07-27 07:00:50,107] connection.py:136 Connection shutdown complete b'EHProducer-c32fd323-38d3-4343-88be-4a2f69359181'.

Code I am using to send the events to eventhub:

class EventhubDataProducer(UsageDataSinkInterface):
    """ The EventhubDataProducer class implements the functionality of sending usage data to eventhub.
    """

    def __init__(
        self,
        config: AzureUsageConfig,
        max_size_in_bytes=AzureUsageLoggerConstants.USAGE_DATA_MAX_BATCH_SIZE_IN_BYTES
    ):
        self.max_size_in_bytes = max_size_in_bytes
        self.credential = ManagedIdentityCredential(
            client_id=config.USAGE_DATA_PRODUCER_IDENTITY)
        self.producer = EventHubProducerClient(
            fully_qualified_namespace=config.USAGE_EVENTHUB_NAMESPACE,
            eventhub_name=config.USAGE_EVENTHUB_NAME,
            credential=self.credential,
            # retry related parameters
            retry_total=3,
            retry_backoff_factor=0.2,
            retry_mode="exponential")
        self.defalt_tags = get_metric_default_tags()
        logger.info("Using eventhub as the sink for openai usage events")

    def send_usage_data_batch(self, event_data_batch: EventDataBatch, batched_events: list):
        try:
            self.producer.send_batch(event_data_batch)
        except:
            log_error(etype=ErrorType.EVENTHUB_DATA_SEND_ERROR,
                      tb=traceback.format_exc())

[swathipil]

Hi @kalyanb9119 - Based on this error message, it looks like there were connection issues, so the connection was shutdown. However, we have built in retries to reconnect when there is a shutdown like this, and, as you pointed out, we recover and send as expected. You can find instructions [here] on suppressing overly verbose logging by changing the uamqp package logging level to WARNING/ERROR.

[ghost]

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

[kalyanb9119]

/unresolve @swathipil - I have dependency on azure-eventhub sdk, why should I explicitely change the logging of uamqp package -- Isn't it expected that only WARNING/ERROR logs from downstream packages are enabled by default and not all INFO logs?

[swathipil]

OOB discussion:

• @kalyanb9119 provided code for their logger instantiation:

  
  class RequestIDAdapter(logging.LoggerAdapter):
  def __init__(self, logger):
      super().__init__(logger, {})
  
  def process(self, msg, kwargs):
      if flask.has_request_context():
          try:
              request_id = g.request_id
          except AttributeError:
              return msg, kwargs
      else:
          request_id = current_request_id
          if request_id is None:
              return msg, kwargs
      msg = msg.replace("\n", f"\n[{request_id}] ")
      return f"[{request_id}] {msg}", kwargs

def getLogger(name): logger = logging.getLogger(name) return RequestIDAdapter(logger)

logger = getLogger(name)

[swathipil]

Hi @kalyanb9119 - We're still looking into why this is happening. In the meantime, would you be able to check if the provided workaround resolves your issue?

[niteshmacha]

Hi @swathipil - The workaround resolved our issue. Thanks

[ghost]

Hi, we're sending this friendly reminder because we haven't heard back from you in a while. We need more information about this issue to help address it. Please be sure to give us your input within the next 7 days. If we don't hear back from you within 14 days of this comment the issue will be automatically closed. Thank you!