improve logging on rtm timeout/disconnect issues

Author: kacperf531

livechat/utils/ws_client.py

@@ -5,6 +5,7 @@
 import json
 import random
 import ssl
+import subprocess
 import threading
 from time import sleep
 from typing import List, NoReturn, Union
@@ -13,13 +14,21 @@
 from websocket import WebSocketApp, WebSocketConnectionClosedException
 from websocket._abnf import ABNF
 
+
 from livechat.utils.structures import RtmResponse
 
 
 def on_message(ws_client: WebSocketApp, message: str):
     ''' Custom WebSocketApp handler that inserts new messages in front of `self.messages` list. '''
     ws_client.messages.insert(0, json.loads(message))
 
+def on_close(ws_client: WebSocketApp, close_status_code: int, close_msg: str):
+    logger.info('websocket closed:')
+
+    if close_status_code or close_msg:
+        logger.info("close status code: " + str(close_status_code))
+        logger.info("close message: " + str(close_msg))
+
 
 class WebsocketClient(WebSocketApp):
     ''' Custom extension of the WebSocketApp class for livechat python SDK. '''
@@ -77,22 +86,30 @@ def send(self, request: dict, opcode=ABNF.OPCODE_TEXT) -> dict:
                 RtmResponse: RTM response structure (`request_id`, `action`,
                              `type`, `success` and `payload` properties)
         '''
-        response_timeout = self.response_timeout
         request_id = str(random.randint(1, 9999999999))
         request.update({'request_id': request_id})
         request_json = json.dumps(request, indent=4)
         logger.info(f'\nREQUEST:\n{request_json}')
+
         if not self.sock or self.sock.send(request_json, opcode) == 0:
             raise WebSocketConnectionClosedException(
                 'Connection is already closed.')
-        while not (response := next(
-            (item
-             for item in self.messages if item.get('request_id') == request_id
-             and item.get('type') == 'response'),
-                None)) and response_timeout > 0:
+        
+        response: dict
+        def await_message():
+            for item in self.messages:
+                if item.get('request_id') == request_id and item.get('type') == 'response':
+                    response = item
+                    return
             sleep(0.2)
-            response_timeout -= 0.2
-        logger.info(f'\nRESPONSE:\n{json.dumps(response, indent=4)}')
+        try:
+            subprocess.run(['await_message', self.response_timeout], timeout = 2)
+            logger.info(f'\nRESPONSE:\n{json.dumps(response, indent=4)}')
+        except subprocess.TimeoutExpired:
+            logger.error(f'timed out waiting for message with request_id {request_id}')
+            logger.debug('all websocket messages received before timeout:')
+            logger.debug(self.messages)
+        
         return RtmResponse(response)
 
     def _wait_till_sock_connected(self,