[Freeswitch-users] Mod_callcenter Double-Dialing Intermittently

R H buscom123+fs at gmail.com
Sat Nov 5 01:41:45 MSK 2011 

Hey Everyone,

I may have a bug for Mod_Callcenter but I wanted to see if anyone else
might notice a setup issue before I send this on to Jira. I recently
launched a production callcenter system for our company. We are currently
beta testing the system with a small subset of our callers and we have
noticed an issue where every so often (IE.* Intermittent issue*) when a
caller arrives in queue and the queue offers the call to the agent,* the
offer happens twice. *

What gets worse is that once the agent answers one of the calls the other
call continues to attempt to reach the agent even while they are talking to
the person they are receiving the second call for. When the call times out
we get a "NO ANSWER" and then the callcenter system attempts the call
again, and again, and again until the agent is done with the caller.

Even more interesting is that the agent state and member state keep
changing to reflect the state of the second calling thread that keeps
trying even though the caller is actually speaking to the agent.

Here is a log from the freeswitch events. This was taken using log level 5
in the cli. Lines in BLUE are cli statements I am recording when events are
fired that I care about. I am using Mod_managed to listen to events and
update information in a company database. Lines in RED are notes about the
logs.

2011-11-04 15:44:06.340969 [ALERT] switch_cpp.cpp:1223
PsiQueueEventConsumer - CallLogId Not Detected, Attempting to Create New ::
Unavailable(2406740599) calling cc+
--- A CALLER JUST JOINED THE QUEUE ---
2011-11-04 15:44:45.160968 [NOTICE] switch_channel.c:915 New Channel
sofia/external/sip:4503 at 97.75.182.83:59868[35e23ce8-072e-11e1-a636-2d222f47338b]
2011-11-04 15:44:45.160968 [NOTICE] switch_channel.c:915 New Channel
sofia/external/sip:4503 at 97.75.182.83:59868[35e24e68-072e-11e1-a63a-2d222f47338b]
--- NOTICE HOW 2 CHANNELS WERE INITIATED TO THE SAME EXTENSION/AGENT ---
--- AGENT STATE: 'Receiving' ---
2011-11-04 15:44:45.200941 [NOTICE] sofia.c:5375 Ring-Ready sofia/external/
sip:4503 at 97.75.182.83:59868!
2011-11-04 15:44:45.481059 [NOTICE] sofia.c:5375 Ring-Ready sofia/external/
sip:4503 at 97.75.182.83:59868!
2011-11-04 15:44:48.740993 [NOTICE] sofia.c:5983 Channel [sofia/external/
sip:4503 at 97.75.182.83:59868] has been answered
--- THE AGENT ANSWERED ONLY ONE OF THE CALLS ---
--- AGENT STATE: 'In A Queue Call' ---
2011-11-04 15:44:55.000947 [NOTICE] switch_ivr_originate.c:3167 Hangup
sofia/external/sip:4503 at 97.75.182.83:59868 [CS_CONSUME_MEDIA] [NO_ANSWER]
2011-11-04 15:44:55.000947 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [user] cause: [NO_ANSWER]
2011-11-04 15:44:55.000947 [NOTICE] switch_core_session.c:1395 Session 605
(sofia/external/sip:4503 at 97.75.182.83:59868) Ended
2011-11-04 15:44:55.000947 [NOTICE] switch_core_session.c:1397 Close
Channel sofia/external/sip:4503 at 97.75.182.83:59868 [CS_DESTROY]
--- THE SECOND CHANNEL JUST TIMED OUT AND FLAGGED THE CALL AS A "NO ANSWER"
---
2011-11-04 15:44:55.000947 [NOTICE] switch_channel.c:915 New Channel
sofia/external/sip:4503 at 97.75.182.83:59868[3bc0c008-072e-11e1-a642-2d222f47338b]
--- AGENT STATE: 'Receiving' ---
2011-11-04 15:44:55.040931 [NOTICE] sofia.c:5375 Ring-Ready sofia/external/
sip:4503 at 97.75.182.83:59868!
--- SECOND CHANNEL ATTEMPTS AGAIN TO REACH THE AGENT, THE AGENT IS ALREADY
TALKING TO THE CALLER ---
2011-11-04 15:45:05.000941 [NOTICE] switch_ivr_originate.c:3167 Hangup
sofia/external/sip:4503 at 97.75.182.83:59868 [CS_CONSUME_MEDIA] [NO_ANSWER]
2011-11-04 15:45:05.000941 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [user] cause: [NO_ANSWER]
2011-11-04 15:45:05.000941 [NOTICE] switch_core_session.c:1395 Session 606
(sofia/external/sip:4503 at 97.75.182.83:59868) Ended
2011-11-04 15:45:05.000941 [NOTICE] switch_core_session.c:1397 Close
Channel sofia/external/sip:4503 at 97.75.182.83:59868 [CS_DESTROY]
--- NO ANSWER TIMEOUT REPEATS ---
2011-11-04 15:45:05.060918 [NOTICE] switch_channel.c:915 New Channel
sofia/external/sip:4503 at 97.75.182.83:59868[41be0a9c-072e-11e1-a647-2d222f47338b]
--- AGENT STATE: 'Receiving' ---
--- TRIES AGAIN ---
2011-11-04 15:45:05.081035 [NOTICE] sofia.c:5375 Ring-Ready sofia/external/
sip:4503 at 97.75.182.83:59868!
2011-11-04 15:45:15.001026 [NOTICE] switch_ivr_originate.c:3167 Hangup
sofia/external/sip:4503 at 97.75.182.83:59868 [CS_CONSUME_MEDIA] [NO_ANSWER]
2011-11-04 15:45:15.001026 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [user] cause: [NO_ANSWER]
2011-11-04 15:45:15.001026 [NOTICE] switch_core_session.c:1395 Session 607
(sofia/external/sip:4503 at 97.75.182.83:59868) Ended
2011-11-04 15:45:15.001026 [NOTICE] switch_core_session.c:1397 Close
Channel sofia/external/sip:4503 at 97.75.182.83:59868 [CS_DESTROY]

