add esl event latency

src/core/callcenter/agent.py

@@ -7,7 +7,7 @@ import traceback
 from collections import defaultdict
 from concurrent.futures import ThreadPoolExecutor
 from typing import List
-
+from datetime import datetime
 from apscheduler.schedulers.background import BackgroundScheduler
 from sqlalchemy import or_
 
@@ -80,6 +80,8 @@ class AgentEventService:
 
     def agent_event_channel(self, event, call_info: CallInfo, device_info: DeviceInfo):
         event_name = EslEventUtil.getEventName(event)
+        event_timestamp = EslEventUtil.getEventTimestamp(event)
+        event_time = datetime.fromtimestamp(event_timestamp).strftime('%Y-%m-%d %H:%M:%S')
         saas_id = call_info.saas_id if call_info else None
         flow_id = call_info.cti_flow_id if call_info else None
         call_id = call_info.call_id if call_info else None
@@ -91,7 +93,7 @@ class AgentEventService:
 
         start_time = time.time()
         try:
-            self.logger.info('agent_event_channel, event_name=%s, call_id=%s, agent_num=%s, device_id=%s, is_agent=%s, hangup_dir=%s, hangup_count=%s, answer_count=%s', event_name, call_id, agent_num, device_id, is_agent, call_info.hangup_dir, call_info.hangup_count, call_info.answer_count)
+            self.logger.info('agent_event_channel, event_name=%s, call_id=%s, event_time=%s, agent_num=%s, device_id=%s, is_agent=%s, hangup_dir=%s, hangup_count=%s, answer_count=%s', event_name, call_id, event_time, agent_num, device_id, is_agent, call_info.hangup_dir, call_info.hangup_count, call_info.answer_count)
             agent = self.data_handle_server.get_agent(saas_id, agent_num)
             if not agent:
                 # self.logger.warn("event service channel agent is null %s %s %s %s %s", saas_id, event_name, caller, called, json.loads(event.serialize('json')))
@@ -175,11 +177,15 @@ class AgentEventService:
         except:
             traceback.print_exc()
         finally:
-            latency = (time.time() - start_time)
+            time_cost = time.time() - start_time
+            registry.ESL_EVENT_CALLBACK_COST.labels(event_name, "agent").observe(time_cost)
+            latency = time.time() - event_timestamp
             registry.ESL_EVENT_CALLBACK_LATENCY.labels(event_name, "agent").observe(latency)
 
     def bot_event_channel(self, event, call_info, device_info):
         event_name = EslEventUtil.getEventName(event)
+        event_timestamp = EslEventUtil.getEventTimestamp(event)
+        event_time = datetime.fromtimestamp(event_timestamp).strftime('%Y-%m-%d %H:%M:%S')
         saas_id = call_info.saas_id if call_info else None
         flow_id = call_info.cti_flow_id if call_info else None
         call_id = call_info.call_id if call_info else None
@@ -192,7 +198,7 @@ class AgentEventService:
 
         start_time = time.time()
         try:
-            self.logger.info('bot_event_channel, event_name=%s, call_id=%s, device_id=%s, is_agent=%s, agent_num=%s, hangup_dir=%s, hangup_count=%s, answer_count=%s', event_name, call_id, device_id, is_agent, agent_num, call_info.hangup_dir, call_info.hangup_count, call_info.answer_count)
+            self.logger.info('bot_event_channel, event_name=%s, call_id=%s, device_id=%s, event_time=%s, is_agent=%s, agent_num=%s, hangup_dir=%s, hangup_count=%s, answer_count=%s', event_name, call_id, device_id, event_time, is_agent, agent_num, call_info.hangup_dir, call_info.hangup_count, call_info.answer_count)
             agent = self.data_handle_server.get_agent(saas_id, agent_num)
             if not agent:
                 self.logger.warn("bot event service channel agent is null %s %s %s %s %s", saas_id, event_name, call_id, caller, called)
@@ -240,8 +246,10 @@ class AgentEventService:
         except:
             traceback.print_exc()
         finally:
-            latency = (time.time() - start_time)
-            registry.ESL_EVENT_CALLBACK_LATENCY.labels(event_name, "agent").observe(latency)
+            time_cost = time.time() - start_time
+            registry.ESL_EVENT_CALLBACK_COST.labels(event_name, "bot").observe(time_cost)
+            latency = time.time() - event_timestamp
+            registry.ESL_EVENT_CALLBACK_LATENCY.labels(event_name, "bot").observe(latency)
 
     def reprocessing_idle(self, state_data: AgentDelayStateData):
         agent = self.data_handle_server.get_agent(state_data.saas_id, state_data.agent_num)
