[OpenSER-Users] openser routing question

Radu Spineanu radu at rdconcept.ro
Sun Jun 24 17:37:35 CEST 2007


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+OpenSER
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 at 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 at 217.73.174.13}
  /usr/sbin/openser[26006]: DEBUG: get_hdr_field: <To> [25]; 
uri=[sip:101 at 217.73.174.13]
  /usr/sbin/openser[26006]: DEBUG: to body [<sip:101 at 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 at 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 at 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 at 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 at 217.73.174.13}
  /usr/sbin/openser[26006]: DEBUG: get_hdr_field: <To> [67]; 
uri=[sip:101 at 217.73.174.13]
  /usr/sbin/openser[26006]: DEBUG: to body [<sip:101 at 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 at 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 at 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 at 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 at 217
   .73.174.13>..From: "Radu Spineanu" 
<sip:100 at 217.73.174.13>;tag=lewnx..Call-ID: 
pfysegloyvynryc at 82.79.243.82..CSeq: 305 INVITE..Contact: <
   sip:100 at 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 at 217.73.174.13>..From: "Radu Spineanu" 
<sip:100 at 217.73.174.13>;tag=lewnx..Call-ID: 
pfysegloyvynryc at 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 at 217.73.174.13 out_uri=sip:101 at 82.79.243.82:5068 
via_cnt==1"....
#
U 217.73.174.13:5060 -> 82.79.243.82:5068
   INVITE sip:101 at 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 at 217.73.174.13>..From: "Radu Spineanu" 
<sip:100 at 217.73.174.13>;tag=lewnx..Call-ID: 
pfysegloyvynryc at 82.79.243.82..CSeq: 305 INVITE..C
   ontact: <sip:100 at 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 at 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 at 217.73.174.13>..From: "Radu Spineanu" 
<sip:100 at 217.73.174.13>;tag=lewnx..Call-ID: 
pfysegloyvynryc at 82.79.243.82..CSeq: 305 INVITE..C
   ontact: <sip:100 at 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




More information about the Users mailing list