[OpenSIPS-Users] Doubt about call center module

Wed Aug 29 15:26:49 EDT 2018

Got some more info.

*This is the first call that worked fine:*
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: Recebida asterisk - Tentando
entrar na fila fila-1
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
using call flow 0x7fd851022270
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
cid=<"fila-1 551122223333">
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:new_cc_call:
created call 0x7fd85104c8b0
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:call_center:print_call_list: [] - 0x7fd85104c8b0
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
avg_call_duration=0.00 queued_calls=0 logedin_agents=1
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
ETA for new call(0x7fd85104c8b0) is 0
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:call_center:cc_call_state_machine: selecting AGENT 0x7fd851022a38 (
1000 at plat5.localdomain.com)
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:call_center:cc_call_state_machine: moved to TOAGENT from 0,
out=0x7fd851022a50
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
new destination for call(0x7fd85104c8b0) is
sip:1000 at plat5.localdomain.com:5060 (state=3)
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:call_center:set_call_leg:
call 0x7fd85104c8b0 moving to sip:1000 at plat5.localdomain.com:5060 , state 3
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:get_scenario_id_list: scenario id = call center
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_logic:udh_to_uri:
user:host:port [fila-1][10.10.10.10][5060]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
hash index [205]:
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
id [0]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
new tuple [0x7fd85104c980]->[205.0]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:t_newtran: transaction
on entrance=(nil)
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=78
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:t_lookup_request: start
searching: hash=21517, isACK=0
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:t_lookup_request: no
transaction found
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:run_reqin_callbacks:
trans=0x7fd85104cec0, callback type 1, id 0 entered
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:_shm_resize:
resize(0) called
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:_reply_light: reply
sent out. buf=0x7fd858dd32c8: SIP/2.0 1..., shmem=0x7fd8510501a0: SIP/2.0 1
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:_reply_light: finished
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:t_ref_cell:
REF_UNSAFE:[0x7fd85104cec0] after is 2
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_entities:server_new:
new server entity[0x7fd85104cc58]: callid=[
7f0e81024a47462530aeb80b4345ddbc at 10.10.10.10:5070] tag=[as5263b362]
param=[205.0] dlg->uas_tran=[0x7fd85104cec0]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2bl_create_new_entity: new entity type [0]
[0x7fd851050400]->[B2B.94.465.1535569466]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI of type param
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI value taken from a parameter [
sip:1000 at plat5.localdomain.com:5060]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI value = [
sip:1000 at plat5.localdomain.com:5060]
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:MD5StringArray: MD5
calculated: e597e6de7f998db0ad2ccad6fec41d4e
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:b2b_entities:generate_tag:
from_tag = e597e6de7f998db0ad2ccad6fec41d4e-7fe2
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:tm:t_uac: next_hop=<
sip:1000 at plat5.localdomain.com:5060>
Aug 29 16:04:27 plat5 /sbin/opensips[24890]: DBG:core:mk_proxy: doing DNS
lookup...

Now, the only agent is in a call.

