[Users] Sending Voicemail to Asterisk

Bill Neely ceo at xantek.cc
Wed May 9 22:54:46 CEST 2007 

I am having a problem forwarding calls to asterisk for voice mail 
handling. What I am trying to do:

When a call times out for no answer, change the address of the call by 
prepending 777 to the extension number. Then forward the call to 
asterisk, where the 777 prefix tells asterisk that it just sends this 
call to voicemail.

Here is my openser.cfg file:

...
modparam("tm", "fr_inv_timer", 20)
...

route[1] {
# # send it out now; use stateful forwarding as it works reliably
# # even for UDP2TCP
t_on_failure("2");


if (!t_relay()) {
sl_reply_error();
};
exit;
}

failure_route[2]
{
if ( t_check_status("408"))
if the call fails for timeout, send me a message and go to route(3)
{
xlog("L_ERR","rrreeeeeeeeeeeeeeeeeecalling froute2 <$rm><$ru>\n");


route(3);


exit;
}
exit;
}

route[3]
{
rewrite the uri to prepend 777
if (subst_uri('/^sip:([0-9]+)@(.*)$/sip:777\1@\2/i'))

{

rewritehostport("66.xxx.20.50:5060"); the asterisk box

append_branch();
xlog("L_ERR","3333333333333333333333333333333333333333after substr 
<$rm><$ru>\n");


if (!t_relay("udp:66.xxx.20.50:5060"))


{
sl_send_reply("500", "Relaying failed");
}

}
exit;



}



What happens is that the call gets forwarded to Asterisk, but asterisk 
does not seem to recognize that the call is destined for 777xxxxxxx, but 
instead tries to send it to xxxxxxx, which causes the call to be 
transferred back to openser. This loop goes around and around until I 
kill it.


Here is portion of log file:


1(7856) rrreeeeeeeeeeeeeeeeeecalling froute2 
<INVITE><sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7>
1(7856) subst_run: running. r=0
1(7856) subst_run: matched (0, 59): 
[sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7]
1(7856) textops: subst_uri_f: match - old uri= 
[sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7], new uri= 
[sip:7771020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7]
1(7856) ******* setting for branch 0 flags 0
1(7856) 3333333333333333333333333333333333333333after substr 
<INVITE><sip:7771020101 at 66.224.20.50:5060;rinstance=1e89b57f830c50f7>
1(7856) check_via_address(67.188.231.188, 67.188.231.188, 0)
1(7856) DBG:check_against_rule_list: using list dns
1(7856) DEBUG:tm:set_timer: relative timeout is 500000
1(7856) DEBUG: add_to_tail_of_timer[4]: 0x801f4b4b0 (49500000)
1(7856) DEBUG:tm:set_timer: relative timeout is 30
1(7856) DEBUG: add_to_tail_of_timer[0]: 0x801f4b4e0 (79)
1(7856) DEBUG:tm:relay_reply: branch=0, save=1, relay=-1
1(7856) DEBUG:tm:build_local: using FROM=<From: 
"Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
 >, TO=<To: "1020101"<sip:1020101 at 67.102.229.3>
 >, CSEQ_N=<CSeq: 1>
1(7856) DEBUG: cancel_branch: sending cancel...
1(7856) DEBUG:tm:set_timer: relative timeout is 500000
1(7856) DEBUG: add_to_tail_of_timer[4]: 0x801f4b3c0 (49500000)
1(7856) DEBUG:tm:set_timer: relative timeout is 30
1(7856) DEBUG: add_to_tail_of_timer[0]: 0x801f4b3f0 (79)
1(7856) DEBUG: final_response_handler : done
0(7855) udp_rcv_loop: probing packet received from 24.5.58.18 53652
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <407>
0(7855) reason: <Proxy Authentication Required>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK5988.480944e.1>; state=6
0(7855) Found param type 234, <received> = <67.102.229.3>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-e004ef19dd229e0e-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <42749>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=22
0(7855) parse_headers: this is the second via
0(7855) DEBUG: add_param: tag=as499a9c72
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [52]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(7855) parse_headers: flags=8
0(7855) DEBUG: t_reply_matching: hash 34965 label 239374468 branch 1
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f4b0d8)!
0(7855) DEBUG: t_check: end=0x801f4b0d8
0(7855) DEBUG:tm:reply_received: org. status uas=180, uac[1]=0 local=0 
is_invite=1)
0(7855) parse_headers: flags=8
0(7855) DEBUG:tm:build_local: using FROM=<From: 
"Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
 >, TO=<To: "1020101"<sip:1020101 at 67.102.229.3>;tag=as499a9c72
 >, CSEQ_N=<CSeq: 1>
