24 Jun
2007
24 Jun
'07
7:37 p.m.
Hi,
I've been trying to setup a openser + asterisk server following the
tutorial here:
http://www.voip-info.org/wiki/view/Realtime+Integration+Of+Asterisk+With+Op…
and with that openser configuration example.
The only difference in my setup is that I am using openser 1.1.
For some reason it doesn't seem to be working, the call is not established.
This is the debugging output:
/usr/sbin/openser[26006]: SIP Request:
/usr/sbin/openser[26006]: method: <INVITE>
/usr/sbin/openser[26006]: uri: <sip:101@217.73.174.13>
/usr/sbin/openser[26006]: version: <SIP/2.0>
/usr/sbin/openser[26006]: parse_headers: flags=2
/usr/sbin/openser[26006]: Found param type 235, <rport> = <n/a>; state=6
/usr/sbin/openser[26006]: Found param type 232, <branch> =
<z9hG4bKapseucta>; state=16
/usr/sbin/openser[26006]: end of header reached, state=5
/usr/sbin/openser[26006]: parse_headers: Via found, flags=2
/usr/sbin/openser[26006]: parse_headers: this is the first via
/usr/sbin/openser[26006]: After parse_msg...
/usr/sbin/openser[26006]: preparing to run routing scripts...
/usr/sbin/openser[26006]: parse_headers: flags=100
/usr/sbin/openser[26006]: DEBUG:maxfwd:is_maxfwd_present: value = 70
/usr/sbin/openser[26006]: parse_headers: flags=10
/usr/sbin/openser[26006]: DEBUG:parse_to:end of header reached, state=10
/usr/sbin/openser[26006]: DBUG:parse_to: display={},
ruri={sip:101@217.73.174.13}
/usr/sbin/openser[26006]: DEBUG: get_hdr_field: <To> [25];
uri=[sip:101@217.73.174.13]
/usr/sbin/openser[26006]: DEBUG: to body [<sip:101@217.73.174.13>^M ]
/usr/sbin/openser[26006]: DEBUG: add_param: tag=hsiim
/usr/sbin/openser[26006]: DEBUG:parse_to:end of header reached, state=29
/usr/sbin/openser[26006]: DBUG:parse_to: display={"Radu Spineanu"},
ruri={sip:100@217.73.174.13}
/usr/sbin/openser[26006]: parse_headers: flags=200
/usr/sbin/openser[26006]: get_hdr_field: cseq <CSeq>: <797> <INVITE>
/usr/sbin/openser[26006]: DEBUG: get_hdr_body : content_length=303
/usr/sbin/openser[26006]: found end of header
/usr/sbin/openser[26006]: find_first_route: No Route headers found
/usr/sbin/openser[26006]: loose_route: There is no Route HF
/usr/sbin/openser[26006]: grep_sock_info - checking if host==us:
13==13 && [217.73.174.13] == [217.73.174.13]
/usr/sbin/openser[26006]: grep_sock_info - checking if port 5060
matches port 5060
/usr/sbin/openser[26006]: grep_sock_info - checking if host==us:
13==13 && [217.73.174.13] == [217.73.174.13]
/usr/sbin/openser[26006]: grep_sock_info - checking if port 5060
matches port 5060
/usr/sbin/openser[26006]: DEBUG: has_totag: no totag
/usr/sbin/openser[26006]: DEBUG: has_totag: no totag
/usr/sbin/openser[26006]: is_user_in(): User is not in group 'voicemail'
/usr/sbin/openser[26006]: rewrite_uri: Rewriting Request-URI with
'sip:101@82.79.243.82:5068'
/usr/sbin/openser[26006]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26006]: DEBUG: t_newtran: msg id=2 , global msg id=0
, T on entrance=0xffffffffffffffff
/usr/sbin/openser[26006]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26006]: parse_headers: flags=78
/usr/sbin/openser[26006]: t_lookup_request: start searching:
hash=18702, isACK=0
/usr/sbin/openser[26006]: DEBUG: RFC3261 transaction matching failed
/usr/sbin/openser[26006]: DEBUG: t_lookup_request: no transaction found
/usr/sbin/openser[26006]: DEBUG:tm:t_relay: new INVITE
/usr/sbin/openser[26006]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26006]: check_via_address(217.73.174.16,
82.79.243.82, 0)
/usr/sbin/openser[26006]: WARNING:vqm_resize: resize(0) called
/usr/sbin/openser[26006]: DEBUG:tm:_reply_light: reply sent out.
buf=0x5e6458: SIP/2.0 1..., shmem=0x2b05574b9fb8: SIP/2.0 1
/usr/sbin/openser[26006]: DEBUG:tm:_reply_light: finished
/usr/sbin/openser[26006]: DEBUG: mk_proxy: doing DNS lookup...
/usr/sbin/openser[26006]: check_via_address(217.73.174.16,
82.79.243.82, 0)
/usr/sbin/openser[26006]: DEBUG: add_to_tail_of_timer[4]: 0x2b05574b7ba0
/usr/sbin/openser[26006]: DEBUG: add_to_tail_of_timer[0]: 0x2b05574b7bc0
/usr/sbin/openser[26006]: SER: new transaction fwd'ed
/usr/sbin/openser[26006]: DEBUG:tm:UNREF_UNSAFE: after is 0
/usr/sbin/openser[26006]: DEBUG:destroy_avp_list: destroying list (nil)
/usr/sbin/openser[26006]: receive_msg: cleaning up
/usr/sbin/openser[26012]: DEBUG: timer routine:4,tl=0x2b05574b7ba0
next=(nil)
/usr/sbin/openser[26012]: DEBUG: retransmission_handler : request
resending (t=0x2b05574b79c0, INVITE si ... )
/usr/sbin/openser[26012]: DEBUG: add_to_tail_of_timer[5]: 0x2b05574b7ba0
/usr/sbin/openser[26012]: DEBUG: retransmission_handler : done
amy /usr/sbin/openser[26012]: DEBUG: timer routine:5,tl=0x2b05574b7ba0
next=(nil)
amy /usr/sbin/openser[26012]: DEBUG: retransmission_handler : request
resending (t=0x2b05574b79c0, INVITE si ... )
amy /usr/sbin/openser[26012]: DEBUG: add_to_tail_of_timer[6]: 0x2b05574b7ba0
amy /usr/sbin/openser[26012]: DEBUG: retransmission_handler : done
[..]
Jun 24 15:38:47 amy /usr/sbin/openser[26012]: DEBUG: timer
routine:0,tl=0x2b05574b7bc0 next=(nil)
/usr/sbin/openser[26012]: DEBUG: final_response_handler:stop retr. and
send CANCEL (0x2b05574b79c0)
/usr/sbin/openser[26012]: DEBUG:tm:t_should_relay_response:
T_code=100, new_code=408
/usr/sbin/openser[26012]: DEBUG:tm:t_pick_branch: picked branch 0,
code 408
/usr/sbin/openser[26012]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
/usr/sbin/openser[26012]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26012]: check_via_address(217.73.174.16,
82.79.243.82, 0)
/usr/sbin/openser[26012]: DEBUG: add_to_tail_of_timer[4]: 0x2b05574b7ae8
/usr/sbin/openser[26012]: DEBUG: add_to_tail_of_timer[0]: 0x2b05574b7b08
/usr/sbin/openser[26012]: DEBUG:tm:relay_reply: sent buf=0x5e4fb0:
SIP/2.0 4..., shmem=0x2b05574b9fb8: SIP/2.0 4
/usr/sbin/openser[26012]: DEBUG: final_response_handler : done
/usr/sbin/openser[26012]: DEBUG: timer routine:7,tl=0x2b05574b7ba0
next=(nil)
/usr/sbin/openser[26006]: SIP Request:
/usr/sbin/openser[26006]: method: <ACK>
/usr/sbin/openser[26006]: uri: <sip:101@217.73.174.13>
/usr/sbin/openser[26006]: version: <SIP/2.0>
/usr/sbin/openser[26006]: parse_headers: flags=2
/usr/sbin/openser[26006]: Found param type 235, <rport> = <n/a>; state=6
/usr/sbin/openser[26006]: Found param type 232, <branch> =
<z9hG4bKapseucta>; state=16
/usr/sbin/openser[26006]: end of header reached, state=5
/usr/sbin/openser[26006]: parse_headers: Via found, flags=2
/usr/sbin/openser[26006]: parse_headers: this is the first via
/usr/sbin/openser[26006]: After parse_msg...
/usr/sbin/openser[26006]: preparing to run routing scripts...
/usr/sbin/openser[26006]: DEBUG : sl_filter_ACK: to late to be a local
ACK!
/usr/sbin/openser[26006]: parse_headers: flags=100
/usr/sbin/openser[26006]: DEBUG:maxfwd:is_maxfwd_present: value = 70
/usr/sbin/openser[26006]: parse_headers: flags=10
/usr/sbin/openser[26006]: DEBUG: add_param:
tag=90f6b651c515331ae78169ff327ec50d-6648
/usr/sbin/openser[26006]: DEBUG:parse_to:end of header reached, state=29
/usr/sbin/openser[26006]: DBUG:parse_to: display={},
ruri={sip:101@217.73.174.13}
/usr/sbin/openser[26006]: DEBUG: get_hdr_field: <To> [67];
uri=[sip:101@217.73.174.13]
/usr/sbin/openser[26006]: DEBUG: to body [<sip:101@217.73.174.13>]
/usr/sbin/openser[26006]: DEBUG: add_param: tag=hsiim
/usr/sbin/openser[26006]: DEBUG:parse_to:end of header reached, state=29
/usr/sbin/openser[26006]: DBUG:parse_to: display={"Radu Spineanu"},
ruri={sip:100@217.73.174.13}
/usr/sbin/openser[26006]: parse_headers: flags=200
/usr/sbin/openser[26006]: get_hdr_field: cseq <CSeq>: <797> <ACK>
/usr/sbin/openser[26006]: DEBUG: get_hdr_body : content_length=0
/usr/sbin/openser[26006]: found end of header
/usr/sbin/openser[26006]: find_first_route: No Route headers found
/usr/sbin/openser[26006]: loose_route: There is no Route HF
/usr/sbin/openser[26006]: grep_sock_info - checking if host==us:
13==13 && [217.73.174.13] == [217.73.174.13]
/usr/sbin/openser[26006]: grep_sock_info - checking if port 5060
matches port 5060
/usr/sbin/openser[26006]: grep_sock_info - checking if host==us:
13==13 && [217.73.174.13] == [217.73.174.13]
/usr/sbin/openser[26006]: grep_sock_info - checking if port 5060
matches port 5060
/usr/sbin/openser[26006]: rewrite_uri: Rewriting Request-URI with
'sip:101@82.79.243.82:5068'
/usr/sbin/openser[26006]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26006]: DEBUG: t_newtran: msg id=3 , global msg id=2
, T on entrance=0xffffffffffffffff
/usr/sbin/openser[26006]: parse_headers: flags=ffffffffffffffff
/usr/sbin/openser[26006]: parse_headers: flags=78
/usr/sbin/openser[26006]: t_lookup_request: start searching:
hash=18702, isACK=1
/usr/sbin/openser[26006]: DEBUG: RFC3261 transaction matched, tid=apseucta
/usr/sbin/openser[26006]: DEBUG:tm:REF_UNSAFE: after is 1
/usr/sbin/openser[26006]: DEBUG: t_lookup_request: transaction found
(T=0x2b05574b79c0)
/usr/sbin/openser[26006]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
/usr/sbin/openser[26006]: DEBUG: add_to_tail_of_timer[2]: 0x2b05574b7a40
/usr/sbin/openser[26006]: DEBUG:tm:UNREF_UNSAFE: after is 0
/usr/sbin/openser[26006]: DEBUG:destroy_avp_list: destroying list (nil)
/usr/sbin/openser[26006]: receive_msg: cleaning up
/usr/sbin/openser[26012]: DEBUG: timer routine:0,tl=0x2b05574b7b08
next=(nil)
/usr/sbin/openser[26012]: DEBUG: timer routine:4,tl=0x2b05574b7ae8
next=(nil)
/usr/sbin/openser[26012]: DEBUG: timer routine:2,tl=0x2b05574b7a40
next=(nil)
/usr/sbin/openser[26012]: DEBUG: wait_handler : removing
0x2b05574b79c0 from table
/usr/sbin/openser[26012]: DEBUG: delete transaction 0x2b05574b79c0
/usr/sbin/openser[26012]: DEBUG: wait_handler : done
And this an ngrep output:
U 217.73.174.16:5063 -> 217.73.174.13:5060
INVITE sip:101@217.73.174.13 SIP/2.0..Via: SIP/2.0/UDP
82.79.243.82:5063;rport;branch=z9hG4bKlejwtozv..Max-Forwards: 70..To:
<sip:101@217
.73.174.13>..From: "Radu Spineanu"
<sip:100@217.73.174.13>;tag=lewnx..Call-ID:
pfysegloyvynryc@82.79.243.82..CSeq: 305 INVITE..Contact: <
sip:100@82.79.243.82:5063>..Content-Type: application/sdp..Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INFO..Suppor
ted: replaces,norefersub,100rel..User-Agent:
Twinkle/1.0.1..Content-Length: 303....v=0..o=100 246106612 367660894 IN
IP4 82.79.243.82..s=
-..c=IN IP4 82.79.243.82..t=0 0..m=audio 8012 RTP/AVP 98 97 8 0 3
101..a=rtpmap:98 speex/16000..a=rtpmap:97 speex/8000..a=rtpmap:8 PCMA/8
000..a=rtpmap:0 PCMU/8000..a=rtpmap:3 GSM/8000..a=rtpmap:101
telephone-event/8000..a=fmtp:101 0-15..a=ptime:20..
#
U 217.73.174.13:5060 -> 217.73.174.16:5063
SIP/2.0 100 trying -- your call is important to us..Via: SIP/2.0/UDP
82.79.243.82:5063;rport=5063;branch=z9hG4bKlejwtozv;received=217.73.
174.16..To: <sip:101@217.73.174.13>..From: "Radu Spineanu"
<sip:100@217.73.174.13>;tag=lewnx..Call-ID:
pfysegloyvynryc@82.79.243.82..CSeq
: 305 INVITE..Server: OpenSer (1.1.0-notls
(x86_64/linux))..Content-Length: 0..Warning: 392 217.73.174.13:5060
"Noisy feedback tells: pi
d=26007 req_src_ip=217.73.174.16 req_src_port=5063
in_uri=sip:101@217.73.174.13 out_uri=sip:101@82.79.243.82:5068
via_cnt==1"....
#
U 217.73.174.13:5060 -> 82.79.243.82:5068
INVITE sip:101@82.79.243.82:5068 SIP/2.0..Record-Route:
<sip:217.73.174.13;lr=on;ftag=lewnx>..Via: SIP/2.0/UDP
217.73.174.13;branch=z9hG4
bK4a11.a2772f67.0..Via: SIP/2.0/UDP
82.79.243.82:5063;received=217.73.174.16;rport=5063;branch=z9hG4bKlejwtozv..Max-Forwards:
69..To: <si
p:101@217.73.174.13>..From: "Radu Spineanu"
<sip:100@217.73.174.13>;tag=lewnx..Call-ID:
pfysegloyvynryc@82.79.243.82..CSeq: 305 INVITE..C
ontact: <sip:100@82.79.243.82:5063>..Content-Type:
application/sdp..Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INF
O..Supported: replaces,norefersub,100rel..User-Agent:
Twinkle/1.0.1..Content-Length: 303..P-hint: usrloc applied....v=0..o=100
246106612
367660894 IN IP4 82.79.243.82..s=-..c=IN IP4 82.79.243.82..t=0
0..m=audio 8012 RTP/AVP 98 97 8 0 3 101..a=rtpmap:98 speex/16000..a=rtpmap
:97 speex/8000..a=rtpmap:8 PCMA/8000..a=rtpmap:0
PCMU/8000..a=rtpmap:3 GSM/8000..a=rtpmap:101
telephone-event/8000..a=fmtp:101 0-15..a=pt
ime:20..
#
U 217.73.174.13:5060 -> 82.79.243.82:5068
INVITE sip:101@82.79.243.82:5068 SIP/2.0..Record-Route:
<sip:217.73.174.13;lr=on;ftag=lewnx>..Via: SIP/2.0/UDP
217.73.174.13;branch=z9hG4
bK4a11.a2772f67.0..Via: SIP/2.0/UDP
82.79.243.82:5063;received=217.73.174.16;rport=5063;branch=z9hG4bKlejwtozv..Max-Forwards:
69..To: <si
p:101@217.73.174.13>..From: "Radu Spineanu"
<sip:100@217.73.174.13>;tag=lewnx..Call-ID:
pfysegloyvynryc@82.79.243.82..CSeq: 305 INVITE..C
ontact: <sip:100@82.79.243.82:5063>..Content-Type:
application/sdp..Allow:
INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,REFER,NOTIFY,SUBSCRIBE,INF
O..Supported: replaces,norefersub,100rel..User-Agent:
Twinkle/1.0.1..Content-Length: 303..P-hint: usrloc applied....v=0..o=100
246106612
367660894 IN IP4 82.79.243.82..s=-..c=IN IP4 82.79.243.82..t=0
0..m=audio 8012 RTP/AVP 98 97 8 0 3 101..a=rtpmap:98 speex/16000..a=rtpmap
:97 speex/8000..a=rtpmap:8 PCMA/8000..a=rtpmap:0
PCMU/8000..a=rtpmap:3 GSM/8000..a=rtpmap:101
telephone-event/8000..a=fmtp:101 0-15..a=pt
ime:20..
#
Initially I did the setup folowing
http://www.openser.org/dokuwiki/doku.php/asterisk:realtime-integration
which worked but didn't have voicemail redirection support.
Thanks and sorry for the long mail,
Radu Spineanu