[OpenSIPS-Users] Missing Ack when using B2BUA
Louis Rochon
lrochon at solacom.com
Fri Mar 30 22:54:59 CEST 2012
We are having a problem where we believe that OpenSIPS B2BUA is failing to send an ACK to a 200 ok message. Everything else works great, but we have
tried alot of different things to get around this issue, with no good results.
We are using OpenSIPS 1.7.2 8878
Phone A 172.16.6.254 (number 1001)
Phone B 192.168.130.103 (Number 8195553185, this is actually a SIP gateway, but from the point of view of OpenSIPS, it might has well be a phone)
Phone C 172.16.1.83 (number 5555)
OpenSIPS 192.168.130.105
Under normal operation, Phone A calls Phone B via OpenSIPS B2BUA.
If phone B fails or goes off-air for whatever reason, two things need to happen: 1, new calls must be redirected to phone C, and 2, any calls that are
currently progress between Phone A and Phone B must be redirected so that Phone A talks to Phone C.
It's part 2 we are having a problem with. We have a job that does a SIP keep alive towards Phone B. If Phone B fails, we do two things:
1. Launch command "opensipsctl fifo b2b_list"
That results in:
tuple:: 0 key=328.0 scenario_state=1 lifetime=106223 db_flag=2 scenario=FailOver next_scenario_state=1
servers:: 0 scenario_id=Server1 key=B2B.311.172 disconnected=0 state=1 no=0 type=0 peer=B2B.330.7393716
to_uri:: sip:8195553185 at 192.168.130.105
from_uri:: sip:1001 at 192.168.130.105
clients:: 0 scenario_id=phone1 key=B2B.330.7393716 disconnected=0 state=1 no=1 type=1 peer=B2B.311.172
to_uri:: sip:8195553185 at 192.168.130.103
from_uri:: sip:1001 at 192.168.130.105
bridge_entities:: 0 scenario_id=Server1 key=B2B.311.172 disconnected=0 state=1 no=0 type=0 peer=B2B.330.7393716
to_uri:: sip:8195553185 at 192.168.130.105
from_uri:: sip:1001 at 192.168.130.105
bridge_entities:: 1 scenario_id=phone1 key=B2B.330.7393716 disconnected=0 state=1 no=1 type=1 peer=B2B.311.172
to_uri:: sip:8195553185 at 192.168.130.103
from_uri:: sip:1001 at 192.168.130.105
2. We extract the key (328.0 in this case)
and then launch command:
opensipsctl fifo b2b_bridge 328.0 sip:5555 at 172.16.1.83 0
PhoneA OpenSIPS PhoneB PhoneC
----Invite---------->
<---Trying----------
-----Invite------>
<----Trying-------
<--183 Progress---
<---183 Progress----
<---200 OK--------
<---200 OK----------
-----ACK ---------->
------ACK-------->
Here, PhoneA talks to PhoneB.
Simulate failure of phone B, so we do
"opensipsctl fifo b2b_list" and "opensipsctl fifo b2b_bridge 328.0 sip:5555 at 172.16.1.83 0"
Call flow continues:
-------BYE------->
<--Invite (no SDP)--
<--200 OK (no SDP)-
---200 OK --------->
-------------Invite-------------->
<------------Trying---------------
<---------180 Ringing-------------
---200 OK---------->
<-Missing ACK!!!----
---200 OK---------->
---200 OK---------->
---BYE------------->
<----200 OK---------
--------Cancel------------------->
<-----487 Request Cancel----------
---------ACK--------------------->
<-----------200 OK----------------
opensips.cfg:
# $Id: opensips-b2b.cfg $
# Debugging mode:
debug=9
memlog= 6
auto_aliases=no
fork=yes
#fork=no
log_stderror=yes
disable_dns_blacklist=yes
listen=192.168.130.105:5060
# alias=OSIPS_REALM
#port=OSIPS_PORT
sip_warning=0
#server_header="SRV_SIGNATURE"
#user_agent_header="PP_USER_AGENT"
#mhomed=yes
#memlog=2
check_via=no
dns=off
rev_dns=off
children=8
disable_tcp=yes
# log_facility=LOG_LOCAL7
# for more info: opensips -h
# ------------------ module loading ----------------------------------
mpath="/usr/local/lib/opensips/modules/"
loadmodule "db_mysql.so"
loadmodule "textops.so"
loadmodule "maxfwd.so"
loadmodule "rr.so"
loadmodule "sl.so"
loadmodule "tm.so"
loadmodule "signaling.so"
loadmodule "b2b_entities.so"
loadmodule "b2b_logic.so"
loadmodule "usrloc.so"
loadmodule "registrar.so"
loadmodule "mi_fifo.so"
loadmodule "auth.so"
loadmodule "uac_auth.so"
loadmodule "auth_db.so"
# ----------------- setting module-specific parameters ---------------
modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo")
modparam("auth_db", "calculate_ha1", yes)
modparam("auth_db", "password_column", "password")
modparam("auth_db|usrloc|b2b_entities|b2b_logic", "db_url", "mysql://opensips:opensipsrw@localhost/opensips")
modparam("usrloc", "db_mode", 2)
modparam("tm", "pass_provisional_replies", 1)
modparam("b2b_logic", "script_scenario", "/usr/local/etc/opensips/scenario_script.xml")
#modparam("b2b_logic", "script_scenario", "/usr/local/etc/opensips/scenario_script2.xml")
# modparam("b2b_logic", "extern_scenario", "/usr/local/etc/opensips/scenario_extern.xml")
modparam("b2b_entities", "script_req_route", "b2b_request")
modparam("b2b_entities", "script_reply_route", "b2b_reply")
#modparam("b2b_logic", "init_callid_hdr", "Init-CallID")
#modparam("b2b_logic", "b2bl_key_avp", "$avp(99)")
route {
if (!mf_process_maxfwd_header("10")) {
sl_send_reply("483","Too Many Hops");
exit;
};
if (msg:len >= 2380 ) {
sl_send_reply("513", "Message too big");
exit;
};
# if (!method=="REGISTER")
# record_route();
# subsequent messages withing a dialog should take the
# path determined by record-routing
if (loose_route()) {
# mark routing logic in request
append_hf("P-hint: rr-enforced\r\n");
route(1);
};
if(is_method("INVITE") && !(src_ip == "192.168.130.105" && src_port ==5060))
{
# write code to do a variable to fix URI
# DO NOT call t_newtran() on this request -> it will result in the transaction never being deleted
xlog("This is method INVITE if\n");
xlog("$tu\n");
xlog("$tU\n");
b2b_init_request("FailOver", "sip:$tU at 192.168.130.103","sip:$tU at 192.168.130.104") ;
# b2b_init_request("refer","sip:$tU at 172.16.5.216");
# b2b_init_request("FailOver", "sip:$tU at 172.16.1.83","sip:$tU at 192.168.130.104") ; /*reverse the call flow */
xlog("Left the Invite B2B routine");
# xlog("$mi] got b2bl_key='$avp(99)'\n");
exit; # do not forward this request, another one will be generated
};
if (!uri==myself) {
# mark routing logic in request
append_hf("P-hint: outbound\r\n");
route(1);
};
# if (uri==myself) {
# if (method=="REGISTER") {
# save("location");
# exit;
# };
# native SIP destinations are handled using our USRLOC DB
# if (!lookup("location")) {
# sl_send_reply("404", "Not Found");
# exit;
# };
append_hf("P-hint: usrloc applied\r\n");
# };
route(1);
}
route[1] {
# send it out now; use stateful forwarding as it works reliably
# even for UDP2TCP
if (!t_relay()) {
sl_reply_error();
};
exit;
}
route[b2b_request] {
xlog("b2b_request ($ci)\n");
}
route[b2b_reply] {
xlog("b2b_reply ($ci)\n");
}
local_route {
xlog("local_route:body: ($rb)\n");
xlog("local_route:method: ($rm)\n");
}
scenario_script.xml:
<?xml version="1.0"?>
<scenario id="FailOver" name="R11TestBed" param="2" type="script">
<init>
<bridge>
<server>
<id>Server1</id>
</server>
<client>
<id>phone1</id>
<type>message</type>
<destination>
<value type = "param">1</value>
</destination>
</client>
</bridge>
<state>1</state>
</init>
</scenario>
Logs: (but only after sending opensipsctl fifo b2b_bridge 328.0 sip:5555 at 172.16.1.83 0)
[root at localhost ~]#
Mar 30 16:47:16 [2727] DBG:mi_fifo:mi_parse_tree: adding node <> ; val <328.0>
Mar 30 16:47:16 [2727] DBG:mi_fifo:mi_parse_tree: adding node <> ; val <sip:5555 at 172.16.1.83>
Mar 30 16:47:16 [2727] DBG:mi_fifo:mi_parse_tree: adding node <> ; val <0>
Mar 30 16:47:16 [2727] DBG:mi_fifo:mi_parse_node: end of input tree
Mar 30 16:47:16 [2727] DBG:mi_fifo:mi_fifo_server: done parsing the mi tree
Mar 30 16:47:16 [2727] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:16 [2727] DBG:b2b_logic:b2bl_create_new_entity: new entity type [1] [0xb6088d60]->[]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_parse_key: hash_index = [330] - local_index= [8005567]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [89188638-5da13315-verdf]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_send_request: Send request [BYE] for entity type [1] for dlg[0xb6088ae8]->[B2B.330.8005567]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_client_build_dlg: Rem_target = sip:8195553185 at 192.168.130.103:5060
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_client_build_dlg: send sock= 192.168.130.105
Mar 30 16:47:16 [2727] DBG:tm:t_uac: next_hop=<sip:8195553185 at 192.168.130.103:5060>
Mar 30 16:47:16 [2727] DBG:core:mk_proxy: doing DNS lookup...
Mar 30 16:47:16 [2727] DBG:tm:dlg2hash: 53695
Mar 30 16:47:16 [2727] DBG:tm:print_request_uri: sip:8195553185 at 192.168.130.103:5060
Mar 30 16:47:16 [2727] DBG:tm:t_uac: building sip_msg from buffer
Mar 30 16:47:16 [2727] DBG:core:parse_msg: SIP Request:
Mar 30 16:47:16 [2727] DBG:core:parse_msg: method: <BYE>
Mar 30 16:47:16 [2727] DBG:core:parse_msg: uri: <sip:8195553185 at 192.168.130.103:5060>
Mar 30 16:47:16 [2727] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2727] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2727] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKfb1d.aa3974f7.0>; state=16
Mar 30 16:47:16 [2727] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2727] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2727] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2727] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2727] DBG:core:parse_to_param: tag=89188638-5da13315-verdf
Mar 30 16:47:16 [2727] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2727] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.103}
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: <To> [62]; uri=[sip:8195553185 at 192.168.130.103]
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: to body [<sip:8195553185 at 192.168.130.103>]
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: cseq <CSeq>: <32410> <BYE>
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: found end of header
local_route:body: ()
local_route:method: (BYE)
Mar 30 16:47:16 [2727] DBG:tm:set_timer: relative timeout is 500000
Mar 30 16:47:16 [2727] DBG:tm:insert_timer_unsafe: [4]: 0xb608c5dc (84897200000)
Mar 30 16:47:16 [2727] DBG:tm:set_timer: relative timeout is 30
Mar 30 16:47:16 [2727] DBG:tm:insert_timer_unsafe: [0]: 0xb608c5f8 (84926)
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:16 [2727] DBG:b2b_entities:b2b_send_request: Send request [INVITE] for entity type [0] for dlg[0xb6087514]->[B2B.150.444]
Mar 30 16:47:16 [2727] DBG:tm:t_uac: next_hop=<sip:1001 at 172.16.6.254:5060;transport=udp>
Mar 30 16:47:16 [2727] DBG:core:mk_proxy: doing DNS lookup...
Mar 30 16:47:16 [2727] DBG:tm:dlg2hash: 2549
Mar 30 16:47:16 [2727] DBG:tm:print_request_uri: sip:1001 at 172.16.6.254:5060;transport=udp
Mar 30 16:47:16 [2727] DBG:tm:t_uac: building sip_msg from buffer
Mar 30 16:47:16 [2727] DBG:core:parse_msg: SIP Request:
Mar 30 16:47:16 [2727] DBG:core:parse_msg: method: <INVITE>
Mar 30 16:47:16 [2727] DBG:core:parse_msg: uri: <sip:1001 at 172.16.6.254:5060;transport=udp>
Mar 30 16:47:16 [2727] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2727] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2727] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5f9.46eea692.0>; state=16
Mar 30 16:47:16 [2727] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2727] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2727] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2727] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2727] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:16 [2727] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2727] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: <To> [43]; uri=[sip:1001 at 192.168.130.105]
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: to body [<sip:1001 at 192.168.130.105>]
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:16 [2727] DBG:core:get_hdr_field: found end of header
local_route:body: ()
local_route:method: (INVITE)
Mar 30 16:47:16 [2727] DBG:tm:t_uac: REF_UNSAFE:[0xb608ddf8] after is 1
Mar 30 16:47:16 [2727] DBG:tm:set_timer: relative timeout is 500000
Mar 30 16:47:16 [2727] DBG:tm:insert_timer_unsafe: [4]: 0xb608df44 (84897200000)
Mar 30 16:47:16 [2727] DBG:tm:set_timer: relative timeout is 30
Mar 30 16:47:16 [2727] DBG:tm:insert_timer_unsafe: [0]: 0xb608df60 (84926)
Mar 30 16:47:16 [2739] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:16 [2739] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2739] DBG:core:parse_msg: status: <200>
Mar 30 16:47:16 [2739] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:16 [2739] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2739] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKfb1d.aa3974f7.0>; state=16
Mar 30 16:47:16 [2739] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2739] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2739] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2739] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:16 [2739] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:16 [2739] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:16 [2739] DBG:core:parse_headers: flags=22
Mar 30 16:47:16 [2739] DBG:core:parse_to_param: tag=89188638-5da13315-verdf
Mar 30 16:47:16 [2739] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2739] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.103}
Mar 30 16:47:16 [2739] DBG:core:get_hdr_field: <To> [62]; uri=[sip:8195553185 at 192.168.130.103]
Mar 30 16:47:16 [2739] DBG:core:get_hdr_field: to body [<sip:8195553185 at 192.168.130.103>]
Mar 30 16:47:16 [2739] DBG:core:get_hdr_field: cseq <CSeq>: <32410> <BYE>
Mar 30 16:47:16 [2739] DBG:tm:t_reply_matching: hash 53695 label 2135397290 branch 0
Mar 30 16:47:16 [2739] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608c490] after is 1
Mar 30 16:47:16 [2739] DBG:tm:t_reply_matching: reply matched (T=0xb608c490)!
Mar 30 16:47:16 [2739] DBG:tm:t_check: end=0xb608c490
Mar 30 16:47:16 [2739] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Mar 30 16:47:16 [2739] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Mar 30 16:47:16 [2739] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:16 [2739] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:16 [2739] DBG:tm:run_trans_callbacks: trans=0xb608c490, callback type 256, id 0 entered
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_tm_cback: tm [0xb608c490] notification cb for [200] reply
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_parse_key: hash_index = [330] - local_index= [8005567]
Mar 30 16:47:16 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2739] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:16 [2739] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:16 [2739] DBG:core:parse_to_param: tag=bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e
Mar 30 16:47:16 [2739] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2739] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e]
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [89188638-5da13315-verdf]
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_tm_cback: Received reply [200] for dialog [0xb6088ae8], method [BYE]
Mar 30 16:47:16 [2739] DBG:b2b_entities:b2b_tm_cback: status la inceput = 8
Mar 30 16:47:16 [2739] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:16 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2739] DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [328.0] with entity [B2B.330.8005567]
Mar 30 16:47:16 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2739] ERROR:b2b_logic:b2b_logic_notify_reply: No b2b_key match found [B2B.330.8005567], src=1
b2b_reply (B2B.330.8005567)
Mar 30 16:47:16 [2739] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 30 16:47:16 [2739] DBG:tm:insert_timer_unsafe: [2]: 0xb608c4d8 (84901)
Mar 30 16:47:16 [2739] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608c490] after is 0
Mar 30 16:47:16 [2739] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:16 [2739] DBG:core:receive_msg: cleaning up
Mar 30 16:47:16 [2728] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:16 [2728] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2728] DBG:core:parse_msg: status: <200>
Mar 30 16:47:16 [2728] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2728] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5f9.46eea692.0>; state=16
Mar 30 16:47:16 [2728] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2728] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2728] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2728] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:16 [2728] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:16 [2728] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=22
Mar 30 16:47:16 [2728] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:16 [2728] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2728] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: <To> [43]; uri=[sip:1001 at 192.168.130.105]
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: to body [<sip:1001 at 192.168.130.105>]
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2728] DBG:tm:t_reply_matching: hash 2549 label 694873700 branch 0
Mar 30 16:47:16 [2728] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608ddf8] after is 2
Mar 30 16:47:16 [2728] DBG:tm:t_reply_matching: reply matched (T=0xb608ddf8)!
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2728] DBG:tm:t_check: end=0xb608ddf8
Mar 30 16:47:16 [2728] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=1)
Mar 30 16:47:16 [2728] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Mar 30 16:47:16 [2728] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:16 [2728] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:16 [2728] DBG:tm:run_trans_callbacks: trans=0xb608ddf8, callback type 256, id 0 entered
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: tm [0xb608ddf8] notification cb for [200] reply
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: content_length=315
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:16 [2728] DBG:core:parse_to_param: tag=B2B.150.444
Mar 30 16:47:16 [2728] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2728] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.105;user=phone}
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: Received reply [200] for dialog [0xb6087514], method [INVITE]
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: status la inceput = 6
Mar 30 16:47:16 [2728] DBG:tm:t_unref_cell: UNREF_UNSAFE: [0xb608ddf8] after is 1
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: dlg=[0xb6087514], uac_tran=NULL
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: DLG state = 6
Mar 30 16:47:16 [2728] DBG:b2b_entities:b2b_tm_cback: switched the state CONFIRMED [0xb6087514]
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [328.0] with entity [B2B.150.444]
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2bl_search_entity: Key [B2B.150.444]
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2b_logic_notify_reply: b2b_entity key = B2B.150.444
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2b_logic_notify_reply: Received a reply [200] while in BRIDGING scenario
Mar 30 16:47:16 [2728] DBG:b2b_logic:process_bridge_200OK: entity_no = 0, entity=0xb6081878, be[0]= 0xb6081878
Mar 30 16:47:16 [2728] DBG:b2b_logic:process_bridge_200OK: Send invite to sip:5555 at 172.16.1.83
Mar 30 16:47:16 [2728] DBG:b2b_logic:process_bridge_200OK: From dname:
Mar 30 16:47:16 [2728] DBG:core:MD5StringArray: MD5 calculated: bfbcd10cb5e39cf1da6ac3f8c8341f14
Mar 30 16:47:16 [2728] DBG:b2b_entities:generate_tag: from_tag = bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e
Mar 30 16:47:16 [2728] DBG:tm:t_uac: next_hop=<sip:5555 at 172.16.1.83>
Mar 30 16:47:16 [2728] DBG:core:mk_proxy: doing DNS lookup...
Mar 30 16:47:16 [2728] DBG:tm:dlg2hash: 62464
Mar 30 16:47:16 [2728] DBG:tm:print_request_uri: sip:5555 at 172.16.1.83
Mar 30 16:47:16 [2728] DBG:tm:t_uac: building sip_msg from buffer
Mar 30 16:47:16 [2728] DBG:core:parse_msg: SIP Request:
Mar 30 16:47:16 [2728] DBG:core:parse_msg: method: <INVITE>
Mar 30 16:47:16 [2728] DBG:core:parse_msg: uri: <sip:5555 at 172.16.1.83>
Mar 30 16:47:16 [2728] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2728] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK004f.1b8733b7.0>; state=16
Mar 30 16:47:16 [2728] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2728] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2728] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2728] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2728] DBG:core:parse_to: end of header reached, state=9
Mar 30 16:47:16 [2728] DBG:core:parse_to: display={}, ruri={sip:5555 at 172.16.1.83}
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: <To> [22]; uri=[sip:5555 at 172.16.1.83]
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: to body [sip:5555 at 172.16.1.83
]
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: cseq <CSeq>: <3> <INVITE>
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: content_length=315
Mar 30 16:47:16 [2728] DBG:core:get_hdr_field: found end of header
local_route:body: (v=0
o=MxSIP 0 2 IN IP4 172.16.6.254
s=SIP Call
c=IN IP4 172.16.6.254
t=0 0
m=audio 3000 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=silenceSupp:on - - - -
a=fmtp:101 0-15
a=ptime:30
a=rtcp:3001 IN IP4 172.16.6.254
a=sendrecv
)
local_route:method: (INVITE)
Mar 30 16:47:16 [2728] DBG:tm:t_uac: REF_UNSAFE:[0xb608b2b0] after is 1
Mar 30 16:47:16 [2728] DBG:tm:set_timer: relative timeout is 500000
Mar 30 16:47:16 [2728] DBG:tm:insert_timer_unsafe: [4]: 0xb608b3fc (84897300000)
Mar 30 16:47:16 [2728] DBG:tm:set_timer: relative timeout is 30
Mar 30 16:47:16 [2728] DBG:tm:insert_timer_unsafe: [0]: 0xb608b418 (84926)
Mar 30 16:47:16 [2728] DBG:b2b_entities:client_new: new client entity [0xb60887e0] callid=[B2B.500.3774777] tag=[bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e] param=[328.0] last method=[1] dlg->uac_tran=[0xb608b2b0]
Mar 30 16:47:16 [2728] DBG:b2b_logic:b2bl_create_new_entity: new entity type [1] [0xb6088964]->[B2B.500.3774777]
Mar 30 16:47:16 [2728] WARNING:b2b_logic:b2bl_delete_entity: entity [0xb6088d60]->[] not found for tuple [328.0]
Mar 30 16:47:16 [2728] INFO:b2b_logic:b2bl_delete_entity: delete tuple [328.0], entity []
[0xb60873a4]->[328.0] to_del=[0] lifetime=[128058] bridge_entities[0xb6081878][(nil)][(nil)]
.type=[0] index=[0] [0xb6081878]->[B2B.150.444] state=1 no=0 dlginfo=[0xb6089630] peer=[(nil)] prev:next=[(nil)][(nil)]
..........dlginfo=[0xb6089630]->[cf2b52e1fa609970][30383c50a9][B2B.150.444]
.type=[0] index=[0] [0xb6081878] peer=[(nil)] prev:next=[(nil)][(nil)]
Mar 30 16:47:16 [2728] INFO:b2b_logic:b2bl_add_client: adding entity [0xb6088964]->[B2B.500.3774777] to tuple [0xb60873a4]->[328.0]
[0xb60873a4]->[328.0] to_del=[0] lifetime=[128058] bridge_entities[0xb6081878][0xb6088964][(nil)]
.type=[0] index=[0] [0xb6081878]->[B2B.150.444] state=1 no=0 dlginfo=[0xb6089630] peer=[(nil)] prev:next=[(nil)][(nil)]
..........dlginfo=[0xb6089630]->[cf2b52e1fa609970][30383c50a9][B2B.150.444]
.type=[1] index=[0] [0xb6088964]->[B2B.500.3774777] state=0 no=1 dlginfo=[(nil)] peer=[(nil)] prev:next=[(nil)][(nil)]
.type=[0] index=[0] [0xb6081878] peer=[(nil)] prev:next=[(nil)][(nil)]
.type=[1] index=[1] [0xb6088964] peer=[(nil)] prev:next=[(nil)][(nil)]
b2b_reply (cf2b52e1fa609970)
Mar 30 16:47:16 [2728] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 30 16:47:16 [2728] DBG:tm:insert_timer_unsafe: [2]: 0xb608de40 (84901)
Mar 30 16:47:16 [2728] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608ddf8] after is 0
Mar 30 16:47:16 [2728] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:16 [2728] DBG:core:receive_msg: cleaning up
Mar 30 16:47:16 [2730] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:16 [2730] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2730] DBG:core:parse_msg: status: <100>
Mar 30 16:47:16 [2730] DBG:core:parse_msg: reason: <Trying>
Mar 30 16:47:16 [2730] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2730] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK004f.1b8733b7.0>; state=16
Mar 30 16:47:16 [2730] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2730] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2730] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2730] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:16 [2730] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:16 [2730] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:16 [2730] DBG:core:parse_headers: flags=22
Mar 30 16:47:16 [2730] DBG:core:parse_to: end of header reached, state=10
Mar 30 16:47:16 [2730] DBG:core:parse_to: display={}, ruri={sip:5555 at 172.16.1.83}
Mar 30 16:47:16 [2730] DBG:core:get_hdr_field: <To> [24]; uri=[sip:5555 at 172.16.1.83]
Mar 30 16:47:16 [2730] DBG:core:get_hdr_field: to body [<sip:5555 at 172.16.1.83>
]
Mar 30 16:47:16 [2730] DBG:core:get_hdr_field: cseq <CSeq>: <3> <INVITE>
Mar 30 16:47:16 [2730] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2730] DBG:tm:t_reply_matching: hash 62464 label 2066970801 branch 0
Mar 30 16:47:16 [2730] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608b2b0] after is 2
Mar 30 16:47:16 [2730] DBG:tm:t_reply_matching: reply matched (T=0xb608b2b0)!
Mar 30 16:47:16 [2730] DBG:tm:t_check: end=0xb608b2b0
Mar 30 16:47:16 [2730] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=1)
Mar 30 16:47:16 [2730] DBG:tm:t_should_relay_response: T_code=0, new_code=100
Mar 30 16:47:16 [2730] DBG:tm:local_reply: branch=0, save=0, winner=-1
Mar 30 16:47:16 [2730] DBG:tm:set_timer: relative timeout is 120
Mar 30 16:47:16 [2730] DBG:tm:insert_timer_unsafe: [1]: 0xb608b418 (85016)
Mar 30 16:47:16 [2730] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608b2b0] after is 1
Mar 30 16:47:16 [2730] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:16 [2730] DBG:core:receive_msg: cleaning up
Mar 30 16:47:16 [2741] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:16 [2741] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2741] DBG:core:parse_msg: status: <180>
Mar 30 16:47:16 [2741] DBG:core:parse_msg: reason: <Ringing>
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2741] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK004f.1b8733b7.0>; state=16
Mar 30 16:47:16 [2741] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2741] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2741] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2741] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:16 [2741] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:16 [2741] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=22
Mar 30 16:47:16 [2741] DBG:core:parse_to_param: tag=550460885
Mar 30 16:47:16 [2741] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2741] DBG:core:parse_to: display={}, ruri={sip:5555 at 172.16.1.83}
Mar 30 16:47:16 [2741] DBG:core:get_hdr_field: <To> [38]; uri=[sip:5555 at 172.16.1.83]
Mar 30 16:47:16 [2741] DBG:core:get_hdr_field: to body [<sip:5555 at 172.16.1.83>]
Mar 30 16:47:16 [2741] DBG:core:get_hdr_field: cseq <CSeq>: <3> <INVITE>
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2741] DBG:tm:t_reply_matching: hash 62464 label 2066970801 branch 0
Mar 30 16:47:16 [2741] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608b2b0] after is 2
Mar 30 16:47:16 [2741] DBG:tm:t_reply_matching: reply matched (T=0xb608b2b0)!
Mar 30 16:47:16 [2741] DBG:tm:t_check: end=0xb608b2b0
Mar 30 16:47:16 [2741] DBG:tm:reply_received: org. status uas=0, uac[0]=100 local=2 is_invite=1)
Mar 30 16:47:16 [2741] DBG:tm:t_should_relay_response: T_code=0, new_code=180
Mar 30 16:47:16 [2741] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:16 [2741] DBG:tm:local_reply: Passing provisional reply 180 to FIFO application
Mar 30 16:47:16 [2741] DBG:tm:run_trans_callbacks: trans=0xb608b2b0, callback type 512, id 0 entered
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_tm_cback: tm [0xb608b2b0] notification cb for [180] reply
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_parse_key: hash_index = [500] - local_index= [3774777]
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2741] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:16 [2741] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:16 [2741] DBG:core:parse_to_param: tag=bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e
Mar 30 16:47:16 [2741] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2741] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e]
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [550460885]
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for client dlg [0xb60887e0] last_method=1 dlg->uac_tran=[0xb608b2b0]
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_tm_cback: Received reply [180] for dialog [0xb60887e0], method [INVITE]
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_tm_cback: status la inceput = 1
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_new_dlg: Not an initial request
Mar 30 16:47:16 [2741] DBG:b2b_entities:b2b_tm_cback: Created new dialog structure 0xb6088e50
Mar 30 16:47:16 [2741] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2741] DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [328.0] with entity [B2B.500.3774777]
Mar 30 16:47:16 [2741] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2741] DBG:b2b_logic:b2bl_search_entity: Key [B2B.500.3774777]
Mar 30 16:47:16 [2741] DBG:b2b_logic:b2b_logic_notify_reply: b2b_entity key = B2B.500.3774777
Mar 30 16:47:16 [2741] DBG:b2b_logic:b2b_logic_notify_reply: Received a reply [180] while in BRIDGING scenario
b2b_reply (B2B.500.3774777)
Mar 30 16:47:16 [2741] DBG:tm:set_timer: relative timeout is 120
Mar 30 16:47:16 [2741] DBG:tm:insert_timer_unsafe: [1]: 0xb608b418 (85016)
Mar 30 16:47:16 [2741] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608b2b0] after is 1
Mar 30 16:47:16 [2741] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:16 [2741] DBG:core:receive_msg: cleaning up
Mar 30 16:47:16 [2746] DBG:tm:utimer_routine: timer routine:4,tl=0xb608c5dc next=0xb608df44, timeout=84897200000
Mar 30 16:47:16 [2746] DBG:tm:utimer_routine: timer routine:4,tl=0xb608df44 next=(nil), timeout=84897200000
Mar 30 16:47:16 [2729] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:16 [2729] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:16 [2729] DBG:core:parse_msg: status: <200>
Mar 30 16:47:16 [2729] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:16 [2729] DBG:core:parse_headers: flags=2
Mar 30 16:47:16 [2729] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5f9.46eea692.0>; state=16
Mar 30 16:47:16 [2729] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:16 [2729] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:16 [2729] DBG:core:parse_headers: this is the first via
Mar 30 16:47:16 [2729] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:16 [2729] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:16 [2729] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:16 [2729] DBG:core:parse_headers: flags=22
Mar 30 16:47:16 [2729] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:16 [2729] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2729] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:16 [2729] DBG:core:get_hdr_field: <To> [43]; uri=[sip:1001 at 192.168.130.105]
Mar 30 16:47:16 [2729] DBG:core:get_hdr_field: to body [<sip:1001 at 192.168.130.105>]
Mar 30 16:47:16 [2729] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Mar 30 16:47:16 [2729] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2729] DBG:tm:t_reply_matching: hash 2549 label 694873700 branch 0
Mar 30 16:47:16 [2729] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608ddf8] after is 1
Mar 30 16:47:16 [2729] DBG:tm:t_reply_matching: reply matched (T=0xb608ddf8)!
Mar 30 16:47:16 [2729] DBG:core:parse_headers: flags=8
Mar 30 16:47:16 [2729] DBG:tm:t_check: end=0xb608ddf8
Mar 30 16:47:16 [2729] DBG:tm:reply_received: org. status uas=200, uac[0]=200 local=2 is_invite=1)
Mar 30 16:47:16 [2729] DBG:tm:t_should_relay_response: T_code=200, new_code=200
Mar 30 16:47:16 [2729] DBG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Mar 30 16:47:16 [2729] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:16 [2729] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:16 [2729] DBG:tm:run_trans_callbacks: trans=0xb608ddf8, callback type 256, id 0 entered
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_tm_cback: tm [0xb608ddf8] notification cb for [200] reply
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:16 [2729] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:16 [2729] DBG:core:get_hdr_field: content_length=315
Mar 30 16:47:16 [2729] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:16 [2729] DBG:core:parse_to_param: tag=B2B.150.444
Mar 30 16:47:16 [2729] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:16 [2729] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.105;user=phone}
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_tm_cback: Got unmatching dlg [0xb6087514] dlg->uac_tran=[(nil)] for transaction [0xb608ddf8]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:16 [2729] DBG:b2b_entities:b2b_tm_cback: I don't care anymore about this transaction for dlg [0xb6087514] last_method=1 method_id=1 t=[0xb608ddf8] dlg->uac_tran=[(nil)]
Mar 30 16:47:16 [2729] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608ddf8] after is 0
Mar 30 16:47:16 [2729] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:16 [2729] DBG:core:receive_msg: cleaning up
Mar 30 16:47:16 [2746] DBG:tm:utimer_routine: timer routine:4,tl=0xb608b3fc next=(nil), timeout=84897300000
Mar 30 16:47:17 [2732] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:17 [2732] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:17 [2732] DBG:core:parse_msg: status: <200>
Mar 30 16:47:17 [2732] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:17 [2732] DBG:core:parse_headers: flags=2
Mar 30 16:47:17 [2732] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5f9.46eea692.0>; state=16
Mar 30 16:47:17 [2732] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:17 [2732] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:17 [2732] DBG:core:parse_headers: this is the first via
Mar 30 16:47:17 [2732] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:17 [2732] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:17 [2732] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:17 [2732] DBG:core:parse_headers: flags=22
Mar 30 16:47:17 [2732] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:17 [2732] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:17 [2732] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:17 [2732] DBG:core:get_hdr_field: <To> [43]; uri=[sip:1001 at 192.168.130.105]
Mar 30 16:47:17 [2732] DBG:core:get_hdr_field: to body [<sip:1001 at 192.168.130.105>]
Mar 30 16:47:17 [2732] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Mar 30 16:47:17 [2732] DBG:core:parse_headers: flags=8
Mar 30 16:47:17 [2732] DBG:tm:t_reply_matching: hash 2549 label 694873700 branch 0
Mar 30 16:47:17 [2732] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608ddf8] after is 1
Mar 30 16:47:17 [2732] DBG:tm:t_reply_matching: reply matched (T=0xb608ddf8)!
Mar 30 16:47:17 [2732] DBG:core:parse_headers: flags=8
Mar 30 16:47:17 [2732] DBG:tm:t_check: end=0xb608ddf8
Mar 30 16:47:17 [2732] DBG:tm:reply_received: org. status uas=200, uac[0]=200 local=2 is_invite=1)
Mar 30 16:47:17 [2732] DBG:tm:t_should_relay_response: T_code=200, new_code=200
Mar 30 16:47:17 [2732] DBG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Mar 30 16:47:17 [2732] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:17 [2732] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:17 [2732] DBG:tm:run_trans_callbacks: trans=0xb608ddf8, callback type 256, id 0 entered
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_tm_cback: tm [0xb608ddf8] notification cb for [200] reply
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:17 [2732] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:17 [2732] DBG:core:get_hdr_field: content_length=315
Mar 30 16:47:17 [2732] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:17 [2732] DBG:core:parse_to_param: tag=B2B.150.444
Mar 30 16:47:17 [2732] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:17 [2732] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.105;user=phone}
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_tm_cback: Got unmatching dlg [0xb6087514] dlg->uac_tran=[(nil)] for transaction [0xb608ddf8]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:17 [2732] DBG:b2b_entities:b2b_tm_cback: I don't care anymore about this transaction for dlg [0xb6087514] last_method=1 method_id=1 t=[0xb608ddf8] dlg->uac_tran=[(nil)]
Mar 30 16:47:17 [2732] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608ddf8] after is 0
Mar 30 16:47:17 [2732] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:17 [2732] DBG:core:receive_msg: cleaning up
Mar 30 16:47:19 [2731] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:19 [2731] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:19 [2731] DBG:core:parse_msg: status: <200>
Mar 30 16:47:19 [2731] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:19 [2731] DBG:core:parse_headers: flags=2
Mar 30 16:47:19 [2731] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5f9.46eea692.0>; state=16
Mar 30 16:47:19 [2731] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:19 [2731] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:19 [2731] DBG:core:parse_headers: this is the first via
Mar 30 16:47:19 [2731] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:19 [2731] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:19 [2731] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:19 [2731] DBG:core:parse_headers: flags=22
Mar 30 16:47:19 [2731] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:19 [2731] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:19 [2731] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:19 [2731] DBG:core:get_hdr_field: <To> [43]; uri=[sip:1001 at 192.168.130.105]
Mar 30 16:47:19 [2731] DBG:core:get_hdr_field: to body [<sip:1001 at 192.168.130.105>]
Mar 30 16:47:19 [2731] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE>
Mar 30 16:47:19 [2731] DBG:core:parse_headers: flags=8
Mar 30 16:47:19 [2731] DBG:tm:t_reply_matching: hash 2549 label 694873700 branch 0
Mar 30 16:47:19 [2731] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608ddf8] after is 1
Mar 30 16:47:19 [2731] DBG:tm:t_reply_matching: reply matched (T=0xb608ddf8)!
Mar 30 16:47:19 [2731] DBG:core:parse_headers: flags=8
Mar 30 16:47:19 [2731] DBG:tm:t_check: end=0xb608ddf8
Mar 30 16:47:19 [2731] DBG:tm:reply_received: org. status uas=200, uac[0]=200 local=2 is_invite=1)
Mar 30 16:47:19 [2731] DBG:tm:t_should_relay_response: T_code=200, new_code=200
Mar 30 16:47:19 [2731] DBG:tm:t_should_relay_response: 200 OK for INVITE after final sent
Mar 30 16:47:19 [2731] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:19 [2731] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:19 [2731] DBG:tm:run_trans_callbacks: trans=0xb608ddf8, callback type 256, id 0 entered
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_tm_cback: tm [0xb608ddf8] notification cb for [200] reply
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:19 [2731] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:19 [2731] DBG:core:get_hdr_field: content_length=315
Mar 30 16:47:19 [2731] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:19 [2731] DBG:core:parse_to_param: tag=B2B.150.444
Mar 30 16:47:19 [2731] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:19 [2731] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.105;user=phone}
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_tm_cback: Got unmatching dlg [0xb6087514] dlg->uac_tran=[(nil)] for transaction [0xb608ddf8]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:19 [2731] DBG:b2b_entities:b2b_tm_cback: I don't care anymore about this transaction for dlg [0xb6087514] last_method=1 method_id=1 t=[0xb608ddf8] dlg->uac_tran=[(nil)]
Mar 30 16:47:19 [2731] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608ddf8] after is 0
Mar 30 16:47:19 [2731] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:19 [2731] DBG:core:receive_msg: cleaning up
Mar 30 16:47:20 [2739] DBG:core:parse_msg: SIP Request:
Mar 30 16:47:20 [2739] DBG:core:parse_msg: method: <BYE>
Mar 30 16:47:20 [2739] DBG:core:parse_msg: uri: <sip:192.168.130.105:5060>
Mar 30 16:47:20 [2739] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=2
Mar 30 16:47:20 [2739] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK626149eadf258c7f8>; state=16
Mar 30 16:47:20 [2739] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:20 [2739] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:20 [2739] DBG:core:parse_headers: this is the first via
Mar 30 16:47:20 [2739] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:20 [2739] DBG:core:receive_msg: preparing to run routing scripts...
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2739] DBG:core:parse_to_param: tag=B2B.150.444
Mar 30 16:47:20 [2739] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:20 [2739] DBG:core:parse_to: display={}, ruri={sip:8195553185 at 192.168.130.105;user=phone}
Mar 30 16:47:20 [2739] DBG:core:get_hdr_field: <To> [61]; uri=[sip:8195553185 at 192.168.130.105;user=phone]
Mar 30 16:47:20 [2739] DBG:core:get_hdr_field: to body [<sip:8195553185 at 192.168.130.105;user=phone>]
Mar 30 16:47:20 [2739] DBG:core:get_hdr_field: cseq <CSeq>: <32409> <BYE>
Mar 30 16:47:20 [2739] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:20 [2739] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_prescript_f: start - method = BYE
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_prescript_f: <uri> host:port [192.168.130.105][5060]
Mar 30 16:47:20 [2739] DBG:core:grep_sock_info: checking if host==us: 15==15 && [192.168.130.105] == [192.168.130.105]
Mar 30 16:47:20 [2739] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Mar 30 16:47:20 [2739] DBG:core:parse_to_param: tag=30383c50a9
Mar 30 16:47:20 [2739] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:20 [2739] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_prescript_f: Received a b2b server request [BYE]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_prescript_f: Received request method[BYE] for dialog[0xb6087514]
Mar 30 16:47:20 [2739] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=78
Mar 30 16:47:20 [2739] DBG:tm:t_lookup_request: start searching: hash=53841, isACK=0
Mar 30 16:47:20 [2739] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 30 16:47:20 [2739] DBG:tm:t_lookup_request: no transaction found
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_prescript_f: Saved uas_tran=[0xb608982c] for dlg[0xb6087514]
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [328.0] with entity [B2B.150.444]
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2bl_search_entity: Key [B2B.150.444]
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2b_logic_notify_request: b2b_entity key = B2B.150.444
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2b_logic_notify_request: request received for tuple[0xb60873a4]->[328.0]
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2b_logic_notify_request: Scenario is in bridging state
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_reply: For server entity
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[0xb608982c]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_reply: Send reply 200 BYE, for dlg [0xb6087514]->[B2B.150.444]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_reply: Reseted transaction- send final reply [0xb6087514], uas_tran=0
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2739] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2739] DBG:core:check_ip_address: params 172.16.6.254, 172.16.6.254, 0
Mar 30 16:47:20 [2739] DBG:core:_shm_resize: resize(0) called
Mar 30 16:47:20 [2739] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 30 16:47:20 [2739] DBG:tm:insert_timer_unsafe: [2]: 0xb6089874 (84905)
Mar 30 16:47:20 [2739] DBG:tm:_reply_light: reply sent out. buf=0x81f0d64: SIP/2.0 2..., shmem=0xb6088fd4: SIP/2.0 2
Mar 30 16:47:20 [2739] DBG:tm:_reply_light: finished
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_reply: Sent reply [200] and unreffed the cell 0xb608982c
Mar 30 16:47:20 [2739] DBG:tm:t_unref_cell: UNREF_UNSAFE: [0xb608982c] after is 0
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_parse_key: hash_index = [500] - local_index= [3774777]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_request: Send request [CANCEL] for entity type [1] for dlg[0xb6088e50]->[B2B.500.3774777]
Mar 30 16:47:20 [2739] DBG:b2b_entities:b2b_send_request: send cancel request
Mar 30 16:47:20 [2739] DBG:tm:t_lookup_ident: REF_UNSAFE:[0xb608b2b0] after is 2
Mar 30 16:47:20 [2739] DBG:tm:t_lookup_ident: transaction found
Mar 30 16:47:20 [2739] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:20 [2739] DBG:tm:build_uac_cancel: sing FROM=<From: <sip:1001 at 192.168.130.105>;tag=bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e
>, TO=<To: sip:5555 at 172.16.1.83
>, CSEQ_N=<CSeq: 3>
Mar 30 16:47:20 [2739] DBG:tm:t_uac_cancel: UNREF_UNSAFE: [0xb608b2b0] after is 1
Mar 30 16:47:20 [2739] DBG:tm:set_timer: relative timeout is 500000
Mar 30 16:47:20 [2739] DBG:tm:insert_timer_unsafe: [4]: 0xb6087804 (84901300000)
Mar 30 16:47:20 [2739] DBG:tm:set_timer: relative timeout is 30
Mar 30 16:47:20 [2739] DBG:tm:insert_timer_unsafe: [0]: 0xb6087820 (84930)
Mar 30 16:47:20 [2739] DBG:b2b_logic:b2b_mark_todel: 0xb60873a4
b2b_request (cf2b52e1fa609970)
Mar 30 16:47:20 [2739] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:20 [2739] DBG:core:receive_msg: cleaning up
Mar 30 16:47:20 [2730] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:20 [2730] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:20 [2730] DBG:core:parse_msg: status: <487>
Mar 30 16:47:20 [2730] DBG:core:parse_msg: reason: <Request Cancelled>
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=2
Mar 30 16:47:20 [2730] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK004f.1b8733b7.0>; state=16
Mar 30 16:47:20 [2730] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:20 [2730] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:20 [2730] DBG:core:parse_headers: this is the first via
Mar 30 16:47:20 [2730] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:20 [2730] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:20 [2730] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=22
Mar 30 16:47:20 [2730] DBG:core:parse_to_param: tag=550460885
Mar 30 16:47:20 [2730] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:20 [2730] DBG:core:parse_to: display={}, ruri={sip:5555 at 172.16.1.83}
Mar 30 16:47:20 [2730] DBG:core:get_hdr_field: <To> [38]; uri=[sip:5555 at 172.16.1.83]
Mar 30 16:47:20 [2730] DBG:core:get_hdr_field: to body [<sip:5555 at 172.16.1.83>]
Mar 30 16:47:20 [2730] DBG:core:get_hdr_field: cseq <CSeq>: <3> <INVITE>
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=8
Mar 30 16:47:20 [2730] DBG:tm:t_reply_matching: hash 62464 label 2066970801 branch 0
Mar 30 16:47:20 [2730] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb608b2b0] after is 2
Mar 30 16:47:20 [2730] DBG:tm:t_reply_matching: reply matched (T=0xb608b2b0)!
Mar 30 16:47:20 [2730] DBG:tm:t_check: end=0xb608b2b0
Mar 30 16:47:20 [2730] DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=2 is_invite=1)
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2730] DBG:core:get_hdr_field: content_length=0
Mar 30 16:47:20 [2730] DBG:core:get_hdr_field: found end of header
Mar 30 16:47:20 [2730] DBG:tm:t_should_relay_response: T_code=180, new_code=487
Mar 30 16:47:20 [2730] DBG:tm:t_pick_branch: picked branch 0, code 487 (prio=687)
Mar 30 16:47:20 [2730] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:20 [2730] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:20 [2730] DBG:tm:run_trans_callbacks: trans=0xb608b2b0, callback type 256, id 0 entered
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_tm_cback: tm [0xb608b2b0] notification cb for [487] reply
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_parse_key: hash_index = [500] - local_index= [3774777]
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2730] DBG:core:parse_to_param: tag=bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e
Mar 30 16:47:20 [2730] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:20 [2730] DBG:core:parse_to: display={}, ruri={sip:1001 at 192.168.130.105}
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [bfbcd10cb5e39cf1da6ac3f8c8341f14-8b2e]
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [550460885]
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_tm_cback: Received reply [487] for dialog [0xb6088e50], method [INVITE]
Mar 30 16:47:20 [2730] DBG:tm:t_unref_cell: UNREF_UNSAFE: [0xb608b2b0] after is 1
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_tm_cback: dlg=[0xb6088e50], uac_tran=NULL
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_tm_cback: Non final negative reply for reINVITE
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2bl_parse_key: hash_index = [328] - local_index= [0]
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2b_logic_notify: b2b_entities notification cb for [328.0] with entity [B2B.500.3774777]
Mar 30 16:47:20 [2730] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2bl_search_entity: Key [B2B.500.3774777]
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2b_logic_notify_reply: b2b_entity key = B2B.500.3774777
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2b_logic_notify_reply: entity [B2B.500.3774777] is disconnected
Mar 30 16:47:20 [2730] DBG:b2b_logic:b2bl_delete_entity: delete entity [0xb6088964]->[B2B.500.3774777] from tuple [328.0]
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_parse_key: hash_index = [500] - local_index= [3774777]
Mar 30 16:47:20 [2730] DBG:b2b_entities:b2b_entity_delete: Deleted dlg [0xb6088e50]->[B2B.500.3774777] with dlginfo [(nil)]
Mar 30 16:47:20 [2730] INFO:db_mysql:switch_state_to_disconnected: disconnect event for 0x81ef91c
Mar 30 16:47:20 [2730] INFO:db_mysql:reset_all_statements: reseting all statements on connection: (0x81ef850) 0x81ef91c
Mar 30 16:47:20 [2730] DBG:db_mysql:db_mysql_connect: opening connection: mysql://xxxx:xxxx@localhost/opensips
Mar 30 16:47:20 [2730] DBG:db_mysql:db_mysql_connect: connection type is Localhost via UNIX socket
Mar 30 16:47:20 [2730] DBG:db_mysql:db_mysql_connect: protocol version is 10
Mar 30 16:47:20 [2730] DBG:db_mysql:db_mysql_connect: server version is 5.0.95
Mar 30 16:47:20 [2730] INFO:db_mysql:connect_with_retry: re-connected successful for 0x81ef91c
Mar 30 16:47:20 [2730] INFO:b2b_logic:b2bl_delete_entity: delete tuple [328.0], entity [B2B.500.3774777]
[0xb60873a4]->[328.0] to_del=[1] lifetime=[84930] bridge_entities[0xb6081878][(nil)][(nil)]
.type=[0] index=[0] [0xb6081878]->[B2B.150.444] state=1 no=0 dlginfo=[0xb6089630] peer=[(nil)] prev:next=[(nil)][(nil)]
..........dlginfo=[0xb6089630]->[cf2b52e1fa609970][30383c50a9][B2B.150.444]
.type=[0] index=[0] [0xb6081878] peer=[(nil)] prev:next=[(nil)][(nil)]
b2b_reply (B2B.500.3774777)
Mar 30 16:47:20 [2730] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 30 16:47:20 [2730] DBG:tm:insert_timer_unsafe: [2]: 0xb608b2f8 (84905)
Mar 30 16:47:20 [2730] DBG:tm:t_unref: UNREF_UNSAFE: [0xb608b2b0] after is 0
Mar 30 16:47:20 [2730] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:20 [2730] DBG:core:receive_msg: cleaning up
Mar 30 16:47:20 [2729] DBG:core:parse_msg: SIP Reply (status):
Mar 30 16:47:20 [2729] DBG:core:parse_msg: version: <SIP/2.0>
Mar 30 16:47:20 [2729] DBG:core:parse_msg: status: <200>
Mar 30 16:47:20 [2729] DBG:core:parse_msg: reason: <OK>
Mar 30 16:47:20 [2729] DBG:core:parse_headers: flags=2
Mar 30 16:47:20 [2729] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK004f.1b8733b7.0>; state=16
Mar 30 16:47:20 [2729] DBG:core:parse_via: end of header reached, state=5
Mar 30 16:47:20 [2729] DBG:core:parse_headers: via found, flags=2
Mar 30 16:47:20 [2729] DBG:core:parse_headers: this is the first via
Mar 30 16:47:20 [2729] DBG:core:receive_msg: After parse_msg...
Mar 30 16:47:20 [2729] DBG:core:forward_reply: found module tm, passing reply to it
Mar 30 16:47:20 [2729] DBG:tm:t_check: start=0xffffffff
Mar 30 16:47:20 [2729] DBG:core:parse_headers: flags=22
Mar 30 16:47:20 [2729] DBG:core:parse_to_param: tag=550460885
Mar 30 16:47:20 [2729] DBG:core:parse_to: end of header reached, state=29
Mar 30 16:47:20 [2729] DBG:core:parse_to: display={}, ruri={sip:5555 at 172.16.1.83}
Mar 30 16:47:20 [2729] DBG:core:get_hdr_field: <To> [38]; uri=[sip:5555 at 172.16.1.83]
Mar 30 16:47:20 [2729] DBG:core:get_hdr_field: to body [<sip:5555 at 172.16.1.83>]
Mar 30 16:47:20 [2729] DBG:core:get_hdr_field: cseq <CSeq>: <3> <CANCEL>
Mar 30 16:47:20 [2729] DBG:tm:t_reply_matching: hash 62464 label 2066970801 branch 0
Mar 30 16:47:20 [2729] DBG:tm:t_reply_matching: REF_UNSAFE:[0xb60876b8] after is 1
Mar 30 16:47:20 [2729] DBG:tm:t_reply_matching: reply matched (T=0xb60876b8)!
Mar 30 16:47:20 [2729] DBG:tm:t_check: end=0xb60876b8
Mar 30 16:47:20 [2729] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Mar 30 16:47:20 [2729] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Mar 30 16:47:20 [2729] DBG:tm:local_reply: branch=0, save=0, winner=0
Mar 30 16:47:20 [2729] DBG:tm:local_reply: local transaction completed
Mar 30 16:47:20 [2729] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 30 16:47:20 [2729] DBG:tm:insert_timer_unsafe: [2]: 0xb6087700 (84905)
Mar 30 16:47:20 [2729] DBG:tm:t_unref: UNREF_UNSAFE: [0xb60876b8] after is 0
Mar 30 16:47:20 [2729] DBG:core:destroy_avp_list: destroying list (nil)
Mar 30 16:47:20 [2729] DBG:core:receive_msg: cleaning up
Mar 30 16:47:20 [2746] ERROR:b2b_logic:b2b_logic_dump: Bridge entities is NULL
Mar 30 16:47:20 [2746] DBG:b2b_logic:b2b_logic_dump: 1 NULL
Mar 30 16:47:20 [2746] DBG:tm:timer_routine: timer routine:2,tl=0xb608c4d8 next=0xb608de40, timeout=84901
Mar 30 16:47:20 [2746] DBG:tm:wait_handler: removing 0xb608c490 from table
Mar 30 16:47:20 [2746] DBG:tm:delete_cell: delete transaction 0xb608c490
Mar 30 16:47:20 [2746] DBG:tm:wait_handler: done
Mar 30 16:47:20 [2746] DBG:tm:timer_routine: timer routine:2,tl=0xb608de40 next=(nil), timeout=84901
Mar 30 16:47:20 [2746] DBG:tm:wait_handler: removing 0xb608ddf8 from table
Mar 30 16:47:20 [2746] DBG:tm:delete_cell: delete transaction 0xb608ddf8
Mar 30 16:47:20 [2746] DBG:tm:wait_handler: done
Mar 30 16:47:20 [2746] DBG:tm:utimer_routine: timer routine:4,tl=0xb6087804 next=(nil), timeout=84901300000
Mar 30 16:47:24 [2746] DBG:tm:timer_routine: timer routine:2,tl=0xb6089874 next=0xb608b2f8, timeout=84905
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: removing 0xb608982c from table
Mar 30 16:47:24 [2746] DBG:tm:delete_cell: delete transaction 0xb608982c
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: done
Mar 30 16:47:24 [2746] DBG:tm:timer_routine: timer routine:2,tl=0xb608b2f8 next=0xb6087700, timeout=84905
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: removing 0xb608b2b0 from table
Mar 30 16:47:24 [2746] DBG:tm:delete_cell: delete transaction 0xb608b2b0
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: done
Mar 30 16:47:24 [2746] DBG:tm:timer_routine: timer routine:2,tl=0xb6087700 next=(nil), timeout=84905
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: removing 0xb60876b8 from table
Mar 30 16:47:24 [2746] DBG:tm:delete_cell: delete transaction 0xb60876b8
Mar 30 16:47:24 [2746] DBG:tm:wait_handler: done
Mar 30 16:48:59 [2746] ERROR:b2b_logic:b2b_logic_dump: Bridge entities is NULL
Mar 30 16:48:59 [2746] DBG:b2b_logic:b2b_logic_dump: 1 NULL
Mar 30 16:48:59 [2746] INFO:b2b_logic:b2bl_clean: Found expired tuple [328.0]: delete and send BYEs
Mar 30 16:48:59 [2746] DBG:b2b_logic:b2bl_delete: Delete record [0xb60873a4]->[328.0], hash_index=[328], local_index=[0]
Mar 30 16:48:59 [2746] DBG:b2b_entities:b2b_parse_key: hash_index = [150] - local_index= [444]
Mar 30 16:48:59 [2746] DBG:b2b_entities:b2b_search_htable_next_dlg: searching totag [B2B.150.444]
Mar 30 16:48:59 [2746] DBG:b2b_entities:b2b_search_htable_next_dlg: searching fromtag [30383c50a9]
Mar 30 16:48:59 [2746] DBG:b2b_entities:b2b_search_htable_next_dlg: Match for server dlg [0xb6087514] dlg->uas_tran=[(nil)]
Mar 30 16:48:59 [2746] DBG:b2b_entities:b2b_entity_delete: Deleted dlg [0xb6087514]->[B2B.150.444] with dlginfo [0xb6089630]
More information about the Users
mailing list