Hi everybody
I've configured a SIP server (OpenSER 1.3.2) to work with rtpproxy and so far everything is fine, but now I want to be able to record the audio from a conversation. I've read that this is possible by using the function start_recording from the module NATHelper but I'm not able to get it working
RTPproxy 1.2.1 is running with the following options:
root@openser:/opt/rtpproxy-1.2.1/bin# ps uax | grep rtpproxy rtpproxy 30827 0.0 0.0 26968 964 ? Ssl 14:49 0:00 /opt/rtpproxy-1.2.1/bin/rtpproxy -u rtpproxy rtpproxy -p /var/run/rtpproxy/rtpproxy.pid -l 192.168.34.1 -s udp:127.0.0.1 7890 -r /etc/openser/stored_conversations -S /tmp -a -d DBUG -P root 31547 0.0 0.0 7524 892 pts/1 R+ 15:59 0:00 grep rtpproxy
Output from netstat
root@openser:/opt/rtpproxy-1.2.1/bin# netstat -tupna | grep rtpproxy udp 0 0 127.0.0.1:7890 0.0.0.0:* 30827/rtpproxy
Relevant parts of the configuration file
... # ------ nathelper params ----- modparam("nathelper", "natping_interval", 30) modparam("nathelper", "ping_nated_only", 1) modparam("nathelper", "sipping_bflag", 7) modparam("nathelper", "sipping_from", "sip:pinger@openser.org")
modparam("nathelper", "rtpproxy_sock", "udp:127.0.0.1:7890") modparam("nathelper", "force_socket", "udp:localhost:7890") ... route[6] { xlog("L_INFO", "ROUTE 6"); # NAT handling # Set reply routing block, to which control is passed after a transaction # completed with a negative result but before sending a final reply t_on_failure("1"); # Check if we're NATed if (isflagset(5) || isbflagset(6)) { # Use rtpproxy force_rtp_proxy(); if ( start_recording() ) { xlog("L_INFO", "RECORDING..."); }; } # Set reply routing block, to which control is passed each time a reply # (provisional or final) for the transaction is received t_on_reply("1"); } ... onreply_route[1] { xlog("L_INFO", "ONREPLY_ROUTE"); if ((isflagset(5) || isbflagset(6)) && status=~"(180)|(183)|(2[0-9][0-9])") { xlog("L_INFO", "NAT'd TRANSACTION"); fix_nated_contact(); force_rtp_proxy(); if ( start_recording() ) { xlog("L_INFO", "RECORDING..."); }; } else if (nat_uac_test("1")) { fix_nated_contact(); } exit; }
When I start OpenSER I see the following in syslog
Mar 19 16:08:45 openser /usr/sbin/openser[31630]: NOTICE:core:main: version: openser 1.3.2-notls (x86_64/linux) Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:main: using 256 Mb shared memory Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:main: using 1 Mb private memory per process Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:sl:mod_init: Initializing StateLess engine Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:tm:mod_init: TM - initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:maxfwd:mod_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:usrloc:ul_init_locks: locks array size 512 Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:registrar:mod_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:textops:mod_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:xlog:mod_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:avpops:avpops_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:acc:mod_init: initializing... Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:dialog:mod_init: Dialog module - initializing Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 255 kb Mar 19 16:08:45 openser /usr/sbin/openser[31630]: INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 255 kb Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31632_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31632_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31632_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31632_1 1 " Mar 19 16:08:45 openser /usr/sbin/openser[31632]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31631_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31631_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31633_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31633_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31634_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31634_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31635_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31635_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31636_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31636_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31637_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31637_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31638_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31638_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31637_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31637_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31631_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31631_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31634_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31634_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31636_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31636_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31633_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31633_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31635_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31635_1 1 " Mar 19 16:08:45 openser /usr/sbin/openser[31631]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31634]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31637]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31633]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31636]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31635]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31638]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31639_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31639_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31638_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31638_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31640_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31640_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31642_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31642_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31643_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31643_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31644_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31644_0 20040107 " Mar 19 16:08:45 openser /usr/sbin/openser[31642]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31643]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31645_0 V" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31645_0 20040107 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31639_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31639_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31642_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31642_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31644_1 VF 20050322" Mar 19 16:08:45 openser /usr/sbin/openser[31644]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31644_1 1 " Mar 19 16:08:45 openser /usr/sbin/openser[31640]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser /usr/sbin/openser[31639]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31640_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31640_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31643_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31643_1 1 " Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:handle_command: received command "31645_1 VF 20050322" Mar 19 16:08:45 openser rtpproxy[30827]: DBUG:doreply: sending reply "31645_1 1 " Mar 19 16:08:45 openser /usr/sbin/openser[31645]: INFO:nathelper:rtpp_test: rtp proxy udp:127.0.0.1:7890 found, support for it enabled
But when I place the call no debug info from rtpproxy is being generated nor the RTP session is being saved to file.
Any idea what the problem can be?
Thanks in advance
Héctor
Hector,
I'm no expert when it comes to rtpproxy or Kamailio , but i've encountered a similar problem in the past. I took a quick look at your logfile and i noticed that there aren't any SIP messages in the log (eg. REGISTER, INVITE...). Are you sure that SIP messages are being proxied ? if not recording would not be possible.
Regards, Vikram.
Hi Vikram
Yes, SIP messages are being proxied, otherwise the call wouldn't be possible.
Here are the SIP messages that are being proxied in case this helps to debug my problem
interface: eth1 (192.168.34.1/255.255.255.240) filter: (ip or ip6) and ( port 5060 )
U 192.168.34.1:5060 -> 192.168.128.61:5060 INVITE sip:0315080190@192.168.128.61 SIP/2.0. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1. From: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. To: sip:0315080190@192.168.35.36. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 101 INVITE. Max-Forwards: 69. Contact: "0315080180" sip:0315080180@195.176.213.123:5060. Expires: 240. User-Agent: Sipura/SPA921-4.1.10(b). Content-Length: 403. Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER. Content-Type: application/sdp. . v=0. o=- 1956263 1956263 IN IP4 195.176.213.123. s=-. c=IN IP4 195.176.213.123. t=0 0. m=audio 16386 RTP/AVP 0 2 4 8 18 96 97 98 101. a=rtpmap:0 PCMU/8000. a=rtpmap:2 G726-32/8000. a=rtpmap:4 G723/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:18 G729a/8000. a=rtpmap:96 G726-40/8000. a=rtpmap:97 G726-24/8000. a=rtpmap:98 G726-16/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=ptime:30. a=sendrecv.
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. To: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. .
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 183 Session Progress. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. To: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE. Content-Type: application/sdp. Content-Length: 186. . v=0. o=- 227934408367722 1 IN IP4 192.168.128.61. s=-. c=IN IP4 192.168.128.61. t=0 0. m=audio 23984 RTP/AVP 0 101. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16.
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-a6818ce1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. To: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE. Content-Type: application/sdp. Content-Length: 186. . v=0. o=- 227934408367722 1 IN IP4 192.168.128.61. s=-. c=IN IP4 192.168.128.61. t=0 0. m=audio 23984 RTP/AVP 0 101. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16.
U 192.168.34.1:5060 -> 192.168.128.61:5060 ACK sip:gw01@192.168.128.61:5060 SIP/2.0. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK2838.f3a91403.2. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-c7ff7fbe. From: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. To: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 101 ACK. Max-Forwards: 69. Contact: "0315080180" sip:0315080180@195.176.213.123:5060. User-Agent: Sipura/SPA921-4.1.10(b). Content-Length: 0. .
U 192.168.128.61:5060 -> 192.168.34.1:5060 BYE sip:0315080180@195.176.213.123:5060 SIP/2.0. Route: sip:192.168.34.1;r2=on;lr=on. Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.128.61:5060;branch=z9hG4bKf9950ba86fb23261fde8afbb. Max-Forwards: 70. From: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. To: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 1 BYE. User-Agent: Netstream VoIP Gateway. .
U 192.168.34.1:5060 -> 192.168.128.61:5060 SIP/2.0 200 OK. To: "0315080180" sip:0315080180@192.168.35.36;tag=58e4d381b7c3e699o0. From: sip:0315080190@192.168.35.36;tag=f9950ba86292ab03fde8af7b. Call-ID: b80ee3a1-19414f9@192.168.0.2. CSeq: 1 BYE. Via: SIP/2.0/UDP 192.168.128.61:5060;rport=5060;branch=z9hG4bKf9950ba86fb23261fde8afbb. Record-Route: sip:192.168.35.36;r2=on;lr=on. Record-Route: sip:192.168.34.1;r2=on;lr=on. Server: Sipura/SPA921-4.1.10(b). Content-Length: 0. .
Cheers
Héctor
-----Original Message----- From: Vikram Ragukumar [mailto:vragukumar@signalogic.com] Sent: Freitag, 19. März 2010 16:48 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Hector,
I'm no expert when it comes to rtpproxy or Kamailio , but i've encountered a similar problem in the past. I took a quick look at your logfile and i noticed that there aren't any SIP messages in the log (eg. REGISTER, INVITE...). Are you sure that SIP messages are being proxied ? if not recording would not be possible.
Regards, Vikram.
Hector,
I could be wrong about what's happening here, but what you have provided is a sip trace from an external utility (wireshark or tcpdump maybe .. ?).
Could you verify your kamailio log to see if it is actually handling SIP messages?
I show below a portion of one of my logs for kamailio, that indicates reception of a REGISTER message. (you might have to increase the 'debug=' value option in you kamailio.cfg)
localhost /usr/local/sbin/kamailio[3083]: DBG:core:io_watch_add: io_watch_add(0x8156f00, 30, 1, (nil)), fd_no=0 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: SIP Request: localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: method: <REGISTER> localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: uri: sip:61.24.320.543:5060 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: version: <SIP/2.0> localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: flags=2 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj1AbnwayUehrY5eBxiVzMEG4UDoGoFAnj>; state=16 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via: end of header reached, state=5 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: via found, flags=2 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: this is the first via localhost /usr/local/sbin/kamailio[3075]: DBG:core:receive_msg: After parse_msg...
Regards, Vikram.
Vikram,
Yes, my server is handling SIP messages, that's why I'm able to make and receive calls. If you really need to see this info, I've activated the debug level 6 in my configuration file so I hope it helps debugging my problem.
Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: SIP Request: Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: method: <INVITE> Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: uri: sip:0315080190@192.168.35.36 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=2 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: this is the first via Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: preparing to run routing scripts... Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=100 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=10 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: <To> [33]; uri=[sip:0315080190@192.168.35.36] Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: to body [sip:0315080190@192.168.35.36^M ] Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE> Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=80 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:uri:has_totag: no totag Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE_3^M Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180@192.168.35.36} Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:domain:is_domain_local: Realm '192.168.35.36' is local Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: freeing 1 rows Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: row[0]=0x724028 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: 0x724028=pkg_free() RES_ROWS Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:registrar:lookup: '0315080190' Not found in usrloc Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:domain:is_domain_local: Realm '192.168.35.36' is local Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: freeing 1 rows Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: row[0]=0x724028 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:db_free_rows: 0x724028=pkg_free() RES_ROWS Mar 22 09:25:16 openser /usr/sbin/openser[32372]: OUTGOING CALL^M Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 10 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 6 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 4 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: ROUTE 1 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:subst_run: running. r=1 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:subst_str: no match Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_newtran: transaction on entrance=(nil) Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: content_length=405 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: found end of header Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 1 entered Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 0 entered Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:_shm_resize: resize(0) called Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:_reply_light: reply sent out. buf=0x724860: SIP/2.0 1..., shmem=0x7f852e6282d0: SIP/2.0 1 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:_reply_light: finished Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:mk_proxy: doing DNS lookup... Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:set_timer: relative timeout is 500000 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:insert_timer_unsafe: [4]: 0x7f852e6257f0 (31200000) Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:set_timer: relative timeout is 30 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:insert_timer_unsafe: [0]: 0x7f852e625820 (60) Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_relay_to: new transaction fwd'ed Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:16 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: cleaning up Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: SIP Reply (status): Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: status: <100> Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: reason: <Trying> Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=2 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: this is the first via Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:forward_reply: found module nathelper, passing reply to it Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=4 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=4 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: parse_headers: this is the second via Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:forward_reply: found module tm, passing reply to it Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_check: start=0xffffffffffffffff Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=22 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190@192.168.35.36] Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: to body [sip:0315080190@192.168.35.36] Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE> Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=8 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)! Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_check: end=0x7f852e6255d0 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Mar 22 09:25:16 openser /usr/sbin/openser[32377]: ONREPLY_ROUTE Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=80 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_should_relay_response: T_code=100, new_code=100 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:relay_reply: branch=0, save=0, relay=-1 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 120 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [1]: 0x7f852e625820 (150) Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:16 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: cleaning up Mar 22 09:25:16 openser /usr/sbin/openser[32380]: DBG:tm:utimer_routine: timer routine:4,tl=0x7f852e6257f0 next=(nil), timeout=31200000 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: SIP Reply (status): Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: status: <183> Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_msg: reason: <Session Progress> Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=2 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: this is the first via Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:forward_reply: found module nathelper, passing reply to it Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=4 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: via found, flags=4 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: parse_headers: this is the second via Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:forward_reply: found module tm, passing reply to it Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_check: start=0xffffffffffffffff Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=22 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190@192.168.35.36] Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: to body [sip:0315080190@192.168.35.36] Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE> Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=8 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)! Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_check: end=0x7f852e6255d0 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) Mar 22 09:25:18 openser /usr/sbin/openser[32379]: ONREPLY_ROUTE Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:parse_headers: flags=80 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_should_relay_response: T_code=100, new_code=183 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:build_res_buf_from_sip_res: old size: 867, new size: 780 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:build_res_buf_from_sip_res: copied size: orig:117, new: 30, rest: 750 msg= SIP/2.0 183 Session Progress^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-b562ca09^M Record-Route: sip:192.168.34.1;r2=on;lr=on^M Record-Route: sip:192.168.35.36;r2=on;lr=on^M From: "0315080180" sip:0315080180@192.168.35.36;tag=40d3dff819e5d131o0^M To: sip:0315080190@192.168.35.36;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5@192.168.0.2^M CSeq: 101 INVITE^M User-Agent: Netstream VoIP Gateway^M Contact: sip:gw01@192.168.128.61:5060^M Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE^M Content-Type: application/sdp^M Content-Length: 186^M ^M v=0^M o=- 227949608179227 1 IN IP4 192.168.128.61^M s=-^M c=IN IP4 192.168.128.61^M t=0 0^M m=audio 17124 RTP/AVP 0 101^M a=rtpmap:0 PCMU/8000^M a=rtpmap:101 telephone-event/8000^M a=fmtp:101 0-16^M Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:relay_reply: sent buf=0x71fda0: SIP/2.0 1..., shmem=0x7f852e6289b8: SIP/2.0 1 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:set_timer: relative timeout is 120 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:insert_timer_unsafe: [1]: 0x7f852e625820 (153) Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:18 openser /usr/sbin/openser[32379]: DBG:core:receive_msg: cleaning up Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: SIP Reply (status): Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: status: <200> Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_msg: reason: <OK> Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=2 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK93a6.ec962825.0>; state=6 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.34.1>; state=16 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: this is the first via Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:forward_reply: found module nathelper, passing reply to it Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=4 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-b562ca09>; state=16 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: via found, flags=4 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: parse_headers: this is the second via Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:forward_reply: found module tm, passing reply to it Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_check: start=0xffffffffffffffff Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=22 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190@192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: to body [sip:0315080190@192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <INVITE> Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=8 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: hash 27193 label 1384278478 branch 0 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_reply_matching: reply matched (T=0x7f852e6255d0)! Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_check: end=0x7f852e6255d0 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1) Mar 22 09:25:22 openser /usr/sbin/openser[32378]: ONREPLY_ROUTE Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:parse_headers: flags=80 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_should_relay_response: T_code=183, new_code=200 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:build_res_buf_from_sip_res: old size: 853, new size: 766 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:build_res_buf_from_sip_res: copied size: orig:103, new: 16, rest: 750 msg= SIP/2.0 200 OK^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-b562ca09^M Record-Route: sip:192.168.34.1;r2=on;lr=on^M Record-Route: sip:192.168.35.36;r2=on;lr=on^M From: "0315080180" sip:0315080180@192.168.35.36;tag=40d3dff819e5d131o0^M To: sip:0315080190@192.168.35.36;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5@192.168.0.2^M CSeq: 101 INVITE^M User-Agent: Netstream VoIP Gateway^M Contact: sip:gw01@192.168.128.61:5060^M Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE^M Content-Type: application/sdp^M Content-Length: 186^M ^M v=0^M o=- 227949608179227 1 IN IP4 192.168.128.61^M s=-^M c=IN IP4 192.168.128.61^M t=0 0^M m=audio 17124 RTP/AVP 0 101^M a=rtpmap:0 PCMU/8000^M a=rtpmap:101 telephone-event/8000^M a=fmtp:101 0-16^M Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:insert_timer_unsafe: [2]: 0x7f852e625650 (42) Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:relay_reply: sent buf=0x71fda0: SIP/2.0 2..., shmem=0x7f852e6289b8: SIP/2.0 2 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:22 openser /usr/sbin/openser[32378]: DBG:core:receive_msg: cleaning up Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: SIP Request: Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: method: <ACK> Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: uri: sip:gw01@192.168.128.61:5060 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=2 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-15f908fd>; state=16 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: this is the first via Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: preparing to run routing scripts... Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=100 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: <To> [62]; uri=[sip:0315080190@192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: to body [sip:0315080190@192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: cseq <CSeq>: <101> <ACK> Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=80 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:uri:has_totag: totag found Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=200 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:is_preloaded: is_preloaded: No Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 12==14 && [192.168.128.61] == [192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 12==14 && [192.168.128.61] == [192.168.34.1] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:check_self: host != me Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.35.36] == [192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.35.36;r2=on;lr=on' is me Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.35.36] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.34.1] Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=200 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: content_length=0 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: found end of header Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:find_next_route: No next Route HF found Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:after_loose: no next URI found Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr=on> Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:dialog:dlg_onroute: Route param 'did' not found Mar 22 09:25:22 openser /usr/sbin/openser[32374]: ACCOUNTING START Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:22 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180@192.168.35.36} Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: ACC: request accounted: timestamp=1269246323;method=ACK;from_tag=40d3dff819e5d131o0;to_tag=f9950f1e7f4263e3fdec46f4;call_id=e4a790c4-f562f6d5@192.168.0.2;code=200;reason=ok Mar 22 09:25:23 openser /usr/sbin/openser[32374]: ROUTE 1 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:subst_run: running. r=1 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:subst_str: no match Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=78 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: start searching: hash=27193, isACK=1 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=38 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_lookup_request: e2e proxy ACK found Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_newtran: building branch for end2end ACK Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_relay_to: forwarding ACK Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:mk_proxy: doing DNS lookup... Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:forward_request: sending: ACK sip:gw01@192.168.128.61:5060 SIP/2.0^M Record-Route: sip:192.168.34.1;r2=on;lr=on^M Record-Route: sip:192.168.35.36;r2=on;lr=on^M Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK93a6.ec962825.2^M Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-15f908fd^M From: "0315080180" sip:0315080180@192.168.35.36;tag=40d3dff819e5d131o0^M To: sip:0315080190@192.168.35.36;tag=f9950f1e7f4263e3fdec46f4^M Call-ID: e4a790c4-f562f6d5@192.168.0.2^M CSeq: 101 ACK^M Max-Forwards: 69^M Contact: "0315080180" sip:0315080180@195.176.213.123:5060^M User-Agent: Sipura/SPA921-4.1.10(b)^M Content-Length: 0^M ^M . Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:forward_request: orig. len=518, new_len=613, proto=1 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 0 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:destroy_avp_list: destroying list 0x7f852e6282d0 Mar 22 09:25:23 openser /usr/sbin/openser[32374]: DBG:core:receive_msg: cleaning up Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: SIP Request: Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: method: <NOTIFY> Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: uri: sip:192.168.35.36 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=2 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-4cb4b718>; state=16 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: this is the first via Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: preparing to run routing scripts... Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=100 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_to: end of header reached, state=10 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_to: display={}, ruri={sip:192.168.35.36} Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: <To> [22]; uri=[sip:192.168.35.36] Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: to body [sip:192.168.35.36^M ] Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: cseq <CSeq>: <16736> <NOTIFY> Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=80 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: content_length=0 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:get_hdr_field: found end of header Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:uri:has_totag: no totag Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=78 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: start searching: hash=21918, isACK=0 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:tm:t_lookup_request: no transaction found Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:check_via_address: params 195.176.213.123, 195.176.213.123, 0 Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:24 openser /usr/sbin/openser[32372]: DBG:core:receive_msg: cleaning up Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:timer_routine: timer routine:2,tl=0x7f852e625650 next=(nil), timeout=42 Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:wait_handler: removing 0x7f852e6255d0 from table Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:delete_cell: delete transaction 0x7f852e6255d0 Mar 22 09:25:27 openser /usr/sbin/openser[32380]: DBG:tm:wait_handler: done Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: SIP Request: Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: method: <BYE> Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: uri: sip:0315080180@195.176.213.123:5060 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=2 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKf9950f1e6b2f5081fdec4739>; state=16 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_via: end of header reached, state=5 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: via found, flags=2 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: this is the first via Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: After parse_msg... Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: preparing to run routing scripts... Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=100 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:maxfwd:is_maxfwd_present: value = 70 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_via_address: params 192.168.128.61, 192.168.128.61, 0 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=80 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180@192.168.35.36} Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: <To> [69]; uri=[sip:0315080180@192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: to body ["0315080180" sip:0315080180@192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <BYE> Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: found end of header Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:uri:has_totag: totag found Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=200 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:is_preloaded: is_preloaded: No Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 15==14 && [195.176.213.123] == [192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 15==14 && [195.176.213.123] == [192.168.34.1] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_self: host != me Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.34.1] == [192.168.34.1] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.34.1;r2=on;lr=on' is me Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:grep_sock_info: checking if host==us: 14==14 && [192.168.35.36] == [192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=200 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:get_hdr_field: found end of header Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:find_next_route: No next Route HF found Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:after_loose: no next URI found Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:rr:run_rr_callbacks: callback id 0 entered with <r2=on;lr=on> Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:dialog:dlg_onroute: Route param 'did' not found Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ACCOUNTING STOP Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to_param: tag=f9950f1e7f4263e3fdec46f4 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_to: display={}, ruri={sip:0315080190@192.168.35.36} Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ACC: request accounted: timestamp=1269246328;method=BYE;from_tag=f9950f1e7f4263e3fdec46f4;to_tag=40d3dff819e5d131o0;call_id=e4a790c4-f562f6d5@192.168.0.2;code=200;reason=ok Mar 22 09:25:28 openser /usr/sbin/openser[32377]: ROUTE 1 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:subst_run: running. r=1 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:subst_str: no match Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=ffffffffffffffff Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:parse_headers: flags=78 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_lookup_request: start searching: hash=19358, isACK=0 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_lookup_request: no transaction found Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 1 entered Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:run_reqin_callbacks: trans=0x7f852e6255d0, callback type 1, id 0 entered Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:mk_proxy: doing DNS lookup... Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:check_via_address: params 192.168.128.61, 192.168.128.61, 0 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 500000 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [4]: 0x7f852e6257f0 (43200000) Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:set_timer: relative timeout is 30 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:insert_timer_unsafe: [0]: 0x7f852e625820 (72) Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_relay_to: new transaction fwd'ed Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:destroy_avp_list: destroying list (nil) Mar 22 09:25:28 openser /usr/sbin/openser[32377]: DBG:core:receive_msg: cleaning up Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: SIP Reply (status): Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: version: <SIP/2.0> Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: status: <200> Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_msg: reason: <OK> Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_headers: flags=2 Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to_param: tag=40d3dff819e5d131o0 Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to: end of header reached, state=29 Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_to: display={"0315080180"}, ruri={sip:0315080180@192.168.35.36} Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: <To> [69]; uri=[sip:0315080180@192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: to body ["0315080180" sip:0315080180@192.168.35.36] Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <BYE> Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKe9b4.709d6d85.0>; state=16 Mar 22 09:25:28 openser /usr/sbin/openser[32374]: DBG:core:parse_via: end of header reached, state=5
Héctor
-----Original Message----- From: Vikram Ragukumar [mailto:vragukumar@signalogic.com] Sent: Freitag, 19. März 2010 22:51 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Hector,
I could be wrong about what's happening here, but what you have provided is a sip trace from an external utility (wireshark or tcpdump maybe .. ?).
Could you verify your kamailio log to see if it is actually handling SIP messages?
I show below a portion of one of my logs for kamailio, that indicates reception of a REGISTER message. (you might have to increase the 'debug=' value option in you kamailio.cfg)
localhost /usr/local/sbin/kamailio[3083]: DBG:core:io_watch_add: io_watch_add(0x8156f00, 30, 1, (nil)), fd_no=0 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: SIP Request: localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: method: <REGISTER> localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: uri: sip:61.24.320.543:5060 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_msg: version: <SIP/2.0> localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: flags=2 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPj1AbnwayUehrY5eBxiVzMEG4UDoGoFAnj>; state=16 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_via: end of header reached, state=5 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: via found, flags=2 localhost /usr/local/sbin/kamailio[3075]: DBG:core:parse_headers: this is the first via localhost /usr/local/sbin/kamailio[3075]: DBG:core:receive_msg: After parse_msg...
Regards, Vikram.
Hi!
Never did recording, but just:
1. try without recording and make sure that the stream really is relayed via rtpproxy (tcpdump, ngrep). Your logs only show the initialization of nathelper module, contacting rtpproxy during startup. It does not show any call that is relayed.
2. only if above is verified and works well, add the start_recording() command to you configuration. I think start_recording() should be called after force_rtpproxy.
regards klaus
Am 19.03.2010 16:13, schrieb Hector.Ortiz@swisscom.com:
Hi
I've tried without recording but I don't see anything in the logs that indicate that the stream is being relayed. I suppose it is relaying because if I comment out the rtpproxy related functions (force_rtpproxy) in my configuration file I don't hear anything, whereas if they are uncommented I can hear audio. How can I troubleshoot this? I've done tcpdump on port 7890 on my local interface and nothing is shown in the dump.
Thanks for any pointers that help me solve my issue
Héctor
-----Original Message----- From: Klaus Darilion [mailto:klaus.mailinglists@pernau.at] Sent: Montag, 22. März 2010 10:18 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Hi!
Never did recording, but just:
1. try without recording and make sure that the stream really is relayed via rtpproxy (tcpdump, ngrep). Your logs only show the initialization of nathelper module, contacting rtpproxy during startup. It does not show any call that is relayed.
2. only if above is verified and works well, add the start_recording() command to you configuration. I think start_recording() should be called after force_rtpproxy.
regards klaus
Am 19.03.2010 16:13, schrieb Hector.Ortiz@swisscom.com:
I mean, I've done all that before but I don't see anything besides the SIP traffic and DNS queries.
Héctor
-----Original Message----- From: Klaus Darilion [mailto:klaus.mailinglists@pernau.at] Sent: Dienstag, 23. März 2010 09:20 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
of course "tcpdump -n udp" works too if you do not have ngrep around (e.g. Centos)
klaus
Am 23.03.2010 09:12, schrieb Hector.Ortiz@swisscom.com:
I have two interfaces in my system, namely eth0=192.168.35.36 and eth1=192.168.34.1. The IP address of the SIP gw I route the calls through is 192.168.128.61 and I see the following in my SIP messages:
U 192.168.34.1:5060 -> 192.168.128.61:5060 INVITE sip:0315080190@192.168.128.61 SIP/2.0. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.0. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-e3302bd1. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 INVITE. Max-Forwards: 69. Contact: "0315080180" sip:0315080180@195.176.213.123:5060. Expires: 240. User-Agent: Sipura/SPA921-4.1.10(b). Content-Length: 405. Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER. Content-Type: application/sdp. . v=0. o=- 33884516 33884516 IN IP4 195.176.213.123. s=-. c=IN IP4 195.176.213.123. t=0 0. m=audio 16408 RTP/AVP 0 2 4 8 18 96 97 98 101. a=rtpmap:0 PCMU/8000. a=rtpmap:2 G726-32/8000. a=rtpmap:4 G723/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:18 G729a/8000. a=rtpmap:96 G726-40/8000. a=rtpmap:97 G726-24/8000. a=rtpmap:98 G726-16/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-15. a=ptime:30. a=sendrecv.
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-e3302bd1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. .
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 183 Session Progress. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-e3302bd1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE. Content-Type: application/sdp. Content-Length: 186. . v=0. o=- 227955333206264 1 IN IP4 192.168.128.61. s=-. c=IN IP4 192.168.128.61. t=0 0. m=audio 11896 RTP/AVP 0 101. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16.
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-e3302bd1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE. Content-Type: application/sdp. Content-Length: 186. . v=0. o=- 227955333206264 1 IN IP4 192.168.128.61. s=-. c=IN IP4 192.168.128.61. t=0 0. m=audio 11896 RTP/AVP 0 101. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16.
U 192.168.34.1:5060 -> 192.168.128.61:5060 ACK sip:gw01@192.168.128.61:5060 SIP/2.0. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.2. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-5db71ced. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 ACK. Max-Forwards: 69. Contact: "0315080180" sip:0315080180@195.176.213.123:5060. User-Agent: Sipura/SPA921-4.1.10(b). Content-Length: 0. .
U 192.168.128.61:5060 -> 192.168.34.1:5060 SIP/2.0 200 OK. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.0;received=192.168.34.1. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-e3302bd1. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 INVITE. User-Agent: Netstream VoIP Gateway. Contact: sip:gw01@192.168.128.61:5060. Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,INFO,REFER,SUBSCRIBE. Content-Type: application/sdp. Content-Length: 186. . v=0. o=- 227955333206264 1 IN IP4 192.168.128.61. s=-. c=IN IP4 192.168.128.61. t=0 0. m=audio 11896 RTP/AVP 0 101. a=rtpmap:0 PCMU/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16.
U 192.168.34.1:5060 -> 192.168.128.61:5060 ACK sip:gw01@192.168.128.61:5060 SIP/2.0. Record-Route: sip:192.168.34.1;r2=on;lr=on. Record-Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.34.1;branch=z9hG4bK032.3ab7d891.2. Via: SIP/2.0/UDP 195.176.213.123:5060;rport=5060;branch=z9hG4bK-5db71ced. From: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. To: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 101 ACK. Max-Forwards: 69. Contact: "0315080180" sip:0315080180@195.176.213.123:5060. User-Agent: Sipura/SPA921-4.1.10(b). Content-Length: 0. .
U 192.168.128.61:5060 -> 192.168.34.1:5060 BYE sip:0315080180@195.176.213.123:5060 SIP/2.0. Route: sip:192.168.34.1;r2=on;lr=on. Route: sip:192.168.35.36;r2=on;lr=on. Via: SIP/2.0/UDP 192.168.128.61:5060;branch=z9hG4bKf9950048a0e92731fde06540. Max-Forwards: 70. From: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. To: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 1 BYE. User-Agent: Netstream VoIP Gateway. .
U 192.168.34.1:5060 -> 192.168.128.61:5060 SIP/2.0 200 OK. To: "0315080180" sip:0315080180@192.168.35.36;tag=7554c9a2d2a2ea9o0. From: sip:0315080190@192.168.35.36;tag=f9950048baf0ac43fde06574. Call-ID: d26aabd6-6189205@192.168.0.2. CSeq: 1 BYE. Via: SIP/2.0/UDP 192.168.128.61:5060;rport=5060;branch=z9hG4bKf9950048a0e92731fde06540. Record-Route: sip:192.168.35.36;r2=on;lr=on. Record-Route: sip:192.168.34.1;r2=on;lr=on. Server: Sipura/SPA921-4.1.10(b). Content-Length: 0.
The first message hasn't rewritten the IP address, the rest have the IP address of my SIP gw so I guess rtpproxy isn't enforced then, but if so, why can I hear then the audio?
Following are the parts of my config file where I call the function force_rtp_proxy
route[6] { xlog("L_INFO", "ROUTE 6"); # NAT handling # Set reply routing block, to which control is passed after a transaction # completed with a negative result but before sending a final reply t_on_failure("1"); # Check if we're NATed if (isflagset(5) || isbflagset(6)) { # Use rtpproxy force_rtp_proxy(); } # Set reply routing block, to which control is passed each time a reply # (provisional or final) for the transaction is received t_on_reply("1"); }
onreply_route[1] { xlog("L_INFO", "ONREPLY_ROUTE"); if ((isflagset(5) || isbflagset(6)) && status=~"(180)|(183)|(2[0-9][0-9])") { xlog("L_INFO", "NAT'd TRANSACTION"); fix_nated_contact(); force_rtp_proxy(); } else if (nat_uac_test("1")) { fix_nated_contact(); } exit; }
How can I then troubleshoot that it is really enforcing it?
Thanks four your help
Héctor
-----Original Message----- From: Klaus Darilion [mailto:klaus.mailinglists@pernau.at] Sent: Dienstag, 23. März 2010 09:34 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Then I guess that rtpproxy is not enforced.
Take a look at the SDP of the outgoing SIP messages if the IP address in the c= line is rewritten or not.
regards klaus
Am 23.03.2010 09:25, schrieb Hector.Ortiz@swisscom.com:
Am 23.03.2010 09:57, schrieb Hector.Ortiz@swisscom.com:
How can I then troubleshoot that it is really enforcing it?
You have to put xlog() statements in your config (e.g. after an if () statement in the blocks) and then watch syslog for the xlog messages - this is the way how you trace how a message is processed by the script.
btw: if you always want to enforce the media relay then remove the if() conditions before the force_rtp_proxy calls.
klaus
Hi, I solved my issue. There was nothing wrong with my configuration.
RTPProxy wasn't being enforced because the SIP Phone wasn't being detected as being behind NAT.
I disabled SIP ALG on my ADSL Modem and now RTPProxy is being enforced and I'm able to do the recording. Now I have to find out how can I play the stored audio.
Thanks for your help
Héctor
-----Original Message----- From: Klaus Darilion [mailto:klaus.mailinglists@pernau.at] Sent: Dienstag, 23. März 2010 16:01 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Am 23.03.2010 09:57, schrieb Hector.Ortiz@swisscom.com:
How can I then troubleshoot that it is really enforcing it?
You have to put xlog() statements in your config (e.g. after an if () statement in the blocks) and then watch syslog for the xlog messages - this is the way how you trace how a message is processed by the script.
btw: if you always want to enforce the media relay then remove the if() conditions before the force_rtp_proxy calls.
klaus
Am 26.03.2010 12:15, schrieb Hector.Ortiz@swisscom.com:
Hi, I solved my issue. There was nothing wrong with my configuration.
RTPProxy wasn't being enforced because the SIP Phone wasn't being detected as being behind NAT.
This is why I always remove NAT-detection as I want the rtpproxy in all cases.
regards klaus
Just out of curiosity, could you please share your config file?
If I don't do the NAT detection and try using the function force_rtp_proxy and cannot hear sound in any direction, the called gets disconnected and see the following in the log
Mar 26 14:15:11 openser /usr/sbin/openser[19389]: ONREPLY_ROUTE Mar 26 14:15:11 openser /usr/sbin/openser[19389]: ERROR:nathelper:extract_body: message body has length zero Mar 26 14:15:11 openser /usr/sbin/openser[19389]: ERROR:nathelper:force_rtp_proxy2_f: can't extract body from the message
Regards
Héctor
-----Original Message----- From: Klaus Darilion [mailto:klaus.mailinglists@pernau.at] Sent: Freitag, 26. März 2010 14:08 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Am 26.03.2010 12:15, schrieb Hector.Ortiz@swisscom.com:
Hi, I solved my issue. There was nothing wrong with my configuration.
RTPProxy wasn't being enforced because the SIP Phone wasn't being detected as being behind NAT.
This is why I always remove NAT-detection as I want the rtpproxy in all cases.
regards klaus
Vikram
Thanks, that solved that problem but now I can only hear audio in one direction and here is what I see in the log
Mar 26 16:11:43 openser rtpproxy[30827]: DBUG:handle_command: received command "21119_2 U 1de249c9-f1fbbfa@192.168.0.3 195.176.213.123 16476 a489077dc86f9d6o0;1" Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_command: new session 1de249c9-f1fbbfa@192.168.0.3, tag a489077dc86f9d6o0;1 requested, type strong Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_command: new session on a port 60268 created, tag a489077dc86f9d6o0;1 Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_copy: starting recording RTP session on port 60268 Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_copy: starting recording RTCP session on port 60269 Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_copy: starting recording RTP session on port 0 Mar 26 16:11:43 openser /usr/sbin/openser[21119]: ROUTE 4 Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_copy: starting recording RTCP session on port 0 Mar 26 16:11:43 openser rtpproxy[30827]: INFO:handle_command: pre-filling caller's address with 195.176.213.123:16476 Mar 26 16:11:43 openser rtpproxy[30827]: DBUG:doreply: sending reply "21119_2 60268 217.193.160.45 " Mar 26 16:11:43 openser /usr/sbin/openser[21119]: ROUTE 1 Mar 26 16:11:43 openser /usr/sbin/openser[21123]: ONREPLY_ROUTE Mar 26 16:11:44 openser /usr/sbin/openser[21124]: ONREPLY_ROUTE Mar 26 16:11:44 openser rtpproxy[30827]: DBUG:handle_command: received command "21124_2 L 1de249c9-f1fbbfa@192.168.0.3 62.65.128.61 12026 a489077dc86f9d6o0;1 f99504f8b00f1bd3fdfde331;1" Mar 26 16:11:44 openser rtpproxy[30827]: INFO:handle_command: lookup on ports 60268/37082, session timer restarted Mar 26 16:11:44 openser rtpproxy[30827]: INFO:handle_command: pre-filling callee's address with 62.65.128.61:12026 Mar 26 16:11:44 openser rtpproxy[30827]: DBUG:doreply: sending reply "21124_2 37082 217.193.160.45 " Mar 26 16:11:44 openser /usr/sbin/openser[21121]: ROUTE_3^M Mar 26 16:11:48 openser /usr/sbin/openser[21120]: ROUTE_3^M Mar 26 16:11:49 openser /usr/sbin/openser[21126]: ONREPLY_ROUTE Mar 26 16:11:49 openser rtpproxy[30827]: DBUG:handle_command: received command "21126_2 L 1de249c9-f1fbbfa@192.168.0.3 62.65.128.61 12026 a489077dc86f9d6o0;1 f99504f8b00f1bd3fdfde331;1" Mar 26 16:11:49 openser rtpproxy[30827]: INFO:handle_command: lookup on ports 60268/37082, session timer restarted Mar 26 16:11:49 openser rtpproxy[30827]: DBUG:doreply: sending reply "21126_2 37082 217.193.160.45 " Mar 26 16:11:49 openser /usr/sbin/openser[21122]: ACCOUNTING START Mar 26 16:11:49 openser /usr/sbin/openser[21122]: ACC: request accounted: timestamp=1269616309;method=ACK;from_tag=a489077dc86f9d6o0;to_tag=f99504f8b00f1bd3fdfde331;call_id=1de249c9-f1fbbfa@192.168.0.3;code=200;reason=ok Mar 26 16:11:49 openser /usr/sbin/openser[21122]: ROUTE 1 Mar 26 16:12:02 openser /usr/sbin/openser[21123]: ACCOUNTING STOP Mar 26 16:12:02 openser /usr/sbin/openser[21123]: ACC: request accounted: timestamp=1269616322;method=BYE;from_tag=f99504f8b00f1bd3fdfde331;to_tag=a489077dc86f9d6o0;call_id=1de249c9-f1fbbfa@192.168.0.3;code=200;reason=ok Mar 26 16:12:02 openser /usr/sbin/openser[21123]: ROUTE 1 Mar 26 16:13:03 openser rtpproxy[30827]: INFO:process_rtp: session timeout Mar 26 16:13:03 openser rtpproxy[30827]: INFO:remove_session: RTP stats: 587 in from callee, 0 in from caller, 587 relayed, 0 dropped Mar 26 16:13:03 openser rtpproxy[30827]: INFO:remove_session: RTCP stats: 0 in from callee, 0 in from caller, 0 relayed, 0 dropped Mar 26 16:13:03 openser rtpproxy[30827]: INFO:remove_session: session on ports 60268/37082 is cleaned up
I don't see any error messages. Any pointers?
Héctor
-----Original Message----- From: Vikram Ragukumar [mailto:vragukumar@signalogic.com] Sent: Freitag, 26. März 2010 15:49 To: Ortiz Héctor, SCS-SIS-ICC-SPC-SBU Cc: klaus.mailinglists@pernau.at; users@lists.kamailio.org Subject: Re: [Kamailio-Users] Recording RTP session
Hector,
From the log it appears that you are trying to read the SDP from a SIP message that does not contain an SDP. You might have to qualify your force_rtp_proxy() call with an appropriate 'if' statement.
Regards, Vikram.
Hector,
Seems like rtpproxy is allocating an rtp session properly. However rtpproxy's stats show that there are no RTP packets from the caller. I would recommend using wireshark or tcpdump, and (a) Verifying the connection address in the SDP for messages leaving the proxy (b) Make sure RTP packets are actually coming into the proxy from both endpoints.
Regards, Vikram.
-
Hector.Ortiz＠swisscom.com -
Klaus Darilion -
Vikram Ragukumar