0(7855) DEBUG:tm:t_should_relay_response: T_code=180, new_code=407
0(7855) DEBUG:tm:t_pick_branch: picked branch 1, code 407
0(7855) DEBUG:tm:relay_reply: branch=1, save=0, relay=1
0(7855) old size: 631, new size: 549
0(7855) build_res_from_sip_res: copied size: orig:125, new: 43, rest: 
506 msg=
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 
67.188.231.188:42749;branch=z9hG4bK-d87543-e004ef19dd229e0e-1--d87543-;rport=42749 

From: "Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
To: "1020101"<sip:1020101 at 67.102.229.3>;tag=as499a9c72
Call-ID: YjgxM2RlZmM4MjRhMDYxN2YwYjI2MDdmZWZjMGY4NTY.
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:7771020101 at 66.224.20.50>
Proxy-Authenticate: Digest realm="sip.xantek.cc", nonce="1aebadb3"
Content-Length: 0


0(7855) DEBUG:tm:set_timer: relative timeout is 500000
0(7855) DEBUG: add_to_tail_of_timer[4]: 0x801f4b220 (49500000)
0(7855) DEBUG:tm:set_timer: relative timeout is 30
0(7855) DEBUG: add_to_tail_of_timer[0]: 0x801f4b250 (79)
0(7855) DEBUG:tm:relay_reply: sent buf=0x62deb0: SIP/2.0 4..., 
shmem=0x801f4aea0: SIP/2.0 4
0(7855) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <200>
0(7855) reason: <OK>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK5988.480944e.0>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) DEBUG: add_param: tag=03422a48
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <1> <CANCEL>
0(7855) DEBUG: t_reply_matching: hash 34965 label 239374468 branch 0
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f4b0d8)!
0(7855) DEBUG: t_check: end=0x801f4b0d8
0(7855) DEBUG:tm:reply_received: org. status uas=407, uac[0]=408 local=0 
is_invite=1)
0(7855) DEBUG:tm:reply_received: reply to local CANCEL processed
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <487>
0(7855) reason: <Request Terminated>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK5988.480944e.0>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-e004ef19dd229e0e-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <42749>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=22
0(7855) parse_headers: this is the second via
0(7855) DEBUG: add_param: tag=03422a48
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(7855) parse_headers: flags=8
0(7855) DEBUG: t_reply_matching: hash 34965 label 239374468 branch 0
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f4b0d8)!
0(7855) DEBUG: t_check: end=0x801f4b0d8
0(7855) DEBUG:tm:reply_received: org. status uas=407, uac[0]=408 local=0 
is_invite=1)
0(7855) parse_headers: flags=8
0(7855) DEBUG:tm:build_local: using FROM=<From: 
"Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
 >, TO=<To: "1020101"<sip:1020101 at 67.102.229.3>;tag=03422a48
 >, CSEQ_N=<CSeq: 1>