*This is the second call that had the problem:*
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: Recebida asterisk - Tentando
entrar na fila fila-1
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
using call flow 0x7fd851022270
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
cid=<"fila-1 551122223333">
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:new_cc_call:
created call 0x7fd8510524a8
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:print_call_list: [] - 0x7fd8510524a8
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:print_call_list: [205.0] - 0x7fd85104c8b0
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
avg_call_duration=0.00 queued_calls=0 logedin_agents=1
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
ETA for new call(0x7fd8510524a8) is 0
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:cc_call_state_machine: selecting QUEUE
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:cc_queue_push_call:  QUEUE - adding call 0x7fd8510524a8
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:cc_queue_push_call: adding call on pos 0 (already 1 calls),
l=(nil) h=(nil)
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
new destination for call(0x7fd8510524a8) is  (state=2)
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
** onhold++ Not to agent [0x7fd8510524a8]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:set_call_leg:
call 0x7fd8510524a8 moving to  , state 2
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:get_scenario_id_list: scenario id = call center
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:udh_to_uri:
user:host:port [fila-1][10.10.10.10][5060]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
Fewer parameters, expected [1] received [0]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
hash index [205]:
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
id [0]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
id [1]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_insert_new:
new tuple [0x7fd851056680]->[205.1]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:t_newtran: transaction
on entrance=(nil)
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=78
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:t_lookup_request: start
searching: hash=41757, isACK=0
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:t_lookup_request: no
transaction found
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:run_reqin_callbacks:
trans=0x7fd851046cb0, callback type 1, id 0 entered
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:parse_headers:
flags=ffffffffffffffff
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:core:_shm_resize:
resize(0) called
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:_reply_light: reply
sent out. buf=0x7fd858dd2160: SIP/2.0 1..., shmem=0x7fd851052878: SIP/2.0 1
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:_reply_light: finished
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:t_ref_cell:
REF_UNSAFE:[0x7fd851046cb0] after is 2
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_entities:server_new:
new server entity[0x7fd851056830]: callid=[
060e63f73ff9d6c935047ce31296d0d9 at 10.10.10.10:5070] tag=[as19cfceed]
param=[205.1] dlg->uas_tran=[0x7fd851046cb0]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2bl_create_new_entity: new entity type [0]
[0x7fd851052aa8]->[B2B.71.64.1535569477]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI of type param
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI value taken from a parameter []
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_logic:b2b_scenario_parse_uri: URI value = []
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
ERROR:b2b_logic:b2b_process_scenario_init: Failed to get the value for the
b2b client ruri
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:b2b_logic:b2bl_delete:
Delete record [0x7fd851056680]->[205.1], hash_index=[205], local_index=[1]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_parse_key: hash_index = [71]  - local_index= [64]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_search_htable_next_dlg: entering with start=(nil),
table=0x7fd850ff26d0, hash=71, label=64
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_search_htable_next_dlg: searching  callid 53[
060e63f73ff9d6c935047ce31296d0d9 at 10.10.10.10:5070]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_search_htable_next_dlg: searching   totag
20[B2B.71.64.1535569477]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag
10[as19cfceed]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg
[0x7fd851056830] dlg->uas_tran=[0x7fd851046cb0]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:b2b_entities:b2b_entity_delete: Deleted dlg
[0x7fd851056830]->[B2B.71.64.1535569477] with dlginfo [0x7fd851055f80]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:tm:t_unref_cell:
UNREF_UNSAFE: [0x7fd851046cb0] after is 1
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
ERROR:call_center:set_call_leg: failed to init new b2bua call (empty ID
received)
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
ERROR:call_center:w_handle_call: failed to set new destination for call
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:w_handle_call:
** onhold-- Error [0x7fd8510524a8]
Aug 29 16:04:38 plat5 /sbin/opensips[24890]:
DBG:call_center:print_call_list: [205.0] - 0x7fd85104c8b0
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: DBG:call_center:free_cc_call:
free call 0x7fd8510524a8, []
Aug 29 16:04:38 plat5 /sbin/opensips[24890]: Falha entrando na fila -
erronum: -1

On Mon, Aug 27, 2018 at 6:15 PM Daniel Zanutti <daniel.zanutti at gmail.com>
wrote:

> Trying to configure the call center modules, but found a problem when
> there is no agents available.
>
> If there is 1 agent available, call is sent to him with no problem:
>
> Aug 27 18:11:00 plat5 /sbin/opensips[23575]: Recebida asterisk - Tentando
> entrar na fila fila-1
> Aug 27 18:11:00 plat5 /sbin/opensips[23575]: Entrou na fila com sucesso
> (fila-1)!
> Aug 27 18:11:01 plat5 /sbin/opensips[23569]: incoming reply
>
> But when there is no agent available, opensips refuses:
> Aug 27 18:11:07 plat5 /sbin/opensips[23569]: Recebida asterisk - Tentando
> entrar na fila fila-1
> Aug 27 18:11:07 plat5 /sbin/opensips[23569]:
> ERROR:b2b_logic:b2b_process_scenario_init: Failed to get the value for the
> b2b client ruri
> Aug 27 18:11:07 plat5 /sbin/opensips[23569]:
> ERROR:call_center:set_call_leg: failed to init new b2bua call (empty ID
> received)
> Aug 27 18:11:07 plat5 /sbin/opensips[23569]:
> ERROR:call_center:w_handle_call: failed to set new destination for call
> Aug 27 18:11:07 plat5 /sbin/opensips[23569]: errnum: -1
>
> Error -1 means flowID is invalid, but I sent the same value on both calls.
>
> This is the call:
>
> cc_handle_call("$rU")
>
> I'm using Opensips 2.4.2 with Debian 8.11.
>
> Am I missing something or found a bug?
>
> Thanks
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20180829/315adfc0/attachment-0001.html>