@@ -1055,10 +1063,11 @@ class AgentStateService:
         return "CTI:%s:HUMAN:%s:%s:LOCK"%(saas_id.upper(), service_id, choose_phone_num)
 
     def _get_expire_time(self):
-        now = datetime.now()
-        end_of_day = now.replace(hour=23, minute=59, second=59, microsecond=0)
-        expire_time = (end_of_day - now).total_seconds()  # Convert to milliseconds
-        return int(expire_time)
+        # now = datetime.now()
+        # end_of_day = now.replace(hour=23, minute=59, second=59, microsecond=0)
+        # expire_time = (end_of_day - now).total_seconds()  # Convert to milliseconds
+        # return int(expire_time)
+        return 60*60*24*30
 
     def _choose_max_idle_time(self, idle_agents: List[AgentStateData]) -> str:
         idle_agents = sorted(idle_agents, key=lambda agent: agent.assign_time, reverse=False)

src/core/callcenter/esl/client.py

@@ -107,6 +107,8 @@ class InboundClient:
 
     def choose_thread_pool_executor(self, e):
         event_name = EslEventUtil.getEventName(e)
+        event_timestamp = EslEventUtil.getEventTimestamp(e)
+        event_time = datetime.fromtimestamp(event_timestamp).strftime('%Y-%m-%d %H:%M:%S')
         call_id = EslEventUtil.getCallId(e)
         device_id = EslEventUtil.getUniqueId(e)
         wdh_device_id = EslEventUtil.getDeviceId(e)
@@ -115,7 +117,7 @@ class InboundClient:
             random_index = abs(mmh3.hash(random_id)) % len(self.executors)
         else:
             random_index = random.randint(0, len(self.executors) - 1) if self.executors else 0
-        self.logger.info('choose_thread_pool_executor:event_name=%s, random_index=%s, call_id=%s, unique_id=%s, device_id=%s, ', event_name, random_index, call_id, device_id, wdh_device_id)
+        self.logger.info('choose_thread_pool_executor:event_name=%s, random_index=%s, call_id=%s, unique_id=%s, device_id=%s, event_time=%s', event_name, random_index, call_id, device_id, wdh_device_id, event_time)
         return self.executors.get(random_index)
 
     def process_esl_event(self, e):
@@ -124,6 +126,7 @@ class InboundClient:
         event_name = EslEventUtil.getEventName(e)
         coreUUID = EslEventUtil.getCoreUuid(e)
         address = self.host + ':' + self.port
+        event_timestamp = EslEventUtil.getEventTimestamp(e)
         # self.logger.info("process_esl_event.event_name=%s,coreUUID=%s", event_name, coreUUID)
         try:
             self.callback.callback_event(e)
@@ -140,7 +143,9 @@ class InboundClient:
         except:
             traceback.print_exc()
         finally:
-            latency = (time.time() - start_time)
+            time_cost = time.time() - start_time
+            registry.ESL_EVENT_COST.labels(event_name).observe(time_cost)
+            latency = time.time() - event_timestamp
             registry.ESL_EVENT_LATENCY.labels(event_name).observe(latency)
 
     def do_delay_action(self, action, message):

src/core/callcenter/esl/utils/esl_event_util.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python3
 # encoding:utf-8
 
+import time
 import random
 import re
 import string
@@ -231,6 +232,10 @@ def getFreeswitchSwitchname(e):
 def getEventDateTimestamp(e):
     return e.getHeader(EVENT_DATE_TIMESTAMP)
 
+def getEventTimestamp(e):
+    event_timestamp = getEventDateTimestamp(e)
+    event_timestamp_sec = event_timestamp / 1_000_000 if event_timestamp else time.time()
+    return event_timestamp_sec
 
 def getEventSubClass(e):
     return e.getHeader(EVENT_SUB_CLASS)

src/core/callcenter/registry.py

@@ -28,7 +28,9 @@ ASR_ERRORS = Counter( 'asr_error_codes', 'Count of ASR error codes', ['errorCode
 
 
 # esl时间耗时
+ESL_EVENT_COST = Histogram('esl_event_cost', 'Esl Event process cost in seconds', ['eventName'])
 ESL_EVENT_LATENCY = Histogram('esl_event_latency', 'Esl Event latency in seconds', ['eventName'])
+ESL_EVENT_CALLBACK_COST = Histogram('esl_event_callback_cost', 'Esl Event callback process cost in seconds', ['eventName','callType'])
 ESL_EVENT_CALLBACK_LATENCY = Histogram('esl_event_callback_latency', 'Esl Event callback latency in seconds', ['eventName','callType'])