0(7855) DEBUG:tm:t_should_relay_response: T_code=407, new_code=487
0(7855) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Request:
0(7855) method: <ACK>
0(7855) uri: <sip:1020101 at 67.102.229.3>
0(7855) version: <SIP/2.0>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-e004ef19dd229e0e-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <n/a>; state=17
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) preparing to run routing scripts...
0(7855) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(7855) parse_headers: flags=100
0(7855) DEBUG: add_param: tag=as499a9c72
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [52]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <1> <ACK>
0(7855) DEBUG: get_hdr_body : content_length=0
0(7855) found end of header
0(7855) DEBUG: is_maxfwd_present: max_forwards header not found!
0(7855) DEBUG: add_param: tag=045b4172
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"Xantek"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) parse_headers: flags=200
0(7855) find_first_route: No Route headers found
0(7855) loose_route: There is no Route HF
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) lookup(): '1020101' Not found in usrloc
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) rewrite_uri: Rewriting Request-URI with 
'sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7'
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) DEBUG: t_newtran: T on entrance=0xffffffffffffffff
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) parse_headers: flags=78
0(7855) t_lookup_request: start searching: hash=34965, isACK=1
0(7855) DEBUG: RFC3261 transaction matched, 
tid=-d87543-e004ef19dd229e0e-1--d87543-
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_lookup_request: transaction found (T=0x801f4b0d8)
0(7855) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(7855) DEBUG: add_to_tail_of_timer[2]: 0x801f4b158 (54)
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Request:
0(7855) method: <INVITE>
0(7855) uri: <sip:1020101 at 67.102.229.3>
0(7855) version: <SIP/2.0>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <n/a>; state=17
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) preparing to run routing scripts...
0(7855) parse_headers: flags=100
0(7855) DEBUG:maxfwd:is_maxfwd_present: value = 70
0(7855) parse_headers: flags=10
0(7855) DEBUG:parse_to:end of header reached, state=10
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [37]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>
]
0(7855) DEBUG: add_param: tag=045b4172
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"Xantek"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) parse_headers: flags=200
0(7855) get_hdr_field: cseq <CSeq>: <2> <INVITE>
0(7855) DEBUG: get_hdr_body : content_length=476
0(7855) found end of header
0(7855) find_first_route: No Route headers found
0(7855) loose_route: There is no Route HF
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) lookup(): '1020101' Not found in usrloc
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) rewrite_uri: Rewriting Request-URI with 
'sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7'
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) DEBUG: t_newtran: T on entrance=0xffffffffffffffff
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) parse_headers: flags=78
0(7855) t_lookup_request: start searching: hash=34962, isACK=0
0(7855) DEBUG: RFC3261 transaction matching failed
0(7855) DEBUG: t_lookup_request: no transaction found
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) check_via_address(67.188.231.188, 67.188.231.188, 0)
0(7855) WARNING:vqm_resize: resize(0) called
0(7855) DEBUG:tm:_reply_light: reply sent out. buf=0x62dcf8: SIP/2.0 
1..., shmem=0x801f4e420: SIP/2.0 1
0(7855) DEBUG:tm:_reply_light: finished
0(7855) DEBUG: mk_proxy: doing DNS lookup...
0(7855) check_via_address(67.188.231.188, 67.188.231.188, 0)
0(7855) DBG:check_against_rule_list: using list dns
0(7855) DEBUG:tm:set_timer: relative timeout is 500000
0(7855) DEBUG: add_to_tail_of_timer[4]: 0x801f550c8 (49600000)
0(7855) DEBUG:tm:set_timer: relative timeout is 30
0(7855) DEBUG: add_to_tail_of_timer[0]: 0x801f550f8 (79)
0(7855) DEBUG:tm:t_relay_to: new transaction fwd'ed
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
1(7856) DEBUG: timer routine:4,tl=0x801f4b4b0 next=0x801f4b3c0, 
timeout=49500000
1(7856) DEBUG: timer routine:4,tl=0x801f4b3c0 next=0x801f4b220, 
timeout=49500000
1(7856) DEBUG: timer routine:4,tl=0x801f4b220 next=0x0, timeout=49500000
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <180>
0(7855) reason: <Ringing>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK2988.3de53f62.0>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <42749>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=22
0(7855) parse_headers: this is the second via
0(7855) DEBUG: add_param: tag=2a63bc63
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <2> <INVITE>
0(7855) parse_headers: flags=8
0(7855) DEBUG: t_reply_matching: hash 34962 label 653483731 branch 0
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f54ea8)!
0(7855) DEBUG: t_check: end=0x801f54ea8
0(7855) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 
is_invite=1)
0(7855) DEBUG:tm:t_should_relay_response: T_code=100, new_code=180
0(7855) DEBUG:tm:relay_reply: branch=0, save=0, relay=0
0(7855) old size: 554, new size: 493
0(7855) build_res_from_sip_res: copied size: orig:82, new: 21, rest: 472 
msg=
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 
67.188.231.188:42749;branch=z9hG4bK-d87543-c535a22e8d568d14-1--d87543-;rport=42749 

Record-Route: <sip:67.102.229.3;lr;ftag=045b4172>
Contact: <sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7>
To: "1020101"<sip:1020101 at 67.102.229.3>;tag=2a63bc63
From: "Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
Call-ID: YjgxM2RlZmM4MjRhMDYxN2YwYjI2MDdmZWZjMGY4NTY.
CSeq: 2 INVITE
User-Agent: eyeBeam release 1009l stamp 37966
Content-Length: 0


