[Serusers] ser and asterisk and rtpproxy

Thu Jul 1 23:15:16 CEST 2004

Hi all!
I know the argument is very famouse, I think I have read all ser.cfg on 
the net....
The problem is that when I call extension 9916 I don't hear asterisk 
music-on-old sound...

The scenario:

ser at port 5060
asterisk at port 5090
rtpproxy

I would like that, when an UA (x-lite for example) call 9916 UA can hear 
"music-on-hold" in asterisk.

*From ser.cfg:*

        if (uri=~"sip:9916@")
        {
                log("\n\nLOG: 9916 - Asterisk - Test()\n\n");

                force_rtp_proxy();
                t_relay_to_udp("xxx.xxx.xxx.xxx","5090");
                break;
        }

*From asterisk sip.conf:*

[general]

port = 5090
bindaddr = xxx.xxx.xxx.xxx
externip = xxx.xxx.xxx.xxx
tos=lowdelay
;
disallow = all
allow = ulaw
allow = alaw
;
context = sip-callfrom
language = us
musicclass = default

at now when I call 9916 from x-lite:

*ser says:*

 0(31421) SIP Request:
 0(31421)  method:  <INVITE>
 0(31421)  uri:     <sip:9916 at xxx.xxx.xxx.xxx>
 0(31421)  version: <SIP/2.0>
 0(31421) parse_headers: flags=1
 0(31421) Found param type 235, <rport> = <n/a>; state=6
 0(31421) Found param type 232, <branch> = 
<z9hG4bKB3CD5F29F30B4329995057709DFC7500>; state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=1
 0(31421) parse_headers: this is the first via
 0(31421) After parse_msg...
 0(31421) preparing to run routing scripts...
 0(31421) DEBUG : is_maxfwd_present: searching for max_forwards header
 0(31421) parse_headers: flags=128
 0(31421) end of header reached, state=9
 0(31421) DEBUG: get_hdr_field: <To> [26]; uri=[sip:9916 at xxx.xxx.xxx.xxx]
 0(31421) DEBUG: to body [<sip:9916 at xxx.xxx.xxx.xxx>
]
 0(31421) get_hdr_field: cseq <CSeq>: <12362> <INVITE>
 0(31421) DEBUG: is_maxfwd_present: value = 70
 0(31421) check_via_address(192.168.6.101, 192.168.6.101, 0)
 0(31421) parse_headers: flags=64
 0(31421) parse_headers: flags=-1
 0(31421) DEBUG: get_hdr_body : content_length=267
 0(31421) found end of header
 0(31421)

LOG: Someone trying to register from private IP, rewriting

 0(31421) parse_headers: flags=64
 0(31421) parse_headers: flags=-1
 0(31421) parse_headers: flags=-1
 0(31421) DEBUG:check_content_type: type <application/sdp> found valid
 0(31421) DEBUG: add_param: tag=2216232801
 0(31421) end of header reached, state=29
 0(31421) parse_headers: flags=256
 0(31421) find_first_route(): No Route headers found
 0(31421) loose_route(): There is no Route HF
 0(31421)

