[OpenSIPS-Users] Load balancer ORed resource types
Taner Sener
tanersener at gmail.com
Tue Dec 22 18:00:22 CET 2009
Hi Bogdan,
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.
* 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".
* 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".
* 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.
----------------
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: SIP
Request:
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: method:
<INVITE>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: uri:
<sip:8002 at 10.210.54.83:5060>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg:
preparing to run routing scripts...
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=100
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of
header reached, state=10
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>
]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:maxfwd:is_maxfwd_present:
value = 70
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:uri:has_totag: no totag
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=78
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: start
searching: hash=16237, isACK=0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: no
transaction found
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=200
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field:
content_length=658
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: found
end of header
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:find_first_route: No
Route headers found
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:loose_route: There is
no Route HF
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to_param:
tag=191113598
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of
header reached, state=29
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={},
ruri={sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8>}
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:load_balancer:do_load_
balance: found requested (0) resource sip
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:build_new_dlg: new
dialog 0xb6096298
(c=617010250 at 86.108.132.8,f=sip:5304556731 at 86.108.132.8<sip%3A5304556731 at 86.108.132.8>
,t=sip:8002 at 10.210.54.83:5060,ft=191113598) on hash 2448
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=ffffffffffffffff
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:init_leg_info:
route_set , contact sip:5304556731 at 86.108.132.8<sip%3A5304556731 at 86.108.132.8>,
cseq 24325 and bind_addr udp:10.210.54.83:5060
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:dlg_add_leg_info:
set leg 0 for 0xb6096298: tag=<191113598> rcseq=<24325>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:link_dlg: ref dlg
0xb6096298 with 3 -> 3
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:rr:add_rr_param: adding
(;did=099.11a69622) 0x81c0738
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]:
DBG:load_balancer:do_load_balance: destination
<sip:ar at 10.10.5.44<sip%3Aar at 10.10.5.44>>
selected for LB set with free=1 (max=1)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]:
DBG:load_balancer:do_load_balance: destination
<sip:ar at 10.10.6.50<sip%3Aar at 10.10.6.50>>
selected for LB set with free=1 (max=1)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:link_dlg_profile:
Entered here with hash = 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:comp_scriptvar: int
26 : 1 / 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_newtran: transaction
on entrance=(nil)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=ffffffffffffffff
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=78
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: start
searching: hash=16237, isACK=0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_lookup_request: no
transaction found
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:run_reqin_callbacks:
trans=0xb6096418, callback type 1, id 1 entered
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:get_dlg_timeout:
invalid AVP value, use default timeout
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:run_reqin_callbacks:
trans=0xb6096418, callback type 1, id 0 entered
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=ffffffffffffffff
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:check_ip_address:
params 86.108.132.8, 86.108.132.8, 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:_shm_resize:
resize(0) called
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
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:_reply_light: finished
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:_shm_resize:
resize(0) called
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:mk_proxy: doing DNS
lookup...
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:check_ip_address:
params 86.108.132.8, 86.108.132.8, 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:set_timer: relative
timeout is 500000
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:insert_timer_unsafe:
[4]: 0xb6096564 (24900000)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:insert_timer_unsafe:
[0]: 0xb6096580 (29)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_relay_to: new
transaction fwd'ed
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:dialog:unref_dlg: unref
dlg 0xb6096298 with 1 -> 2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: status:
<100>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: reason:
<Trying>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>; state=16
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via
found, flags=8
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
parse_headers: this is the second via
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: end of
header reached, state=10
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>
]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: end=0xb6096418
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)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]:
DBG:tm:t_should_relay_response: T_code=100, new_code=100
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:relay_reply: branch=0,
save=0, relay=-1
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:insert_timer_unsafe:
[1]: 0xb6096580 (29)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status:
<180>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason:
<Ringing>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>; state=16
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via
found, flags=8
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
parse_headers: this is the second via
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to_param:
tag=86c07149-44ed-de11-9f3b-0017a4d22923
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: end of
header reached, state=29
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: <To>
[71]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>]
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=0xb6096418
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)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]:
DBG:tm:t_should_relay_response: T_code=100, new_code=180
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:relay_reply: branch=0,
save=0, relay=0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:run_trans_callbacks:
trans=0xb6096418, callback type 16, id 0 entered
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)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]:
DBG:dialog:push_reply_in_dialog: new branch with tag
<86c07149-44ed-de11-9f3b-0017a4d22923>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:dialog:init_leg_info:
route_set , contact , cseq 24325 and bind_addr udp:10.210.54.83:5060
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>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]:
DBG:core:build_res_buf_from_sip_res: old size: 515, new size: 454
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
CSeq: 24325 INVITE
Via: SIP/2.0/UDP 86.108.132.8:5060;branch=z9hG4bK780409778
User-Agent: Ekiga/3.2.0
From: <sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8>
>;tag=191113598
Call-ID: 617010250 at 86.108.132.8
To: <sip:8002 at 10.210.54.83:5060>;tag=86c07149-44ed-de11-9f3b-0017a4d22923
Allow:
INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING
Content-Length: 0
Record-Route: <sip:10.210.54.83;lr;ftag=191113598;did=099.11a69622>
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:run_trans_callbacks:
trans=0xb6096418, callback type 128, id 0 entered
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
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
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:insert_timer_unsafe:
[1]: 0xb6096580 (29)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:40 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer
routine:4,tl=0xb6096564 next=(nil), timeout=24900000
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:0,tl=0xb6093320 next=0xb6094368, timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:0,tl=0xb6094368 next=0xb60953b8, timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:0,tl=0xb60953b8 next=(nil), timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:2,tl=0xb6094248 next=0xb6093200, timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing
0xb6094200 from table
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete
transaction 0xb6094200
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:2,tl=0xb6093200 next=0xb6095298, timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing
0xb60931b8 from table
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete
transaction 0xb60931b8
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:2,tl=0xb6095298 next=(nil), timeout=25
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: removing
0xb6095250 from table
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:delete_cell: delete
transaction 0xb6095250
Dec 22 10:49:40 arsipt1 /sbin/opensips[9146]: DBG:tm:wait_handler: done
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:1,tl=0xb6096580 next=(nil), timeout=29
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler:
stop retr. and send CANCEL (0xb6096418)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]:
DBG:tm:t_should_relay_response: T_code=180, new_code=408
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:t_pick_branch: picked
branch 0, code 408 (prio=800)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:is_3263_failure:
dns-failover test: branch=0, last_recv=408, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:t_check_status: checked
status is <408>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: load_balancer: Request from
sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8> to
sip:8002 at 10.210.54.83:5060 failed. Re-balancing to 8002!
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: found requested (0) resource sip
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: destination
<sip:ar at 10.10.6.50<sip%3Aar at 10.10.6.50>>
selected for LB set with free=1 (max=1)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: failed to remove from profile
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:dialog:link_dlg_profile:
Entered here with hash = 9
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int
26 : 1 / 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:_shm_resize:
resize(0) called
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:mk_proxy: doing DNS
lookup...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:core:check_ip_address:
params 86.108.132.8, 86.108.132.8, 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative
timeout is 500000
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe:
[4]: 0xb6096684 (29500000)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe:
[0]: 0xb60966a0 (34)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:relay_reply: branch=0,
save=1, relay=-1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:build_local: using
FROM=<From: <sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8>
>;tag=191113598
>, TO=<To: <sip:8002 at 10.210.54.83:5060>
>, CSEQ_N=<CSeq: 24325>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: status:
<100>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:cancel_branch: sending
cancel...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_msg: reason:
<Trying>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative
timeout is 500000
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe:
[4]: 0xb60965e0 (29500000)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.1>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:insert_timer_unsafe:
[0]: 0xb60965fc (34)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler:
done
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers: via
found, flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_headers:
parse_headers: this is the second via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: end of
header reached, state=10
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>
]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_check: end=0xb6096418
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)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]:
DBG:tm:t_should_relay_response: T_code=180, new_code=100
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:relay_reply: branch=1,
save=0, relay=-1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:insert_timer_unsafe:
[1]: 0xb60966a0 (34)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status:
<200>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason:
<OK>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:44 arsipt1 /sbin/opensips[9137]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <CANCEL>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: status:
<487>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_msg: reason:
<Request Terminated>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: end of
header reached, state=10
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: <To>
[30]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>
]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers: via
found, flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=0xb6096418
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
parse_headers: this is the second via
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)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to_param:
tag=86c07149-44ed-de11-9f3b-0017a4d22923
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:reply_received: reply
to local CANCEL processed
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: end of
header reached, state=29
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: <To>
[71]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: version:
<SIP/2.0>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: status:
<180>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_msg: reason:
<Ringing>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_check: end=0xb6096418
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <INVITE>
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)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.1>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:parse_headers:
flags=18
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:build_local: using
FROM=<From: <sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8>
>;tag=191113598
>, TO=<To: <sip:8002 at 10.210.54.83:5060
>;tag=86c07149-44ed-de11-9f3b-0017a4d22923
>, CSEQ_N=<CSeq: 24325>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]:
DBG:tm:t_should_relay_response: T_code=180, new_code=487
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:relay_reply: branch=0,
save=0, relay=-1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:44 arsipt1 /sbin/opensips[9141]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers:
flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bK780409778>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers: via
found, flags=8
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_headers:
parse_headers: this is the second via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to_param:
tag=15a2b4dc-2a00-1910-8513-001f2903606f
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to: end of
header reached, state=29
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:parse_to: display={},
ruri={sip:8002 at 10.210.54.83:5060}
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: <To>
[71]; uri=[sip:8002 at 10.210.54.83:5060]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:get_hdr_field: to
body [<sip:8002 at 10.210.54.83:5060>]
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching:
REF_UNSAFE: after is 1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_reply_matching: reply
matched (T=0xb6096418)!
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_check: end=0xb6096418
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)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]:
DBG:tm:t_should_relay_response: T_code=180, new_code=180
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:relay_reply: branch=1,
save=0, relay=1
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:run_trans_callbacks:
trans=0xb6096418, callback type 16, id 0 entered
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)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]:
DBG:dialog:push_reply_in_dialog: new branch with tag
<15a2b4dc-2a00-1910-8513-001f2903606f>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:dialog:init_leg_info:
route_set , contact , cseq 24325 and bind_addr udp:10.210.54.83:5060
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>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]:
DBG:core:build_res_buf_from_sip_res: old size: 515, new size: 454
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
CSeq: 24325 INVITE
Via: SIP/2.0/UDP 86.108.132.8:5060;branch=z9hG4bK780409778
User-Agent: Ekiga/3.2.6
From: <sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8>
>;tag=191113598
Call-ID: 617010250 at 86.108.132.8
To: <sip:8002 at 10.210.54.83:5060>;tag=15a2b4dc-2a00-1910-8513-001f2903606f
Allow:
INVITE,ACK,OPTIONS,BYE,CANCEL,SUBSCRIBE,NOTIFY,REFER,MESSAGE,INFO,PING
Content-Length: 0
Record-Route: <sip:10.210.54.83;lr;ftag=191113598;did=099.11a69622>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: SIP Reply
(status):
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:run_trans_callbacks:
trans=0xb6096418, callback type 128, id 0 entered
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: version:
<SIP/2.0>
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
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: status:
<481>
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
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_msg: reason:
<Call Leg/Transaction Does Not Exist>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:set_timer: relative
timeout is 5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:insert_timer_unsafe:
[1]: 0xb60966a0 (34)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:get_hdr_field: cseq
<CSeq>: <24325> <ACK>
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:tm:t_unref: UNREF_UNSAFE:
after is 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via_param:
found param type 232, <branch> = <z9hG4bKd6f3.70c971d7.0>; state=16
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_via: end of
header reached, state=5
Dec 22 10:49:44 arsipt1 /sbin/opensips[9139]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: via
found, flags=2
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers: this
is the first via
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: After
parse_msg...
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:forward_reply: found
module tm, passing reply to it
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check:
start=0xffffffff
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:parse_headers:
flags=22
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: hash
16237 label 2098699271 branch 0
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching: no
matching transaction exists
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_reply_matching:
failure to match a transaction
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:tm:t_check: end=(nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:destroy_avp_list:
destroying list (nil)
Dec 22 10:49:44 arsipt1 /sbin/opensips[9143]: DBG:core:receive_msg: cleaning
up
Dec 22 10:49:45 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer
routine:4,tl=0xb6096684 next=0xb60965e0, timeout=29500000
Dec 22 10:49:45 arsipt1 /sbin/opensips[9146]: DBG:tm:utimer_routine: timer
routine:4,tl=0xb60965e0 next=(nil), timeout=29500000
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:0,tl=0xb60965fc next=(nil), timeout=34
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:timer_routine: timer
routine:1,tl=0xb60966a0 next=(nil), timeout=34
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:final_response_handler:
stop retr. and send CANCEL (0xb6096418)
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:tm:t_should_relay_response: T_code=180, new_code=408
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:t_pick_branch: picked
branch 1, code 408 (prio=800)
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:is_3263_failure:
dns-failover test: branch=1, last_recv=408, flags=2
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:tm:t_check_status: checked
status is <408>
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Request from
sip:5304556731 at 86.108.132.8 <sip%3A5304556731 at 86.108.132.8> to
sip:8002 at 10.210.54.83:5060 failed. Re-balancing to 8002!
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: found requested (0) resource sip
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: failed to remove from profile
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: no destination found
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int
26 : -2 / 0
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Insufficient
resource to balance request from
sip:5304556731 at 86.108.132.8<sip%3A5304556731 at 86.108.132.8>to
sip:8002 at 10.210.54.83:5060 . Re-balancing to route 4!
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: found requested (0) resource sip
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: failed to remove from profile
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]:
DBG:load_balancer:do_load_balance: no destination found
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: DBG:core:comp_scriptvar: int
26 : -2 / 0
Dec 22 10:49:49 arsipt1 /sbin/opensips[9146]: load_balancer: Insufficient
resource to balance request from
sip:5304556731 at 86.108.132.8<sip%3A5304556731 at 86.108.132.8>to
sip:8002 at 10.210.54.83:5060 . Sending error!
Regards,
Taner
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.opensips.org/pipermail/users/attachments/20091222/957042f1/attachment-0001.htm
More information about the Users
mailing list