--- LOOPS CONTINUALLY FOR 7 MINUTES ---
....

--- TRIES AGAIN ---
2011-11-04 15:52:15.040968 [NOTICE] switch_channel.c:915 New Channel
sofia/external/sip:4503 at 97.75.182.83:59868[4208943a-072f-11e1-a72a-2d222f47338b]
--- AGENT STATE: 'Receiving' ---
2011-11-04 15:52:15.080896 [NOTICE] sofia.c:5375 Ring-Ready sofia/external/
sip:4503 at 97.75.182.83:59868!
2011-11-04 15:52:25.000919 [NOTICE] switch_ivr_originate.c:3167 Hangup
sofia/external/sip:4503 at 97.75.182.83:59868 [CS_CONSUME_MEDIA] [NO_ANSWER]
2011-11-04 15:52:25.000919 [NOTICE] switch_ivr_originate.c:2459 Cannot
create outgoing channel of type [user] cause: [NO_ANSWER]
2011-11-04 15:52:25.000919 [NOTICE] switch_core_session.c:1395 Session 653
(sofia/external/sip:4503 at 97.75.182.83:59868) Ended
2011-11-04 15:52:25.000919 [NOTICE] switch_core_session.c:1397 Close
Channel sofia/external/sip:4503 at 97.75.182.83:59868 [CS_DESTROY]
2011-11-04 15:52:28.140959 [NOTICE] switch_ivr_bridge.c:658 Hangup
sofia/external/sip:4503 at 97.75.182.83:59868 [CS_EXCHANGE_MEDIA]
[NORMAL_CLEARING]
--- AGENT ACTUALLY HANGS UP ON THE REAL CALL ---
--- AGENT STATE: 'Waiting' ---
2011-11-04 15:52:28.180984 [NOTICE] switch_core_session.c:1395 Session 604
(sofia/external/sip:4503 at 97.75.182.83:59868) Ended
2011-11-04 15:52:28.180984 [NOTICE] switch_core_session.c:1397 Close
Channel sofia/external/sip:4503 at 97.75.182.83:59868 [CS_DESTROY]
--- THE LOOP IS ENDED BECAUSE THE MEMBER IS NO LONGER IN THE SYSTEM ---