0(7855) DEBUG:tm:relay_reply: sent buf=0x62d678: SIP/2.0 1..., 
shmem=0x801f4e420: SIP/2.0 1
0(7855) DEBUG:tm:set_timer: relative timeout is 20
0(7855) DEBUG: add_to_tail_of_timer[1]: 0x801f550f8 (69)
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
1(7856) DEBUG: timer routine:4,tl=0x801f550c8 next=0x0, timeout=49600000
0(7855) SIP Request:
0(7855) method: <CANCEL>
0(7855) uri: <sip:1020101 at 67.102.229.3>
0(7855) version: <SIP/2.0>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <n/a>; state=17
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) preparing to run routing scripts...
0(7855) parse_headers: flags=100
0(7855) DEBUG:parse_to:end of header reached, state=10
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [37]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>
]
0(7855) get_hdr_field: cseq <CSeq>: <2> <CANCEL>
0(7855) DEBUG: get_hdr_body : content_length=0
0(7855) found end of header
0(7855) DEBUG: is_maxfwd_present: max_forwards header not found!
0(7855) DEBUG: add_param: tag=045b4172
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"Xantek"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) parse_headers: flags=200
0(7855) find_first_route: No Route headers found
0(7855) loose_route: There is no Route HF
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) lookup(): '1020101' Not found in usrloc
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) rewrite_uri: Rewriting Request-URI with 
'sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7'
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) DEBUG: t_newtran: T on entrance=0xffffffffffffffff
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) parse_headers: flags=78
0(7855) t_lookup_request: start searching: hash=34962, isACK=0
0(7855) DEBUG: RFC3261 transaction matching failed
0(7855) DEBUG: t_lookup_request: no transaction found
0(7855) DEBUG: t_lookupOriginalT: searching on hash entry 34962
0(7855) DEBUG: RFC3261 transaction matched, 
tid=-d87543-c535a22e8d568d14-1--d87543-
0(7855) DEBUG: t_lookupOriginalT: canceled transaction found (0x801f54ea8)!
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_lookupOriginalT completed
0(7855) check_via_address(67.188.231.188, 67.188.231.188, 0)
0(7855) DEBUG:tm:set_timer: relative timeout is 500000
0(7855) DEBUG: add_to_tail_of_timer[4]: 0x801f583f8 (50600000)
0(7855) DEBUG:tm:set_timer: relative timeout is 30
0(7855) DEBUG: add_to_tail_of_timer[0]: 0x801f58428 (80)
0(7855) DEBUG: e2e_cancel: e2e cancel proceeding
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) check_via_address(67.188.231.188, 67.188.231.188, 0)
0(7855) WARNING:vqm_resize: resize(0) called
0(7855) DEBUG:tm:_reply_light: reply sent out. buf=0x62dcf8: SIP/2.0 
2..., shmem=0x801f57da0: SIP/2.0 2
0(7855) DEBUG:tm:_reply_light: finished
0(7855) DEBUG:tm:t_relay_to: new transaction fwd'ed
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <200>
0(7855) reason: <OK>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK2988.3de53f62.0>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <42749>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=22
0(7855) parse_headers: this is the second via
0(7855) DEBUG: add_param: tag=2a63bc63
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <2> <CANCEL>
0(7855) DEBUG: t_reply_matching: hash 34962 label 653483731 branch 0
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f581d8)!
0(7855) DEBUG: t_check: end=0x801f581d8
0(7855) DEBUG:tm:reply_received: org. status uas=200, uac[0]=0 local=0 
is_invite=0)
0(7855) DEBUG:tm:t_should_relay_response: T_code=200, new_code=200
0(7855) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
0(7855) DEBUG: add_to_tail_of_timer[2]: 0x801f58258 (55)
0(7855) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Reply (status):
0(7855) version: <SIP/2.0>
0(7855) status: <487>
0(7855) reason: <Request Terminated>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = <z9hG4bK2988.3de53f62.0>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) DEBUG:forward_reply: found module tm, passing reply to it
0(7855) DEBUG: t_check: start=0xffffffffffffffff
0(7855) parse_headers: flags=22
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <42749>; state=16
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=22
0(7855) parse_headers: this is the second via
0(7855) DEBUG: add_param: tag=2a63bc63
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <2> <INVITE>
0(7855) parse_headers: flags=8
0(7855) DEBUG: t_reply_matching: hash 34962 label 653483731 branch 0
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_reply_matching: reply matched (T=0x801f54ea8)!
0(7855) DEBUG: t_check: end=0x801f54ea8
0(7855) DEBUG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 
is_invite=1)
0(7855) parse_headers: flags=8
0(7855) DEBUG:tm:build_local: using FROM=<From: 
"Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
 >, TO=<To: "1020101"<sip:1020101 at 67.102.229.3>;tag=2a63bc63
 >, CSEQ_N=<CSeq: 2>
0(7855) DEBUG:tm:t_should_relay_response: T_code=180, new_code=487
0(7855) DEBUG:tm:t_pick_branch: picked branch 0, code 487
0(7855) DEBUG:t_check_status: checked status is <487>
0(7855) DEBUG:tm:relay_reply: branch=0, save=0, relay=0
0(7855) old size: 442, new size: 381
0(7855) build_res_from_sip_res: copied size: orig:93, new: 32, rest: 349 
msg=
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 
67.188.231.188:42749;branch=z9hG4bK-d87543-c535a22e8d568d14-1--d87543-;rport=42749 

