Hi Bogdan,<br><br>I run scenario again with a few destinations: two
8002 destinations and one 8003 destination. Here's my test analysis and
trace of INVITE processing in debug=6. I hope it helps us to see
what is wrong with my configuration.<br>
<br>* Call is received at 10:49:40: load balancer forwards INVITE to
host 10.10.5.44. Host 10.10.5.44 returns "100 Trying" but does not send
"200 OK".<br>* At 10:49:44: tm timer detects that INVITE is not
processed and cancels the call. Then failure route is called and
load_balancer tries to forward this call to 10.10.6.50. Host 10.10.6.50
again sends "100 Trying" but does not send "200 OK".<br>
* At 10.49.49: tm timer again detects that INVITE is not processed and
cancels the call. Failure procedure at this point returns < 0 for
8002. So load_balance(8003) is called. But a valid destination is not
found.<br><br>
----------------<br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: SIP Request: <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: method: <INVITE> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: uri: <<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=2 <br>Dec
22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: this is the first via <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: After parse_msg... <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: preparing to run routing scripts... <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=100 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of header reached, state=10 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: <To> [30]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>><br>
] <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:maxfwd:is_maxfwd_present: value = 70 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:uri:has_totag: no totag <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=78 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: start searching: hash=16237, isACK=0 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:matching_3261: RFC3261 transaction matching failed <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: no transaction found <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=200 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: content_length=658 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: found end of header <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:find_first_route: No Route headers found <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:loose_route: There is no Route HF <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to_param: tag=191113598 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of header reached, state=29 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={}, ruri={<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>} <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:load_balancer:do_load_<div id=":tb" class="ii gt">
balance: found requested (0) resource sip <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:build_new_dlg: new dialog 0xb6096298 (c=<a href="mailto:617010250@86.108.132.8" target="_blank">617010250@86.108.132.8</a>,f=<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>,t=<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>,ft=191113598) on hash 2448 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=ffffffffffffffff <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:init_leg_info: route_set , contact <a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>, cseq 24325 and bind_addr udp:<a href="http://10.210.54.83:5060/" target="_blank">10.210.54.83:5060</a> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]:
DBG:dialog:dlg_add_leg_info: set leg 0 for 0xb6096298:
tag=<191113598> rcseq=<24325> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:link_dlg: ref dlg 0xb6096298 with 3 -> 3 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:add_rr_param: adding (;did=099.11a69622) 0x81c0738 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:load_balancer:do_load_balance: destination <<a href="mailto:sip%3Aar@10.10.5.44" target="_blank">sip:ar@10.10.5.44</a>> selected for LB set with free=1 (max=1) <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:load_balancer:do_load_balance: destination <<a href="mailto:sip%3Aar@10.10.6.50" target="_blank">sip:ar@10.10.6.50</a>> selected for LB set with free=1 (max=1) <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:link_dlg_profile: Entered here with hash = 0 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:comp_scriptvar: int 26 : 1 / 0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_newtran: transaction on entrance=(nil) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=ffffffffffffffff <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=78 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: start searching: hash=16237, isACK=0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:matching_3261: RFC3261 transaction matching failed <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: no transaction found <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:run_reqin_callbacks: trans=0xb6096418, callback type 1, id 1 entered <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:run_reqin_callbacks: trans=0xb6096418, callback type 1, id 0 entered <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=ffffffffffffffff <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:check_ip_address: params 86.108.132.8, 86.108.132.8, 0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:_shm_resize: resize(0) called <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:_reply_light:
reply sent out. buf=0x81c0a60: SIP/2.0 1..., shmem=0xb6098260: SIP/2.0
1 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:_reply_light: finished <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:_shm_resize: resize(0) called <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:mk_proxy: doing DNS lookup... <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:check_ip_address: params 86.108.132.8, 86.108.132.8, 0 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:set_timer: relative timeout is 500000 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:insert_timer_unsafe: [4]: 0xb6096564 (24900000) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:set_timer: relative timeout is 5 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:insert_timer_unsafe: [0]: 0xb6096580 (29) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_relay_to: new transaction fwd'ed <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:unref_dlg: unref dlg 0xb6096298 with 1 -> 2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:destroy_avp_list: destroying list (nil) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: cleaning up <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: SIP Reply (status): <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: status: <100> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: reason: <Trying> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>;
state=16 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of header reached, state=5 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: this is the first via <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: After parse_msg... <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:forward_reply: found module tm, passing reply to it <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: start=0xffffffff <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=22 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=8 <br>Dec
22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via found, flags=8 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: parse_headers: this is the second via <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: end of header reached, state=10 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: <To> [30]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>><br>
] <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_should_relay_response: T_code=100, new_code=100 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:relay_reply: branch=0, save=0, relay=-1 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:set_timer: relative timeout is 5 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:insert_timer_unsafe: [1]: 0xb6096580 (29) <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:destroy_avp_list: destroying list (nil) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: cleaning up <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply (status): <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status: <180> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason: <Ringing> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>;
state=16 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of header reached, state=5 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this is the first via <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After parse_msg... <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found module tm, passing reply to it <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: start=0xffffffff <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=22 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=8 <br>Dec
22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via found, flags=8 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: parse_headers: this is the second via <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to_param: tag=86c07149-44ed-de11-9f3b-0017a4d22923 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: end of header reached, state=29 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: <To> [71]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>] <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_should_relay_response: T_code=100, new_code=180 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:relay_reply: branch=0, save=0, relay=0 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:run_trans_callbacks: trans=0xb6096418, callback type 16, id 0 entered <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:dialog:push_reply_in_dialog: 0xb6096298 totag in rpl is <86c07149-44ed-de11-9f3b-0017a4d22923> (36) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:dialog:push_reply_in_dialog: new branch with tag <86c07149-44ed-de11-9f3b-0017a4d22923> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:dialog:init_leg_info: route_set , contact , cseq 24325 and bind_addr udp:<a href="http://10.210.54.83:5060/" target="_blank">10.210.54.83:5060</a> <br>Dec
22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:dialog:dlg_add_leg_info:
set leg 1 for 0xb6096298: tag=<86c07149-44ed-de11-9f3b-0017a4d22923> rcseq=<24325> <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:build_res_buf_from_sip_res: old size: 515, new size: 454 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:build_res_buf_from_sip_res: copied size: orig:102, new: 41, rest: 413 msg= SIP/2.0 180 Ringing<br>
CSeq: 24325 INVITE<br> Via: SIP/2.0/UDP 86.108.132.8:5060;branch=z9hG4bK780409778<br> User-Agent: Ekiga/3.2.0<br> From: <<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>>;tag=191113598<br>
Call-ID: <a href="mailto:617010250@86.108.132.8" target="_blank">617010250@86.108.132.8</a><br> To: <<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>;tag=86c07149-44ed-de11-9f3b-0017a4d22923<br>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING<br>
Content-Length: 0<br> Record-Route: <sip:10.210.54.83;lr;ftag=191113598;did=099.11a69622><br> <br> <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:run_trans_callbacks: trans=0xb6096418, callback type 128, id 0 entered <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]:
DBG:dialog:next_state_dlg: dialog 0xb6096298 changed from state 1 to
state 2, due event 2 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:relay_reply: sent buf=0x81c04c0: SIP/2.0 1..., shmem=0xb6098a40: SIP/2.0 1 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:set_timer: relative timeout is 5 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:insert_timer_unsafe: [1]: 0xb6096580 (29) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list: destroying list (nil) <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning up <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer routine:4,tl=0xb6096564 next=(nil), timeout=24900000 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:0,tl=0xb6093320 next=0xb6094368, timeout=25 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:0,tl=0xb6094368 next=0xb60953b8, timeout=25 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:0,tl=0xb60953b8 next=(nil), timeout=25 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:2,tl=0xb6094248 next=0xb6093200, timeout=25 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing 0xb6094200 from table <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete transaction 0xb6094200 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:2,tl=0xb6093200 next=0xb6095298, timeout=25 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing 0xb60931b8 from table <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete transaction 0xb60931b8 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:2,tl=0xb6095298 next=(nil), timeout=25 <br>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing 0xb6095250 from table <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete transaction 0xb6095250 <br>Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:1,tl=0xb6096580 next=(nil), timeout=29 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb6096418) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:t_should_relay_response: T_code=180, new_code=408 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=2 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:t_check_status: checked status is <408> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: load_balancer: Request from <a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a> to <a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a> failed. Re-balancing to 8002! <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: found requested (0) resource sip <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: destination <<a href="mailto:sip%3Aar@10.10.6.50" target="_blank">sip:ar@10.10.6.50</a>> selected for LB set with free=1 (max=1) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: failed to remove from profile <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:dialog:link_dlg_profile: Entered here with hash = 9 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int 26 : 1 / 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:_shm_resize: resize(0) called <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:mk_proxy: doing DNS lookup... <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:check_ip_address: params 86.108.132.8, 86.108.132.8, 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative timeout is 500000 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe: [4]: 0xb6096684 (29500000) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative timeout is 5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe: [0]: 0xb60966a0 (34) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: SIP Reply (status): <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:relay_reply: branch=0, save=1, relay=-1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:build_local: using FROM=<From: <<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>>;tag=191113598<br>
>, TO=<To: <<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>><br> >, CSEQ_N=<CSeq: 24325> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: status: <100> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:cancel_branch: sending cancel... <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: reason: <Trying> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative timeout is 500000 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe: [4]: 0xb60965e0 (29500000) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative timeout is 5 <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.1>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe: [0]: 0xb60965fc (34) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler: done <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: this is the first via <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: After parse_msg... <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:forward_reply: found module tm, passing reply to it <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: start=0xffffffff <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=22 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: flags=8 <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via found, flags=8 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: parse_headers: this is the second via <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: end of header reached, state=10 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: <To> [30]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>><br>
] <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:reply_received: org. status uas=180, uac[1]=0 local=0 is_invite=1) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_should_relay_response: T_code=180, new_code=100 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:relay_reply: branch=1, save=0, relay=-1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply (status): <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:set_timer: relative timeout is 5 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:insert_timer_unsafe: [1]: 0xb60966a0 (34) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status: <200> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason: <OK> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:destroy_avp_list: destroying list (nil) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: SIP Reply (status): <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: cleaning up <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <CANCEL> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: status: <487> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: reason: <Request Terminated> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this is the first via <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After parse_msg... <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found module tm, passing reply to it <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: start=0xffffffff <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via found, flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=22 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: this is the first via <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: After parse_msg... <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:forward_reply: found module tm, passing reply to it <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_check: start=0xffffffff <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=8 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=22 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: end of header reached, state=10 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=8 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: <To> [30]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>><br>
] <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via found, flags=8 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: parse_headers: this is the second via <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:reply_received: org. status uas=180, uac[0]=408 local=0 is_invite=1) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to_param: tag=86c07149-44ed-de11-9f3b-0017a4d22923 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:reply_received: reply to local CANCEL processed <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of header reached, state=29 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list: destroying list (nil) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: <To> [71]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: SIP Reply (status): <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning up <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>] <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: status: <180> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: reason: <Ringing> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: flags=2 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <INVITE> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:reply_received: org. status uas=180, uac[0]=408 local=0 is_invite=1) <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.1>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: flags=18 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:build_local: using FROM=<From: <<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>>;tag=191113598<br>
>, TO=<To: <<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>;tag=86c07149-44ed-de11-9f3b-0017a4d22923<br> >, CSEQ_N=<CSeq: 24325> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: via found, flags=2 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_should_relay_response: T_code=180, new_code=487 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: this is the first via <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:relay_reply: branch=0, save=0, relay=-1 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:receive_msg: After parse_msg... <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:forward_reply: found module tm, passing reply to it <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:destroy_avp_list: destroying list (nil) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_check: start=0xffffffff <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: cleaning up <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: flags=22 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: flags=8 <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>;
state=16 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: via found, flags=8 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: parse_headers: this is the second via <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to_param: tag=15a2b4dc-2a00-1910-8513-001f2903606f <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to: end of header reached, state=29 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to: display={}, ruri={<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>} <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: <To> [71]; uri=[<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>] <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: to body [<<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>] <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching: reply matched (T=0xb6096418)! <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_check: end=0xb6096418 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:reply_received: org. status uas=180, uac[1]=100 local=0 is_invite=1) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_should_relay_response: T_code=180, new_code=180 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:relay_reply: branch=1, save=0, relay=1 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:run_trans_callbacks: trans=0xb6096418, callback type 16, id 0 entered <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:push_reply_in_dialog: 0xb6096298 totag in rpl is <15a2b4dc-2a00-1910-8513-001f2903606f> (36) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:push_reply_in_dialog: new branch with tag <15a2b4dc-2a00-1910-8513-001f2903606f> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:init_leg_info: route_set , contact , cseq 24325 and bind_addr udp:<a href="http://10.210.54.83:5060/" target="_blank">10.210.54.83:5060</a> <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:dlg_add_leg_info:
set leg 2 for 0xb6096298: tag=<15a2b4dc-2a00-1910-8513-001f2903606f> rcseq=<24325> <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:build_res_buf_from_sip_res: old size: 515, new size: 454 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:build_res_buf_from_sip_res: copied size: orig:102, new: 41, rest: 413 msg= SIP/2.0 180 Ringing<br>
CSeq: 24325 INVITE<br> Via: SIP/2.0/UDP 86.108.132.8:5060;branch=z9hG4bK780409778<br> User-Agent: Ekiga/3.2.6<br> From: <<a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a>>;tag=191113598<br>
Call-ID: <a href="mailto:617010250@86.108.132.8" target="_blank">617010250@86.108.132.8</a><br> To: <<a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a>>;tag=15a2b4dc-2a00-1910-8513-001f2903606f<br>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING<br>
Content-Length: 0<br> Record-Route: <sip:10.210.54.83;lr;ftag=191113598;did=099.11a69622><br> <br> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply (status): <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:run_trans_callbacks: trans=0xb6096418, callback type 128, id 0 entered <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version: <SIP/2.0> <br>Dec
22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:next_state_dlg:
dialog 0xb6096298 changed from state 2 to state 2, due event 2 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status: <481> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:relay_reply: sent buf=0x81c04c0: SIP/2.0 1..., shmem=0xb6098a40: SIP/2.0 1 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason: <Call Leg/Transaction Does Not Exist> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:set_timer: relative timeout is 5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=2 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:insert_timer_unsafe: [1]: 0xb60966a0 (34) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq <CSeq>: <24325> <ACK> <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>;
state=16 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:destroy_avp_list: destroying list (nil) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of header reached, state=5 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:receive_msg: cleaning up <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via found, flags=2 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this is the first via <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After parse_msg... <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found module tm, passing reply to it <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: start=0xffffffff <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: flags=22 <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash 16237 label 2098699271 branch 0 <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: no matching transaction exists <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: failure to match a transaction <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=(nil) <br>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list: destroying list (nil) <br>Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning up <br>Dec
22 10:49:45 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer
routine:4,tl=0xb6096684 next=0xb60965e0, timeout=29500000 <br>
Dec 22 10:49:45 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer routine:4,tl=0xb60965e0 next=(nil), timeout=29500000 <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:0,tl=0xb60965fc next=(nil), timeout=34 <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer routine:1,tl=0xb60966a0 next=(nil), timeout=34 <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb6096418) <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:t_should_relay_response: T_code=180, new_code=408 <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:t_pick_branch: picked branch 1, code 408 (prio=800) <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:is_3263_failure: dns-failover test: branch=1, last_recv=408, flags=2 <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:t_check_status: checked status is <408> <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Request from <a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a> to <a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a> failed. Re-balancing to 8002! <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: found requested (0) resource sip <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: failed to remove from profile <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: no destination found <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int 26 : -2 / 0 <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Insufficient resource to balance request from <a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a> to <a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a> . Re-balancing to route 4! <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: found requested (0) resource sip <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: failed to remove from profile <br>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:load_balancer:do_load_balance: no destination found <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int 26 : -2 / 0 <br>Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Insufficient resource to balance request from <a href="mailto:sip%3A5304556731@86.108.132.8" target="_blank">sip:5304556731@86.108.132.8</a> to <a href="http://sip:8002@10.210.54.83:5060/" target="_blank">sip:8002@10.210.54.83:5060</a> . Sending error!<br>
</div><br>Regards,<br>Taner<br>