LOG: 9916 - Asterisk - Test()

 0(31421) parse_headers: flags=-1
 0(31421) DEBUG:check_content_type: type <application/sdp> found valid
 0(31421) ERROR: extract_mediaip: no `c=' in SDP
 0(31421) DEBUG: t_newtran: msg id=7 , global msg id=6 , T on 
entrance=0xffffffff
 0(31421) parse_headers: flags=-1
 0(31421) parse_headers: flags=60
 0(31421) t_lookup_request: start searching: hash=6960, isACK=0
 0(31421) DEBUG: RFC3261 transaction matching failed
 0(31421) DEBUG: t_lookup_request: no transaction found
 0(31421) SER: new INVITE
 0(31421) parse_headers: flags=-1
 0(31421) check_via_address(192.168.6.101, 192.168.6.101, 0)
 0(31421) WARNING:vqm_resize: resize(0) called
 0(31421) DEBUG: reply sent out. buf=0x80f9b98: SIP/2.0 1..., 
shmem=0x4019d0f0: SIP/2.0 1
 0(31421) DEBUG: _reply_light: finished
 0(31421) parse_headers: flags=2048
 0(31421) parse_headers: flags=-1
 0(31421) clen_builder: content-length: 306 (306)
 0(31421) check_via_address(192.168.6.101, 192.168.6.101, 0)
 0(31421) DEBUG: add_timer_unsafe[4]: 0x4019d520
 0(31421) DEBUG: add_timer_unsafe[0]: 0x4019d530
 0(31421) SER: new transaction fwd'ed
 0(31421) receive_msg: cleaning up
 0(31421) SIP Reply  (status):
 0(31421)  version: <SIP/2.0>
 0(31421)  status:  <100>
 0(31421)  reason:  <Trying>
 0(31421) parse_headers: flags=1
 0(31421) Found param type 232, <branch> = <z9hG4bK03b1.24325446.0>; 
state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=1
 0(31421) parse_headers: this is the first via
 0(31421) After parse_msg...
 0(31421) forward_reply: found module tm, passing reply to it
 0(31421) DEBUG: t_check: msg id=8 global id=7 T start=0xffffffff
 0(31421) parse_headers: flags=17
 0(31421) Found param type 235, <rport> = <5060>; state=6
 0(31421) Found param type 232, <branch> = 
<z9hG4bKB3CD5F29F30B4329995057709DFC7500>; state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=17
 0(31421) parse_headers: this is the second via
 0(31421) DEBUG: add_param: tag=as72cacbaf
 0(31421) end of header reached, state=29
 0(31421) DEBUG: get_hdr_field: <To> [41]; uri=[sip:9916 at xxx.xxx.xxx.xxx]
 0(31421) DEBUG: to body [<sip:9916 at xxx.xxx.xxx.xxx>]
 0(31421) get_hdr_field: cseq <CSeq>: <12362> <INVITE>
 0(31421) parse_headers: flags=4
 0(31421) DEBUG: t_reply_matching: hash 6960 label 1682252610 branch 0
 0(31421) DEBUG: t_reply_matching: reply matched (T=0x4019d408)!
 0(31421) DEBUG: t_check: msg id=8 global id=8 T end=0x4019d408
 0(31421) DEBUG: reply_received: org. status uas=100, uac[0]=0 local=0 
is_invite=1)
 0(31421) ->>>>>>>>> T_code=100, new_code=100
 0(31421) DEBUG: relay_reply: branch=0, save=0, relay=-1
 0(31421) DEBUG: add_timer_unsafe[1]: 0x4019d530
 0(31421) receive_msg: cleaning up
 0(31421) SIP Reply  (status):
 0(31421)  version: <SIP/2.0>
 0(31421)  status:  <200>
 0(31421)  reason:  <OK>
 0(31421) parse_headers: flags=1
 0(31421) Found param type 232, <branch> = <z9hG4bK03b1.24325446.0>; 
state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=1
 0(31421) parse_headers: this is the first via
 0(31421) After parse_msg...
 0(31421) forward_reply: found module tm, passing reply to it
 0(31421) DEBUG: t_check: msg id=9 global id=8 T start=0xffffffff
 0(31421) parse_headers: flags=17
 0(31421) Found param type 235, <rport> = <5060>; state=6
 0(31421) Found param type 232, <branch> = 
<z9hG4bKB3CD5F29F30B4329995057709DFC7500>; state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=17
 0(31421) parse_headers: this is the second via
 0(31421) DEBUG: add_param: tag=as72cacbaf
 0(31421) end of header reached, state=29
 0(31421) DEBUG: get_hdr_field: <To> [41]; uri=[sip:9916 at xxx.xxx.xxx.xxx]
 0(31421) DEBUG: to body [<sip:9916 at xxx.xxx.xxx.xxx>]
 0(31421) get_hdr_field: cseq <CSeq>: <12362> <INVITE>
 0(31421) parse_headers: flags=4
 0(31421) DEBUG: t_reply_matching: hash 6960 label 1682252610 branch 0
 0(31421) DEBUG: t_reply_matching: reply matched (T=0x4019d408)!
 0(31421) parse_headers: flags=4
 0(31421) DEBUG: t_check: msg id=9 global id=9 T end=0x4019d408
 0(31421) DEBUG: reply_received: org. status uas=100, uac[0]=100 local=0 
is_invite=1)
 0(31421) ->>>>>>>>> T_code=100, new_code=200
 0(31421) DEBUG: relay_reply: branch=0, save=0, relay=0
 0(31421)  old size: 842, new size: 780
 0(31421) build_res_from_sip_res: copied size: orig:78, new: 16, rest: 
764 msg=
SIP/2.0 200 OK
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKB3CD5F29F30B4329995057709DFC7500
Record-Route: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>;tag=as72cacbaf
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:9916 at xxx.xxx.xxx.xxx:5090>
Content-Type: application/sdp
Content-Length: 265

v=0
o=root 31456 31456 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 10100 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

 0(31421) DEBUG: update_totag_set: new totag
 0(31421) DEBUG: reply relayed. buf=0x80f9de8: SIP/2.0 2..., 
shmem=0x4019b240: SIP/2.0 2
 0(31421) DEBUG: cleanup_uac_timers: RETR/FR timers reset
 0(31421) DEBUG: add_timer_unsafe[2]: 0x4019d450
 0(31421) receive_msg: cleaning up
 0(31421) SIP Request:
 0(31421)  method:  <ACK>
 0(31421)  uri:     <sip:9916 at xxx.xxx.xxx.xxx:5090>
 0(31421)  version: <SIP/2.0>
 0(31421) parse_headers: flags=1
 0(31421) Found param type 235, <rport> = <n/a>; state=6
 0(31421) Found param type 232, <branch> = 
<z9hG4bKA83370958AA746AFA673710404627DFC>; state=16
 0(31421) end of header reached, state=5
 0(31421) parse_headers: Via found, flags=1
 0(31421) parse_headers: this is the first via
 0(31421) After parse_msg...
 0(31421) preparing to run routing scripts...
 0(31421) DEBUG : sl_filter_ACK: to late to be a local ACK!
 0(31421) DEBUG : is_maxfwd_present: searching for max_forwards header
 0(31421) parse_headers: flags=128
 0(31421) DEBUG: add_param: tag=as72cacbaf
 0(31421) end of header reached, state=29
 0(31421) DEBUG: get_hdr_field: <To> [41]; uri=[sip:9916 at xxx.xxx.xxx.xxx]
 0(31421) DEBUG: to body [<sip:9916 at xxx.xxx.xxx.xxx>]
 0(31421) get_hdr_field: cseq <CSeq>: <12362> <ACK>
 0(31421) DEBUG: is_maxfwd_present: value = 70
 0(31421) check_via_address(192.168.6.101, 192.168.6.101, 0)
 0(31421) parse_headers: flags=64
 0(31421) parse_headers: flags=-1
 0(31421) DEBUG: get_hdr_body : content_length=0
 0(31421) found end of header
 0(31421)

LOG: Someone trying to register from private IP, rewriting

 0(31421) parse_headers: flags=64
 0(31421) DEBUG: add_param: tag=2216232801
 0(31421) end of header reached, state=29
 0(31421) parse_headers: flags=256
 0(31421) check_self - checking if host==us: 13==13 &&  
[xxx.xxx.xxx.xxx] == [xxx.xxx.xxx.xxx]
 0(31421) check_self - checking if port 5060 matches port 5090
 0(31421) check_self - checking if host==us: 13==13 &&  
[xxx.xxx.xxx.xxx] == [xxx.xxx.xxx.xxx]
 0(31421) check_self - checking if port 5060 matches port 5090
 0(31421) check_self: host != me
 0(31421) check_self - checking if host==us: 13==13 &&  
[xxx.xxx.xxx.xxx] == [xxx.xxx.xxx.xxx]
 0(31421) check_self - checking if port 5060 matches port 5060
 0(31421) ral(): Topmost route URI: 
'sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on' is me
 0(31421) parse_headers: flags=256
 0(31421) found end of header
 0(31421) fnr(): No next Route HF found
 0(31421) ral(): No next URI found
 0(31421)

LOG: 9916 - Asterisk - Test()

 0(31421) DEBUG: t_newtran: msg id=10 , global msg id=9 , T on 
entrance=0xffffffff
 0(31421) parse_headers: flags=-1
 0(31421) parse_headers: flags=60
 0(31421) t_lookup_request: start searching: hash=6960, isACK=1
 0(31421) parse_headers: flags=28
 0(31421) DEBUG: t_lookup_request: e2e proxy ACK found
 0(31421) parse_headers: flags=4
 0(31421) DEBUG: totag for e2e ACK found: 0
 0(31421) SER: forwarding ACK  statelessly
 0(31421) check_via_address(192.168.6.101, 192.168.6.101, 0)
 0(31421) Sending:
ACK sip:9916 at xxx.xxx.xxx.xxx:5090 SIP/2.0
Record-Route: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx;branch=0
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKA83370958AA746AFA673710404627DFC
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>;tag=as72cacbaf
Contact: <sip:2001 at 192.168.6.101:5060>
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 ACK
Max-Forwards: 69
Content-Length: 0
Voco-dbg: NAThelper

.
 0(31421) orig. len=435, new_len=509, proto=1
 0(31421) receive_msg: cleaning up
 1(31422) DEBUG: timer routine:1,tl=0x4019d530 next=(nil)
 1(31422) DEBUG: timer routine:4,tl=0x4019d520 next=(nil)

*rtpproxy -f says:*

rtpproxy: new session 
7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101, tag 2216232801 requested
rtpproxy: new session on a port 10018 created, tag 2216232801
rtpproxy: pre-filling caller's address with 192.168.6.101:8000

*asterisk sip debug says:*

Sip read:
INVITE sip:9916 at xxx.xxx.xxx.xxx:5090 SIP/2.0
Record-Route: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx;branch=z9hG4bK03b1.24325446.0
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKB3CD5F29F30B4329995057709DFC7500
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>
Contact: <sip:2001 at 192.168.6.101:5060>
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 INVITE
Max-Forwards: 69
Content-Type: application/sdp
User-Agent: X-Lite release 1103m
Content-Length: 306
Voco-dbg: NAThelper
Voco-dbg: SDP rewrited

v=0
o=2001 8220109 8220125 IN IP4 192.168.6.101
s=X-Lite
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 10018 RTP/AVP 0 8 3 97 101
a=rtpmap:0 pcmu/8000
a=rtpmap:8 pcma/8000
a=rtpmap:3 gsm/8000
a=rtpmap:97 speex/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=direction:active
a=nortpproxy:yes

15 headers, 14 lines
Using latest request as basis request
Sending to xxx.xxx.xxx.xxx : 5060 (non-NAT)
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 97
Found RTP audio format 101
Peer RTP is at port xxx.xxx.xxx.xxx:0
Found description format pcmu
Found description format pcma
Found description format gsm
Found description format speex
Found description format telephone-event
Capabilities: us - 0x40e(GSM|ULAW|ALAW|ILBC), peer - 
audio=0x20e(GSM|ULAW|ALAW|SPEEX)/video=0x0(EMPTY), combined - 
0xe(GSM|ULAW|ALAW)
Non-codec capabilities: us - 0x1(G723), peer - 0x1(G723), combined - 
0x1(G723)
Found no matching peer or user for 'xxx.xxx.xxx.xxx:5060'
Looking for 9916 in sip-callfrom
list_route: hop: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
list_route: hop: <sip:2001 at 192.168.6.101:5060>
Transmitting (no NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx;branch=z9hG4bK03b1.24325446.0
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKB3CD5F29F30B4329995057709DFC7500
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>;tag=as72cacbaf
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:9916 at xxx.xxx.xxx.xxx:5090>
Content-Length: 0

 to xxx.xxx.xxx.xxx:5060
    -- Executing Answer("SIP/xxx.xxx.xxx.xxx-081346f0", "") in new stack
We're at xxx.xxx.xxx.xxx port 10100
Answering with preferred capability 0x2(GSM)
Answering with preferred capability 0x4(ULAW)
Answering with preferred capability 0x8(ALAW)
Answering with non-codec capability 0x1(G723)
Reliably Transmitting (no NAT):
SIP/2.0 200 OK
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx;branch=z9hG4bK03b1.24325446.0
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKB3CD5F29F30B4329995057709DFC7500
Record-Route: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>;tag=as72cacbaf
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:9916 at xxx.xxx.xxx.xxx:5090>
Content-Type: application/sdp
Content-Length: 265

v=0
o=root 31456 31456 IN IP4 xxx.xxx.xxx.xxx
s=session
c=IN IP4 xxx.xxx.xxx.xxx
t=0 0
m=audio 10100 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -

 to xxx.xxx.xxx.xxx:5060
    -- Executing MusicOnHold("SIP/xxx.xxx.xxx.xxx-081346f0", "default") 
in new stack
    -- Started music on hold, class 'default', on 
SIP/xxx.xxx.xxx.xxx-081346f0

Sip read:
ACK sip:9916 at xxx.xxx.xxx.xxx:5090 SIP/2.0
Record-Route: <sip:xxx.xxx.xxx.xxx;ftag=2216232801;lr=on>
Via: SIP/2.0/UDP xxx.xxx.xxx.xxx;branch=0
Via: SIP/2.0/UDP 
192.168.6.101:5060;rport=5060;branch=z9hG4bKA83370958AA746AFA673710404627DFC
From: 2001 <sip:2001 at xxx.xxx.xxx.xxx>;tag=2216232801
To: <sip:9916 at xxx.xxx.xxx.xxx>;tag=as72cacbaf
Contact: <sip:2001 at 192.168.6.101:5060>
Call-ID: 7C0EAF05-D24D-463B-BB2A-F7746D751921 at 192.168.6.101
CSeq: 12362 ACK
Max-Forwards: 69
Content-Length: 0
Voco-dbg: NAThelper

12 headers, 0 lines