To: "1020101"<sip:1020101 at 67.102.229.3>;tag=2a63bc63
From: "Xantek"<sip:1020101 at 67.102.229.3>;tag=045b4172
Call-ID: YjgxM2RlZmM4MjRhMDYxN2YwYjI2MDdmZWZjMGY4NTY.
CSeq: 2 INVITE
User-Agent: eyeBeam release 1009l stamp 37966
Content-Length: 0


0(7855) DEBUG:tm:set_timer: relative timeout is 500000
0(7855) DEBUG: add_to_tail_of_timer[4]: 0x801f54ff0 (50700000)
0(7855) DEBUG:tm:set_timer: relative timeout is 30
0(7855) DEBUG: add_to_tail_of_timer[0]: 0x801f55020 (80)
0(7855) DEBUG:tm:relay_reply: sent buf=0x62dcf8: SIP/2.0 4..., 
shmem=0x801f546f8: SIP/2.0 4
0(7855) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
0(7855) SIP Request:
0(7855) method: <ACK>
0(7855) uri: <sip:1020101 at 67.102.229.3>
0(7855) version: <SIP/2.0>
0(7855) parse_headers: flags=2
0(7855) Found param type 232, <branch> = 
<z9hG4bK-d87543-c535a22e8d568d14-1--d87543->; state=6
0(7855) Found param type 235, <rport> = <n/a>; state=17
0(7855) end of header reached, state=5
0(7855) parse_headers: Via found, flags=2
0(7855) parse_headers: this is the first via
0(7855) After parse_msg...
0(7855) preparing to run routing scripts...
0(7855) DEBUG : sl_filter_ACK: to late to be a local ACK!
0(7855) parse_headers: flags=100
0(7855) DEBUG: add_param: tag=2a63bc63
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"1020101"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) DEBUG: get_hdr_field: <To> [50]; uri=[sip:1020101 at 67.102.229.3]
0(7855) DEBUG: to body ["1020101"<sip:1020101 at 67.102.229.3>]
0(7855) get_hdr_field: cseq <CSeq>: <2> <ACK>
0(7855) DEBUG: get_hdr_body : content_length=0
0(7855) found end of header
0(7855) DEBUG: is_maxfwd_present: max_forwards header not found!
0(7855) DEBUG: add_param: tag=045b4172
0(7855) DEBUG:parse_to:end of header reached, state=29
0(7855) DBUG:parse_to: display={"Xantek"}, ruri={sip:1020101 at 67.102.229.3}
0(7855) parse_headers: flags=200
0(7855) find_first_route: No Route headers found
0(7855) loose_route: There is no Route HF
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) lookup(): '1020101' Not found in usrloc
0(7855) grep_sock_info - checking if host==us: 12==12 && [67.102.229.3] 
== [67.102.229.3]
0(7855) grep_sock_info - checking if port 5060 matches port 5060
0(7855) rewrite_uri: Rewriting Request-URI with 
'sip:1020101 at 67.188.231.188:42749;rinstance=1e89b57f830c50f7'
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) DEBUG: t_newtran: T on entrance=0xffffffffffffffff
0(7855) parse_headers: flags=ffffffffffffffff
0(7855) parse_headers: flags=78
0(7855) t_lookup_request: start searching: hash=34962, isACK=1
0(7855) DEBUG: RFC3261 transaction matched, 
tid=-d87543-c535a22e8d568d14-1--d87543-
0(7855) DEBUG:tm:REF_UNSAFE: after is 1
0(7855) DEBUG: t_lookup_request: transaction found (T=0x801f54ea8)
0(7855) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(7855) DEBUG: add_to_tail_of_timer[2]: 0x801f54f28 (55)
0(7855) DEBUG:tm:UNREF_UNSAFE: after is 0
0(7855) DEBUG:destroy_avp_list: destroying list 0x0
0(7855) receive_msg: cleaning up
1(7856) DEBUG: timer routine:4,tl=0x801f583f8 next=0x0, timeout=50600000
1(7856) DEBUG: timer routine:4,tl=0x801f54ff0 next=0x0, timeout=50700000
^C 0(7855) INT received, program terminates
0(7855) INFO: signal 2 received
0(7855) Memory status (pkg):
0(7855) fm_status (0x615be0):
0(7855) heap size= 1048576
0(7855) used= 56472, used+overhead=95544, free=953032
0(7855) max used (+overhead)= 95544


Anybody see what I an doing wrong?

-- 
Bill Neely
Xantek, Inc.
1-866-553-3833
1-702-874-3833

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.kamailio.org/pipermail/users/attachments/20070509/579ce9c5/attachment.htm

More information about the Users mailing list