While the agent state keeps changing the agent is actually in a call with
the caller this entire time. Events are firing every 10 seconds informing
me this agent had a "No Answer" on an inbound call when they are actually
talking to the caller.

Here are some settings in case you want to know:

*freeswitch at internal> callcenter_config queue list*
name|strategy|moh_sound|time_base_score|tier_rules_apply|tier_rule_wait_second|tier_rule_wait_multiply_level|tier_rule_no_agent_no_wait|discard_abandoned_after|abandoned_resume_allowed|max_wait_time|max_wait_time_with_no_agent|max_wait_time_with_no_agent_time_reached|record_template
*callcenter at sip.**<hidden>**
.com|longest-idle-agent|local_stream://moh|system|false|300|true|false|60|false|0|0|5|/usr/local/freeswitch/recordings/${strftime(%Y-%m-%d-%H-%M-%S)}.${destination_number}.${caller_id_number}.${uuid}.wav
*
+OK

*freeswitch at internal> callcenter_config agent list*
name|system|uuid|type|contact|status|state|max_no_answer|wrap_up_time|reject_delay_time|busy_delay_time|no_answer_delay_time|last_bridge_start|last_bridge_end|last_offered_call|last_status_change|no_answer_count|calls_answered|talk_time|ready_time
7003 at sip.
<hidden>.com|single_box|6d3dabc4-0732-11e1-a7c6-2d222f47338b|callback|[call_timeout=10]user/4513 at sip.<hidden>.com|Available|In
a queue
call|0|30|0|0|0|1320444899|1320444795|1320444896|1320443529|0|4|1129|0
*7004 at sip.<hidden>.com|single_box||callback|[call_timeout=10]user/4503 at sip.
<hidden>.com|Available|Waiting|0|30|0|0|0|1320445006|1320445099|1320445000|1320434600|0|24|4254|0
*
+OK

And here are the queue settings in XML. Same as above but easier to read.

<queues>
    <queue name="callcenter at sip.<hidden>.com">
      <param name="strategy" value="longest-idle-agent"/>
      <param name="moh-sound" value="$${hold_music}"/>
      <param name="record-template"
value="$${base_dir}/recordings/${strftime(%Y-%m-%d-%H-%M-%S)}.${destination_number}.${caller_id_number}.${uuid}.wav"/>
      <param name="time-base-score" value="system"/>
      <param name="max-wait-time" value="0"/>
      <param name="max-wait-time-with-no-agent" value="0"/>
      <param name="max-wait-time-with-no-agent-time-reached" value="5"/>
      <param name="tier-rules-apply" value="false"/>
      <param name="tier-rule-wait-second" value="300"/>
      <param name="tier-rule-wait-multiply-level" value="true"/>
      <param name="tier-rule-no-agent-no-wait" value="false"/>
      <param name="discard-abandoned-after" value="60"/>
      <param name="abandoned-resume-allowed" value="false"/>
    </queue>
  </queues>


So to summarize, most calls work exactly as expected, but a percentage of
our total call volume is currently having this issue. We are taking around
200 calls per day at the moment but we plan to take many more in the coming
month. We have another system with an IVR in front of this and it only
hands callers of a particular ivr option to this server.

I should also note that we are running Dual Quad Core Intel Xeon's, 8GB
DDR2, Suse 11.4 - x86_64, Mono 1.8.2. We are also testing 3 Polycom 450's
and 5 X-Lite SoftPhones with our agents.

Any suggestions or help would be appreciated.

Thanks!

Ryan H
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20111104/87786e11/attachment-0001.html

Join us at ClueCon 2011 Aug 9-11, 2011
More information about the FreeSWITCH-users mailing list