RTPPROXY shutdown at each call
Locked
 
|
This post was updated on .
Hi all, I am implementing my first OpenSIPS with RTPPROXY so, for sure, any issue is related to my NOT-Knowledge!! :-)
Issue is follow: each time I make a call ( from USERA to USERB, for instance ) RTPPROXY shuts down immediatly. Here there are logs and config: RTPPROXY STARTED WITH: rtpproxy -F -s udp:127.0.0.1:7890 -l 10.9.23.41/151.x.x.201 -d DBUG:LOG_LOCAL2 10.9.23.41=Internal IP (eth0:1) 151.x.x.201=External IP (eth0) STARTING SERVER: Sep 4 16:12:20 opensips opensips: DBG:core:yyparse: loading module /usr/local/opensips_proxy/lib/opensips/modules/rtpproxy.so Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: rtpproxy matches module rtpproxy Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: found <rtpproxy_sock> in module rtpproxy [/usr/local/opensips_proxy/lib/opensips/modules/] Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: rtpproxy matches module rtpproxy Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: found <rtpproxy_autobridge> in module rtpproxy [/usr/local/opensips_proxy/lib/opensips/modules/] Sep 4 16:12:20 opensips opensips: DBG:core:find_cmd_export_t: found <rtpproxy_offer>(1) in module rtpproxy [/usr/local/opensips_proxy/lib/opensips/modules/] Sep 4 16:12:20 opensips opensips: DBG:core:find_cmd_export_t: found <rtpproxy_answer>(1) in module rtpproxy [/usr/local/opensips_proxy/lib/opensips/modules/] Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:core:init_mod: initializing module rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:rtpproxy:add_rtpproxy_socks: url is udp:127.0.0.1:7890, len is 18 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:core:init_mod: register MI for rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:core:fix_actions: fixing rtpproxy_offer, line 486 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:core:fix_actions: fixing rtpproxy_answer, line 516 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: DBG:core:init_mod_child: type=CHILD, rank=2, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: DBG:core:init_mod_child: type=PROC_MODULE, rank=-2, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: DBG:core:init_mod_child: type=CHILD, rank=3, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: DBG:core:init_mod_child: type=CHILD, rank=4, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: DBG:core:init_mod_child: type=CHILD, rank=5, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: DBG:core:init_mod_child: type=CHILD, rank=1, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: DBG:core:init_mod_child: type=CHILD, rank=6, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: DBG:core:init_mod_child: type=CHILD, rank=8, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: DBG:core:init_mod_child: type=PROC_MAIN, rank=0, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: DBG:core:init_mod_child: type=CHILD, rank=7, module=rtpproxy Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1 > 0) Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: INFO:rtpproxy:rtpp_test: rtp proxy <udp:127.0.0.1:7890> found, support for it enabled Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19721]: DBG:core:init_mod_child: type=PROC_TCP_MAIN, rank=-4, module=rtpproxy MADE CALL: Sep 4 17:17:00 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 4 17:17:00 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 4 17:17:00 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 39 Sep 4 17:17:00 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 100, get_ticks = 40 Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1295]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 4 17:17:01 opensips /usr/local/opensips_proxy/sbin/opensips[1293]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 4 17:17:06 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 4 17:17:06 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 4 17:17:06 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 100, get_ticks = 45 Sep 4 17:17:06 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 4 17:17:06 opensips /usr/local/opensips_proxy/sbin/opensips[1292]: ERROR:rtpproxy:force_rtp_proxy: no available proxies root@opensips:~# netstat -tanpu | grep 7890 udp 0 0 127.0.0.1:52275 127.0.0.1:7890 ESTABLISHED 906/opensips udp 0 0 127.0.0.1:53814 127.0.0.1:7890 ESTABLISHED 912/opensips udp 0 0 127.0.0.1:46903 127.0.0.1:7890 ESTABLISHED 911/opensips udp 0 0 127.0.0.1:52799 127.0.0.1:7890 ESTABLISHED 914/opensips udp 0 0 127.0.0.1:57936 127.0.0.1:7890 ESTABLISHED 915/opensips udp 0 0 127.0.0.1:7890 0.0.0.0:* 712/rtpproxy udp 0 0 127.0.0.1:50773 127.0.0.1:7890 ESTABLISHED 910/opensips udp 0 0 127.0.0.1:47838 127.0.0.1:7890 ESTABLISHED 908/opensips udp 0 0 127.0.0.1:39021 127.0.0.1:7890 ESTABLISHED 907/opensips udp 0 0 127.0.0.1:39163 127.0.0.1:7890 ESTABLISHED 904/opensips udp 0 0 127.0.0.1:52373 127.0.0.1:7890 ESTABLISHED 913/opensips udp 0 0 127.0.0.1:34339 127.0.0.1:7890 ESTABLISHED 905/opensips OPENSIPS CONFIG: #### NAT module loadmodule "nathelper.so" modparam("nathelper", "natping_interval", 5) modparam("nathelper", "ping_nated_only", 1) modparam("nathelper", "received_avp", "$avp(received_nh)") modparam("nathelper", "sipping_bflag", 7) modparam("nathelper", "sipping_from", "sip:NAT_Pinger@10.9.23.41:5060") #### RTPProxy module loadmodule "rtpproxy.so" modparam("rtpproxy", "rtpproxy_sock", "udp:127.0.0.1:7890") modparam("rtpproxy", "rtpproxy_autobridge", 1) Can someone point me in a right way? Thanks. |
|
|
Hi, can someone help me?
|
Re: RTPPROXY shutdown at each call
|
In reply to this post by Spady#7
Hi,
As I assume RTPproxy is running when you start opensips (I see opensips successfully detected rtpproxy at startup), check if after the call attempt rtpproxy is still running or not (as process) Regards, Bogdan-Andrei Iancu OpenSIPS Founder and Developer http://www.opensips-solutions.com On 09/04/2012 06:19 PM, spady wrote: > Hi all, I am implementing my first OpenSIPS with RTPPROXY so, for sure, any > issue is related to my NOT-Knowledge!! :-) > > Issue is follow: > each time I make a call ( from USERA to USERB, for instance ) RTPPROXY shuts > down immediatly. > Here there are logs and config: > > > STARTING SERVER: > > Sep 4 16:12:20 opensips opensips: DBG:core:yyparse: loading module > /usr/local/opensips_proxy/lib/opensips/modules/rtpproxy.so > Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: rtpproxy > matches module rtpproxy > Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: found > <rtpproxy_sock> in module rtpproxy > [/usr/local/opensips_proxy/lib/opensips/modules/] > Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: rtpproxy > matches module rtpproxy > Sep 4 16:12:20 opensips opensips: DBG:core:set_mod_param_regex: found > <rtpproxy_autobridge> in module rtpproxy > [/usr/local/opensips_proxy/lib/opensips/modules/] > Sep 4 16:12:20 opensips opensips: DBG:core:find_cmd_export_t: found > <rtpproxy_offer>(1) in module rtpproxy > [/usr/local/opensips_proxy/lib/opensips/modules/] > Sep 4 16:12:20 opensips opensips: DBG:core:find_cmd_export_t: found > <rtpproxy_answer>(1) in module rtpproxy > [/usr/local/opensips_proxy/lib/opensips/modules/] > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:core:init_mod: initializing module rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:rtpproxy:add_rtpproxy_socks: url is udp:127.0.0.1:7890, len is 18 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:core:init_mod: register MI for rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:core:fix_actions: fixing rtpproxy_offer, line 486 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:core:fix_actions: fixing rtpproxy_answer, line 516 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > DBG:core:init_mod_child: type=CHILD, rank=2, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > DBG:core:init_mod_child: type=PROC_MODULE, rank=-2, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > DBG:core:init_mod_child: type=CHILD, rank=3, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19708]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > DBG:core:init_mod_child: type=CHILD, rank=4, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19710]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > DBG:core:init_mod_child: type=CHILD, rank=5, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19716]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:core:init_mod_child: type=CHILD, rank=1, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > DBG:core:init_mod_child: type=PROC_TIMER, rank=-1, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19715]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19714]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > DBG:core:init_mod_child: type=CHILD, rank=6, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19717]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > DBG:core:init_mod_child: type=CHILD, rank=8, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19719]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19707]: > DBG:core:init_mod_child: type=PROC_MAIN, rank=0, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > DBG:core:init_mod_child: type=CHILD, rank=7, module=rtpproxy > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > DBG:rtpproxy:connect_rtpproxies: [RTPProxy] set list 0xaee30b0c > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > DBG:rtpproxy:connect_rtpproxies: [Re]connecting sockets (1> 0) > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > DBG:rtpproxy:connect_rtpproxies: connected 127.0.0.1:7890 > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > INFO:rtpproxy:rtpp_test: rtp proxy<udp:127.0.0.1:7890> found, support for > it enabled > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19718]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:20 opensips /usr/local/opensips_proxy/sbin/opensips[19721]: > DBG:core:init_mod_child: type=PROC_TCP_MAIN, rank=-4, module=rtpproxy > > > > MADE CALL: > > Sep 4 16:12:50 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1<ro> and param2 > <none> > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy > Connection refused > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > ERROR:rtpproxy:send_rtpp_command: proxy<udp:127.0.0.1:7890> does not > respond, disable it > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > DBG:rtpproxy:raise_rtpproxy_event: no event sent > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19709]: > ERROR:rtpproxy:force_rtp_proxy_body: no available proxies > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > ERROR:rtpproxy:force_rtp_proxy: Unable to parse body > Sep 4 16:12:51 opensips /usr/local/opensips_proxy/sbin/opensips[19711]: > ERROR:rtpproxy:force_rtp_proxy: Unable to parse body > Sep 4 16:12:54 opensips /usr/local/opensips_proxy/sbin/opensips[19712]: > ERROR:rtpproxy:force_rtp_proxy: Unable to parse body > > > > OPENSIPS CONFIG: > > > > #### NAT module > loadmodule "nathelper.so" > modparam("nathelper", "natping_interval", 5) > modparam("nathelper", "ping_nated_only", 1) > modparam("nathelper", "received_avp", "$avp(received_nh)") > modparam("nathelper", "sipping_bflag", 7) > modparam("nathelper", "sipping_from", "sip:NAT_Pinger@10.9.23.41:5060") > > > #### RTPProxy module > loadmodule "rtpproxy.so" > modparam("rtpproxy", "rtpproxy_sock", "udp:127.0.0.1:7890") > modparam("rtpproxy", "rtpproxy_autobridge", 1) > > > > Can someone point me in a right way? > Thanks. > > > > > > -- > View this message in context: http://opensips-open-sip-server.1449251.n2.nabble.com/RTPPROXY-shutdown-at-each-call-tp7581647.html > Sent from the OpenSIPS - Users mailing list archive at Nabble.com. > > _______________________________________________ > Users mailing list > [hidden email] > http://lists.opensips.org/cgi-bin/mailman/listinfo/users > _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
Hi Bogdan,
NO, after made call rtpproxy is no more running!!! |
|
|
Hi,
Can you share how did you start the rtpproxy !? what is your /etc/default/rtpproxy file if you are using lsb script to start rtpproxy. Also I suspect that your rtpproxy is crashing when you make a call.
Regards, Sammy On Thu, Sep 6, 2012 at 11:56 AM, spady <[hidden email]> wrote: Hi Bogdan, _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
Hi Sam,
i've not created a /etc/init.d/rtpproxy file!! Have I to create manually or is inside rtpproxy's installation dir? Btw, as wrote above, I start RTPP. by using this command: rtpproxy -F -s udp:127.0.0.1:7890 -l 10.9.23.41/151.x.x.201 -d DBUG:LOG_LOCAL2 and also Yes, it crash when i make a call!! Any idea? |
|
|
Hi,
In most of the cases as your's the issue lies here "-l 10.9.23.41/151.x.x.201" , now since you are putting a "/" in between the two interface addresses it seems fine so far. How are you calling the media-proxy function in your opensips.cfg script ? Are you using the "i" and "e" flags properly ?
A few lines from the rtpproxy log would help as well. BR Sammy On Thu, Sep 6, 2012 at 12:04 PM, spady <[hidden email]> wrote: Hi Sam, _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
Re: RTPPROXY shutdown at each call
|
|
In reply to this post by Spady#7
And do you see any errors / logs from rtpproxy into syslog ?
Regards, Bogdan-Andrei Iancu OpenSIPS Founder and Developer http://www.opensips-solutions.com On 09/06/2012 10:56 AM, spady wrote: > Hi Bogdan, > NO, after made call rtpproxy is no more running!!! > > > > -- > View this message in context: http://opensips-open-sip-server.1449251.n2.nabble.com/RTPPROXY-shutdown-at-each-call-tp7581647p7581679.html > Sent from the OpenSIPS - Users mailing list archive at Nabble.com. > > _______________________________________________ > Users mailing list > [hidden email] > http://lists.opensips.org/cgi-bin/mailman/listinfo/users > _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
This post has NOT been accepted by the mailing list yet.
Hi, here is my Opensips.cfg
# # $Id: opensips_residential.m4 9042 2012-05-17 13:57:10Z vladut-paiu $ # # OpenSIPS residential configuration script # by OpenSIPS Solutions <team@opensips-solutions.com> # # This script was generated via "make menuconfig", from # the "Residential" scenario. # You can enable / disable more features / functionalities by # re-generating the scenario with different options.# # # Please refer to the Core CookBook at: # http://www.opensips.org/Resources/DocsCookbooks # for a explanation of possible statements, functions and parameters. # ####### Global Parameters ######### debug=8 log_stderror=no log_facility=LOG_LOCAL1 fork=yes children=4 /* uncomment the following lines to enable debugging */ #debug=6 #fork=no #log_stderror=yes /* uncomment the next line to enable the auto temporary blacklisting of not available destinations (default disabled) */ #disable_dns_blacklist=no /* uncomment the next line to enable IPv6 lookup after IPv4 dns lookup failures (default disabled) */ #dns_try_ipv6=yes /* comment the next line to enable the auto discovery of local aliases based on revers DNS on IPs */ auto_aliases=no listen=udp:10.9.23.41:5060 # CUSTOMIZE ME listen=udp:151.8.12.201:5060 disable_tcp=no listen=tcp:10.9.23.41:5060 # CUSTOMIZE ME listen=tcp:151.8.12.201:5060 disable_tls=yes server_header="Server: Lw-OpenSips Video Proxy" server_signature=yes user_agent_header="User-Agent: Lw-OpenSips Video Proxy" sip_warning=0 ##by Antonio S. (0=No; 1=Si ) Aggiunge l'header "WARNING" in ogni risposta da parte di OPENSIPS. Utile per il DEBUG ####################################################### # ----------------- Modules Section ----------------- # ####################################################### #set module path mpath="/usr/local/opensips_proxy/lib/opensips/modules/" #### SIGNALING module loadmodule "signaling.so" #### StateLess module loadmodule "sl.so" #### Transaction Module loadmodule "tm.so" modparam("tm", "fr_timer", 5) modparam("tm", "fr_inv_timer", 30) modparam("tm", "restart_fr_on_each_reply", 0) modparam("tm", "onreply_avp_mode", 1) #### Record Route Module loadmodule "rr.so" /* do not append from tag to the RR (no need for this script) */ modparam("rr", "append_fromtag", 0) #### MAX ForWarD module loadmodule "maxfwd.so" #### SIP MSG OPerationS module loadmodule "sipmsgops.so" #### FIFO Management Interface loadmodule "mi_fifo.so" modparam("mi_fifo", "fifo_name", "/tmp/opensips_fifo") modparam("mi_fifo", "fifo_mode", 0666) #### URI module loadmodule "uri.so" modparam("uri", "use_uri_table", 0) modparam("uri", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") #### MYSQL module loadmodule "db_mysql.so" #### USeR LOCation module loadmodule "usrloc.so" modparam("usrloc", "nat_bflag", 10) modparam("usrloc", "db_mode", 2) modparam("usrloc", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### REGISTRAR module loadmodule "registrar.so" modparam("registrar", "tcp_persistent_flag", 7) modparam("registrar", "received_avp", "$avp(received_nh)") /* uncomment the next line not to allow more than 10 contacts per AOR */ #modparam("registrar", "max_contacts", 10) #### TEXTOPS module loadmodule "textops.so" #### ACCounting module loadmodule "acc.so" /* what special events should be accounted ? */ modparam("acc", "early_media", 0) modparam("acc", "report_cancels", 0) /* by default we do not adjust the direct of the sequential requests. if you enable this parameter, be sure the enable "append_fromtag" in "rr" module */ modparam("acc", "detect_direction", 0) modparam("acc", "failed_transaction_flag", 3) /* account triggers (flags) */ modparam("acc", "db_flag", 1) modparam("acc", "db_missed_flag", 2) modparam("acc", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### AUTHentication modules loadmodule "auth.so" loadmodule "auth_db.so" modparam("auth_db", "calculate_ha1", yes) modparam("auth_db", "password_column", "password") modparam("auth_db", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME modparam("auth_db", "load_credentials", "") #### ALIAS module loadmodule "alias_db.so" modparam("alias_db", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### DOMAIN module loadmodule "domain.so" modparam("domain", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME modparam("domain", "db_mode", 1) # Use caching modparam("auth_db|usrloc|uri", "use_domain", 1) #### DIALOG module loadmodule "dialog.so" modparam("dialog", "dlg_match_mode", 1) modparam("dialog", "default_timeout", 21600) # 6 hours timeout modparam("dialog", "db_mode", 2) modparam("dialog", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### AVP module loadmodule "avpops.so" modparam("avpops", "avp_table", "usr_preferences") modparam("avpops", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") #### NAT module loadmodule "nathelper.so" modparam("nathelper", "natping_interval", 5) modparam("nathelper", "ping_nated_only", 1) modparam("nathelper", "received_avp", "$avp(received_nh)") modparam("nathelper", "sipping_bflag", 7) modparam("nathelper", "sipping_from", "sip:NAT_Pinger@10.9.23.41:5060") #### RTPProxy module loadmodule "rtpproxy.so" modparam("rtpproxy", "rtpproxy_sock", "udp:127.0.0.1:7890") # CUSTOMIZE ME modparam("rtpproxy", "rtpproxy_autobridge", 1) #### DIALPLAN module loadmodule "dialplan.so" modparam("dialplan", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### DYNAMMIC ROUTING module loadmodule "drouting.so" modparam("drouting", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") # CUSTOMIZE ME #### SIP_TRACE_AGENT (Homer) ##by Antonio S. loadmodule "siptrace.so" modparam("siptrace", "db_url", "mysql://opensips:opensipsrw@localhost/opensips") modparam("siptrace", "duplicate_uri", "sip:10.9.101.168:9060") modparam("siptrace", "duplicate_with_hep", 1) modparam("siptrace", "trace_to_database", 0) modparam("siptrace", "trace_flag", 22) modparam("siptrace", "trace_on", 1) modparam("siptrace", "hep_version", 2) #HEPv2 == timestamp will be included to HEP header ##################################################### # ----------------- Routing Logic ----------------- # ##################################################### # main request routing logic route{ if (!mf_process_maxfwd_header("10")) { send_reply("483","Too Many Hops"); exit; } #---- NAT Detection ----# force_rport(); if (nat_uac_test("19")) { if (is_method("REGISTER")) { fix_nated_register(); } else { fix_nated_contact(); #---- Insert nat=yes at the end of the Contact header ----# #---- This helps with REINVITEs, ----# #--- nat=yes will be included in the R-URI for sequential requests ---# search_append('Contact:.*sip:[^>[:cntrl:]]*', ';nat=yes'); } setflag(10); } ######################################### #----- Sequential requests section -----# ######################################### if (has_totag()) { # sequential request withing a dialog should # take the path determined by record-routing if (loose_route()) { # validate the sequential request against dialog if ( $DLG_status!=NULL && !validate_dialog() ) { xlog("In-Dialog $rm from $si (callid=$ci) is not valid according to dialog\n"); ## exit; } if (is_method("BYE")) { setflag(1); # do accounting ... setflag(3); # ... even if the transaction fails } else if (is_method("INVITE")) { # even if in most of the cases is useless, do RR for # re-INVITEs alos, as some buggy clients do change route set # during the dialog. record_route(); } if (check_route_param("nat=yes")) setflag(10); # route it out to whatever destination was set by loose_route() # in $du (destination URI). route(1); } else { if ( is_method("ACK") ) { if ( t_check_trans() ) { # non loose-route, but stateful ACK; must be an ACK after # a 487 or e.g. 404 from upstream server t_relay(); exit; } else { # ACK without matching transaction -> # ignore and discard exit; } } sl_send_reply("404","Not here"); } exit; } ###################################### #----- Initial requests section -----# ###################################### # CANCEL processing if (is_method("CANCEL")) { if (t_check_trans()) t_relay(); exit; } #---- catch retransmissions ----# t_check_trans(); if ( !(is_method("REGISTER") || is_from_gw() ) ) { if (is_from_local()) { # authenticate if from local subscriber # authenticate all initial non-REGISTER request that pretend to be # generated by local subscriber (domain from FROM URI is local) if (!proxy_authorize("", "subscriber")) { proxy_challenge("", "0"); exit; } if (!db_check_from()) { sl_send_reply("403","Forbidden auth ID"); exit; } consume_credentials(); # caller authenticated } else { # if caller is not local, then called number must be local if (!is_uri_host_local()) { send_reply("403","Rely forbidden"); exit; } } } ###################################### #----- Preloaded Route Checking -----# ###################################### if (loose_route()) { ## Alcuni UAC aggiungono l'header "route" al primo INVITE, se ad es settano un outbound proxy!! xlog("L_ERR", "Attempt to route with preloaded Route's [$fu/$tu/$ru/$ci]"); if (!is_method("ACK")) sl_send_reply("403","Preload Route denied"); exit; } # record routing if (!is_method("REGISTER|MESSAGE")) record_route(); # account only INVITEs if (is_method("INVITE")) { # create dialog with timeout if ( !create_dialog("B") ) { send_reply("500","Internal Server Error"); exit; } setflag(1); # do accounting } if (!is_uri_host_local()) { append_hf("P-hint: outbound\r\n"); route(1); } # requests for my domain if (is_method("PUBLISH")) { sl_send_reply("503", "Service Unavailable"); exit; } #--- registration handling ----# if (is_method("REGISTER")) { # authenticate the REGISTER requests if (!www_authorize("", "subscriber")) { www_challenge("", "0"); exit; } if (!db_check_to()) { sl_send_reply("403","Forbidden auth ID"); exit; } if ( proto==TCP || 0 ) setflag(7); if (!save("location")) sl_reply_error(); exit; } #---- Request is behind NAT(flag5) save with bflag 6 ----# #---- Use bflag 7 to start SIP pinging (Options) ----# if (isflagset(5)) { setbflag(6); setbflag(7); }; if ($rU==NULL) { # request with no Username in RURI sl_send_reply("484","Address Incomplete"); exit; } # apply DB based aliases alias_db_lookup("dbaliases"); # apply transformations from dialplan table dp_translate("0","$rU/$rU"); if ($rU=~"^\+[1-9][0-9]+$") { if (!do_routing("0")) { send_reply("500","No PSTN Route found"); exit; } route(1); exit; } # do lookup with method filtering if (!lookup("location","m")) { if (!db_does_uri_exist()) { send_reply("420","Bad Extension"); exit; } t_newtran(); t_reply("404", "Not Found"); exit; } if (isbflagset(10)) setflag(10); # when routing via usrloc, log the missed calls also setflag(2); route(1); } ###################### # ----- Routes ----- # ###################### route[1] { # for INVITEs enable some additional helper routes if (is_method("INVITE")) { if (isflagset(10)) { rtpproxy_offer("ro"); } t_on_branch("2"); t_on_reply("2"); t_on_failure("1"); } if (isflagset(10)) { add_rr_param(";nat=yes"); } if (!t_relay()) { send_reply("500","Internal Error"); }; exit; } branch_route[2] { xlog("new branch at $ru\n"); } onreply_route[2] { if (nat_uac_test("1")) fix_nated_contact(); if ( isflagset(10) ) rtpproxy_answer("ro"); xlog("incoming reply\n"); } failure_route[1] { if (t_was_cancelled()) { exit; } # uncomment the following lines if you want to block client # redirect based on 3xx replies. ##if (t_check_status("3[0-9][0-9]")) { ##t_reply("404","Not found"); ## exit; ##} } local_route { if (is_method("BYE") && $DLG_dir=="UPSTREAM") { acc_db_request("200 Dialog Timeout", "acc"); } } and here there is RTPPROXY.LOG, when call is made: Sep 6 09:32:42 opensips rtpproxy[19964]: DBUG:handle_command: received command "19989_5 UR172.16.52.53c18,97 29d66022-c0a80101-0-1d@172.16.52.195 172.16.52.195 41000 c0a80101-7327839;1" Sep 6 09:32:42 opensips rtpproxy[19964]: INFO:handle_command: new session 29d66022-c0a80101-0-1d@172.16.52.195, tag c0a80101-7327839;1 requested, type strong OPENSIPS.LOG: Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: SIP Request: Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: method: <INVITE> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: uri: <sip:1000@video.longwave.eu:5060;user=phone> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5747926469769213710-120748090>; state= Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: this is the first via Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: preparing to run routing scripts... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=100 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: end of header reached, state=10 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: <t> [46]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>#015#012] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:check_ip_address: params 172.16.52.195, 172.16.52.195, 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: content_length=228 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:uri:has_totag: no totag Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=78 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_lookup_request: start searching: hash=36067, isACK=0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_lookup_request: no transaction found Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to_param: tag=c0a80101-7327839 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: display={"OPENSIPS"}, ruri={sip:utente2@video.longwave.eu:5060;user=phone} Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=10000 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:auth:pre_auth: credentials with given realm not found Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:auth:reserve_nonce_index: second= 23, sec_monit= -1, index= 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:auth:build_auth_hf: nonce index= 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="video.longwave.eu", nonce="504851b8000000002fe fac8972001622d3da8aabca2d7a"#015#012' Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:sl:run_sl_callbacks: callback id 0 entered Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:siptrace:trace_sl_onreply_out: trace slonreply out Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:siptrace:trace_sl_onreply_out: nothing to trace... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: cleaning up Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: SIP Request: Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: method: <ACK> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: uri: <sip:1000@video.longwave.eu:5060;user=phone> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK5747926469769213710-120748090>; state= Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: this is the first via Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:receive_msg: preparing to run routing scripts... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=8 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to_param: tag=2fd9d4a31f868720ea20de4261af08b1.8e5b Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: <t> [88]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:sl:sl_filter_ACK: local ACK found -> dropping it! Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:receive_msg: cleaning up Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: SIP Request: Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: method: <INVITE> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: uri: <sip:1000@video.longwave.eu:5060;user=phone> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2475363147136087087-120748101>; state= Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: this is the first via Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: preparing to run routing scripts... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=100 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: end of header reached, state=10 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: <t> [46]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>#015#012] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:check_ip_address: params 172.16.52.195, 172.16.52.195, 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: content_length=228 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:uri:has_totag: no totag Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=78 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: start searching: hash=36064, isACK=0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: no transaction found Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to_param: tag=c0a80101-7327839 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: display={"OPENSIPS"}, ruri={sip:utente2@video.longwave.eu:5060;user=phone} Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:auth:check_nonce: comparing [504851b8000000002fe41fac8972001622d3da8aabca2d7a] and [504851b8000000002 41fac8972001622d3da8aabca2d7a] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb7219940 (tail=-1222544604) MC=0xb7217358 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|select password from subscriber where username=? AND main=?| Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:re_init_statement: query is <select password from subscriber where username=? AND domain=? ptr=(nil) Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0xb721aacc) on connection: (0xb7219940) 0xb7217324 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=7; type=254; is_null=0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=17; type=254; is_null=0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 1 columns in result Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_do_prepared_query: doing to BIND_PARAM out ... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb721b050 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0xb721b07c Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb721b080)[0]=[password] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_allocate_rows: allocate 28 bytes for result rows and values at 0xb721b098 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_str2val: converting STRING [opensips] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:auth_db:get_ha1: HA1 string calculated: 28c26c8854d209223fdb27b516870a70 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:auth:check_response: our result = '112b8dd2ff6ac56b6d21c62ff963fd3b' Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:auth:check_response: authorization is OK Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:auth:post_auth: nonce index= 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_columns: freeing result columns at 0xb721b07c Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_rows: freeing 1 rows Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_row: freeing row values at 0xb721b0a0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_rows: freeing rows at 0xb721b098 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_result: freeing result set at 0xb721b050 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:uri:check_username: Digest username and URI username match Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=200 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:find_first_route: No Route headers found Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:loose_route: There is no Route HF Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:w_create_dialog2: bye on timeout activated Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:build_new_dlg: new dialog 0xaeeb5110 (c=29d66022-c0a80101-0-1d@172.16.52.195,f=sip:utente2@vid .longwave.eu:5060;user=phone,t=sip:1000@video.longwave.eu:5060;user=phone,ft=c0a80101-7327839) on hash 3244 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:init_leg_info: route_set , contact sip:utente2@172.16.52.195:5060;transport=udp;user=phone, cs 2 and bind_addr udp:10.9.23.41:5060 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0xaeeb5110: tag=<c0a80101-7327839> rcseq=<0> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:link_dlg: ref dlg 0xaeeb5110 with 3 -> 3 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:add_rr_param: adding (;did=cac.deaa4071) 0xb721b1d8 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb721b4e8 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_allocate_columns: allocate 32 bytes for result columns at 0xb721b514 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb721b51c)[0]=[username] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb721b524)[1]=[domain] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_allocate_rows: allocate 48 bytes for result rows and values at 0xb721b540 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_str2val: converting STRING [utente1] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:db_mysql:db_mysql_str2val: converting STRING [video.longwave.eu] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:alias_db:alias_db_query: new URI [0] is [sip:utente1@video.longwave.eu] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_columns: freeing result columns at 0xb721b514 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_rows: freeing 1 rows Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_row: freeing row values at 0xb721b548 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_rows: freeing rows at 0xb721b540 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:db_free_result: freeing result set at 0xb721b4e8 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialplan:dp_get_ivalue: integer value Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialplan:dp_translate_f: dpid is 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialplan:dp_get_svalue: searching 15 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialplan:dp_translate_f: input is utente1 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialplan:dp_translate_f: no information available for dpid 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:registrar:lookup: found a complete match Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:registrar:lookup: setting as ruri <sip:utente1@172.16.52.53:33606;rinstance=3f9c3a674b9ad47b> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:registrar:lookup: looking for branches Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=40 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 23 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:add_rr_param: adding (;nat=yes) 0xb721b46c Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_newtran: transaction on entrance=(nil) Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=78 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: start searching: hash=36064, isACK=0 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: no transaction found Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:run_reqin_callbacks: trans=0xaeeb56e4, callback type 1, id 2 entered Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:siptrace:trace_onreq_in: trace on req in Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:siptrace:trace_onreq_in: nothing to trace... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:run_reqin_callbacks: trans=0xaeeb56e4, callback type 1, id 1 entered Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:dlg_onreq: t hash_index = 36064, t label = 1315880115 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:run_reqin_callbacks: trans=0xaeeb56e4, callback type 1, id 0 entered Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=78 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:_shm_resize: resize(0) called Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:_reply_light: reply sent out. buf=0xb721b75c: SIP/2.0 1..., shmem=0xaeeb7960: SIP/2.0 1 Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:_reply_light: finished Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:buf_init: initializing... Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: new branch at sip:utente1@172.16.52.53:33606;rinstance=3f9c3a674b9ad47b Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:_shm_resize: resize(0) called Sep 6 09:32:42 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:mk_proxy: doing DNS lookup... Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 84, get_ticks = 24 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:set_timer: relative timeout is 500000 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:insert_timer_unsafe: [4]: 0xaeeb5830 (24900000) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:set_timer: relative timeout is 5 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:insert_timer_unsafe: [0]: 0xaeeb584c (29) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_relay_to: new transaction fwd'ed Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb56e4] after is 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:unref_dlg: unref dlg 0xaeeb5110 with 1 -> 2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: cleaning up Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: SIP Reply (status): Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: status: <100> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: reason: <Trying> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0ec8.3bcbe6e4.0>; state=16 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: this is the first via Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.52.195>; state=6 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2475363147136087087-120748101>; state= Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: via found, flags=4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: parse_headers: this is the second via Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:forward_reply: found module tm, passing reply to it Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_check: start=0xffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=22 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: end of header reached, state=10 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: <To> [46]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>#015#012] Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=8 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_reply_matching: hash 36064 label 1315880115 branch 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaeeb56e4] after is 1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_reply_matching: reply matched (T=0xaeeb56e4)! Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 2, id 1 entered Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_check: end=0xaeeb56e4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: content_length=0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:buf_init: initializing... Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: incoming reply Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_should_relay_response: T_code=100, new_code=100 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:relay_reply: branch=0, save=0, relay=-1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:set_timer: relative timeout is 30 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:insert_timer_unsafe: [1]: 0xaeeb584c (54) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb56e4] after is 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:receive_msg: cleaning up Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: SIP Reply (status): Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: status: <180> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: reason: <Ringing> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0ec8.3bcbe6e4.0>; state=16 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: this is the first via Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.52.195>; state=6 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2475363147136087087-120748101>; state= Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: via found, flags=4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: parse_headers: this is the second via Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:forward_reply: found module tm, passing reply to it Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_check: start=0xffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=22 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to_param: tag=0b433034 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: <To> [59]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=8 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: hash 36064 label 1315880115 branch 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaeeb56e4] after is 1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: reply matched (T=0xaeeb56e4)! Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 2, id 1 entered Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_check: end=0xaeeb56e4 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: content_length=0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:buf_init: initializing... Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: incoming reply Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_should_relay_response: T_code=100, new_code=180 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 8, id 0 entered Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:dialog:push_reply_in_dialog: 0xaeeb5110 totag in rpl is <0b433034> (8) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:dialog:push_reply_in_dialog: new branch with tag <0b433034> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:dialog:init_leg_info: route_set , contact , cseq 2 and bind_addr udp:10.9.23.41:5060 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0xaeeb5110: tag=<0b433034> rcseq=<2> Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:build_res_buf_from_sip_res: old size: 603, new size: 544 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:build_res_buf_from_sip_res: copied size: orig:295, new: 236, rest: 308 msg=#012SIP/2.0 180 Ringi #015#012Via: SIP/2.0/UDP 172.16.52.195:5060;rport=5060;received=172.16.52.195;branch=z9hG4bK2475363147136087087-120748101#015#012Record-Route: <sip:10.9.23.41;lr;did=cac.deaa4071 at=yes>#015#012Contact: <sip:utente1@172.16.52.53:33606>#015#012To: <sip:1000@video.longwave.eu:5060;user=phone>;tag=0b433034#015#012From: "OPENSIPS"<sip:utente2@video.longwave.e 5060;user=phone>;tag=c0a80101-7327839#015#012Call-ID: 29d66022-c0a80101-0-1d@172.16.52.195#015#012CSeq: 2 INVITE#015#012User-Agent: Bria 3 release 3.4.2 stamp 67674#015#012Allow- ents: hold, talk#015#012Content-Length: 0#015#012#015#012 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 64, id 0 entered Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:dialog:next_state_dlg: dialog 0xaeeb5110 changed from state 1 to state 2, due event 2 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:relay_reply: sent buf=0xb721ab78: SIP/2.0 1..., shmem=0xaeeb8084: SIP/2.0 1 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 128, id 1 entered Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:set_timer: relative timeout is 30 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:insert_timer_unsafe: [1]: 0xaeeb584c (54) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb56e4] after is 0 Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:43 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: cleaning up Sep 6 09:32:44 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:utimer_routine: timer routine:4,tl=0xaeeb5830 next=(nil), timeout=24900000 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: SIP Reply (status): Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: status: <200> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_msg: reason: <OK> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=2 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0ec8.3bcbe6e4.0>; state=16 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: this is the first via Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=4 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.52.195>; state=6 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2475363147136087087-120748101>; state=16 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: via found, flags=4 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: parse_headers: this is the second via Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:forward_reply: found module tm, passing reply to it Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_check: start=0xffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=22 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to_param: tag=0b433034 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: <To> [59]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=8 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_reply_matching: hash 36064 label 1315880115 branch 0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaeeb56e4] after is 1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_reply_matching: reply matched (T=0xaeeb56e4)! Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=8 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 2, id 1 entered Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=8 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_check: end=0xaeeb56e4 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: content_length=239 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=40 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 84, get_ticks = 27 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: ERROR:rtpproxy:force_rtp_proxy: no available proxies Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:buf_init: initializing... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: incoming reply Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_should_relay_response: T_code=180, new_code=200 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 8, id 0 entered Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:push_reply_in_dialog: 0xaeeb5110 totag in rpl is <0b433034> (8) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:push_reply_in_dialog: branch with tag <0b433034> already exists Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:print_rr_body: current rr is <sip:10.9.23.41;lr;did=cac.deaa4071;nat=yes> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:print_rr_body: skipping 1 route records Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:print_rr_body: out rr [] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:print_rr_body: we have 1 records Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:dlg_update_routing: dialog 0xaeeb5110[1]: rr=<> contact=<sip:utente1@172.16.52.53:33606> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:build_res_buf_from_sip_res: old size: 959, new size: 900 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:build_res_buf_from_sip_res: copied size: orig:290, new: 231, rest: 669 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 172.16.52.195:5060;rport=5060;received=172.16.52.195;branch=z9hG4bK2475363147136087087-120748101#015#012Record-Route: <sip:10.9.23.41;lr;did=cac.deaa4071;nat=yes>#015#012Contact: <sip:utente1@172.16.52.53:33606>#015#012To: <sip:1000@video.longwave.eu:5060;user=phone>;tag=0b433034#015#012From: "OPENSIPS"<sip:utente2@video.longwave.eu:5060;user=phone>;tag=c0a80101-7327839#015#012Call-ID: 29d66022-c0a80101-0-1d@172.16.52.195#015#012CSeq: 2 INVITE#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO#015#012Content-Type: application/sdp#015#012Supported: replaces, eventlist#015#012User-Agent: Bria 3 release 3.4.2 stamp 67674#015#012Content-Length: 239#015#012#015#012v=0#015#012o=- 1346916764885158 1 IN IP4 172.16.52.53#015#012s=CounterPath Bria 3.3#015#012c=IN IP4 172.16.52.53#015#012t=0 0#015#012m=audio 60404 RTP/AVP 18 97#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpmap:97 telephone-event/8000#015#012a=fmtp:97 0-15#015#012a=sendrecv#015#012 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:update_totag_set: new totag Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:insert_timer_unsafe: [2]: 0xaeeb572c (32) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 64, id 0 entered Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:next_state_dlg: dialog 0xaeeb5110 changed from state 2 to state 3, due event 3 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:dlg_onreply: dialog 0xaeeb5110 confirmed Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0xaeeb5144 for 21627 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:dialog:ref_dlg: ref dlg 0xaeeb5110 with 1 -> 3 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:relay_reply: sent buf=0xb721bbbc: SIP/2.0 2..., shmem=0xaeeb8350: SIP/2.0 2 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:run_trans_callbacks: trans=0xaeeb56e4, callback type 128, id 1 entered Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb721996c (tail=-1222544604) MC=0xb7217358 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time ) values (?,?,?,?,?,?,?)| Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:re_init_statement: query is <insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time ) values (?,?,?,?,?,?,?)>, ptr=(nil) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0xb721bf50) on connection: (0xb721996c) 0xb7217324 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=16; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=8; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=36; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=36; type=12; is_null=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb56e4] after is 0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19987]: DBG:core:receive_msg: cleaning up Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: SIP Request: Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: method: <ACK> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: uri: <sip:utente1@172.16.52.53:33606;user=phone> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=2 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7529708647547431532-120750068>; state=16 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: this is the first via Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: preparing to run routing scripts... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:sl:sl_filter_ACK: to late to be a local ACK! Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=100 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to_param: tag=0b433034 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: <t> [59]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <ACK> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:check_ip_address: params 172.16.52.195, 172.16.52.195, 0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: content_length=0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:uri:has_totag: totag found Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=200 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:is_preloaded: is_preloaded: No Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if host==us: 12==10 && [172.16.52.53] == [10.9.23.41] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [172.16.52.53] == [151.8.12.201] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if host==us: 12==10 && [172.16.52.53] == [10.9.23.41] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [172.16.52.53] == [151.8.12.201] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:check_self: host != me Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if host==us: 10==10 && [10.9.23.41] == [10.9.23.41] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:after_loose: Topmost route URI: 'sip:10.9.23.41;lr;did=cac.deaa4071;nat=yes' is me Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=200 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:find_next_route: No next Route HF found Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:after_loose: No next URI found! Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=cac.deaa4071;nat=yes> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:dlg_onroute: route param is 'cac.deaa4071' (len=12) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:lookup_dlg: ref dlg 0xaeeb5110 with 1 -> 4 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:lookup_dlg: dialog id=386181869 found on entry 3244 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=58 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to_param: tag=c0a80101-7327839 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_to: display={"OPENSIPS"}, ruri={sip:utente2@video.longwave.eu:5060;user=phone} Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:next_state_dlg: dialog 0xaeeb5110 changed from state 3 to state 4, due event 6 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:dlg_validate_dialog: CSEQ validation passed Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:compare_uris: Different uri types Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: ERROR:dialog:dlg_validate_dialog: failed to validate remote contact: dlg=[sip:utente1@172.16.52.53:33606] , req=[sip:utente1@172.16.52.53:33606;user=phone] Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: In-Dialog ACK from 172.16.52.195 (callid=29d66022-c0a80101-0-1d@172.16.52.195) is not valid according to dialog Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:check_route_param: params are <;lr;did=cac.deaa4071;nat=yes> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:add_rr_param: adding (;nat=yes) (nil) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:rr:add_rr_param: rr_param_buf=<;nat=yes> Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_newtran: transaction on entrance=0xffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=78 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: start searching: hash=36064, isACK=1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:parse_headers: flags=38 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: REF_UNSAFE:[0xaeeb56e4] after is 1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_lookup_request: e2e proxy ACK found Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_newtran: building branch for end2end ACK - flags=1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_relay_to: forwarding ACK Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:mk_proxy: doing DNS lookup... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:forward_request: sending:#012ACK sip:utente1@172.16.52.53:33606;user=phone SIP/2.0#015#012Via: SIP/2.0/UDP 10.9.23.41;branch=z9hG4bK0ec8.3bcbe6e4.2#015#012v: SIP/2.0/UDP 172.16.52.195:5060;rport=5060;received=172.16.52.195;branch=z9hG4bK7529708647547431532-120750068#015#012f: "OPENSIPS"<sip:utente2@video.longwave.eu:5060;user=phone>;tag=c0a80101-7327839#015#012t: <sip:1000@video.longwave.eu:5060;user=phone>;tag=0b433034#015#012i: 29d66022-c0a80101-0-1d@172.16.52.195#015#012CSeq: 2 ACK#015#012Max-Forwards: 69#015#012Allow-Events: refer,dialog,message-summary,check-sync,talk,hold#015#012Proxy-Authorization: Digest username="utente2", realm="video.longwave.eu", nonce="504851b8000000002fe41fac8972001622d3da8aabca2d7a", uri="sip:utente1@172.16.52.53:33606;user=phone", response="3cc07661ba3a9494afadcea2fb1a2261", algorithm=MD5#015#012User-Agent: THOMSON ST2030 hw5 fw2.72 00-1F-9F-16-C2-DC#015#012l: 0#015#012#015#012. Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:forward_request: orig. len=776, new_len=816, proto=1 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:run_fwd_callbacks: FWD callback entered Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:siptrace:trace_msg_out: trace off... Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0xaeeb56e4] after is 0 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:dialog:unref_dlg: unref dlg 0xaeeb5110 with 1 -> 3 Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:46 opensips /usr/local/opensips_proxy/sbin/opensips[19989]: DBG:core:receive_msg: cleaning up Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: SIP Request: Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: method: <BYE> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: uri: <sip:utente1@172.16.52.53:33606;user=phone> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7960258682981536932-120752106>; state=16 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: this is the first via Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:receive_msg: preparing to run routing scripts... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=100 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to_param: tag=0b433034 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: <t> [59]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:check_ip_address: params 172.16.52.195, 172.16.52.195, 0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: content_length=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:uri:has_totag: totag found Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=200 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:is_preloaded: is_preloaded: No Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if host==us: 12==10 && [172.16.52.53] == [10.9.23.41] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [172.16.52.53] == [151.8.12.201] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if host==us: 12==10 && [172.16.52.53] == [10.9.23.41] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [172.16.52.53] == [151.8.12.201] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if port 5060 matches port 33606 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:check_self: host != me Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if host==us: 10==10 && [10.9.23.41] == [10.9.23.41] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:after_loose: Topmost route URI: 'sip:10.9.23.41;lr;did=cac.deaa4071;nat=yes' is me Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=200 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:get_hdr_field: found end of header Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:find_next_route: No next Route HF found Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:after_loose: No next URI found! Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:run_rr_callbacks: callback id 1 entered with <lr;did=cac.deaa4071;nat=yes> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:dlg_onroute: route param is 'cac.deaa4071' (len=12) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:lookup_dlg: ref dlg 0xaeeb5110 with 1 -> 4 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:lookup_dlg: dialog id=386181869 found on entry 3244 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=58 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to_param: tag=c0a80101-7327839 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_to: display={"OPENSIPS"}, ruri={sip:utente2@video.longwave.eu:5060;user=phone} Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:next_state_dlg: dialog 0xaeeb5110 changed from state 4 to state 5, due event 7 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 1 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:remove_dialog_from_db: trying to remove a dialog, update_flag is 31 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:unref_dlg: unref dlg 0xaeeb5110 with 2 -> 2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:dlg_validate_dialog: CSEQ validation passed Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:compare_uris: Different uri types Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: ERROR:dialog:dlg_validate_dialog: failed to validate remote contact: dlg=[sip:utente1@172.16.52.53:33606] , req=[sip:utente1@172.16.52.53:33606;user=phone] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: In-Dialog BYE from 172.16.52.195 (callid=29d66022-c0a80101-0-1d@172.16.52.195) is not valid according to dialog Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:check_route_param: params are <;lr;did=cac.deaa4071;nat=yes> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:add_rr_param: adding (;nat=yes) (nil) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:rr:add_rr_param: rr_param_buf=<;nat=yes> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_newtran: transaction on entrance=0xffffffff Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=78 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_lookup_request: start searching: hash=36065, isACK=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_lookup_request: no transaction found Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:run_reqin_callbacks: trans=0xaeeb86e4, callback type 1, id 2 entered Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:siptrace:trace_onreq_in: trace on req in Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:siptrace:trace_onreq_in: nothing to trace... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:run_reqin_callbacks: trans=0xaeeb86e4, callback type 1, id 1 entered Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:ref_dlg: ref dlg 0xaeeb5110 with 1 -> 3 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:run_reqin_callbacks: trans=0xaeeb86e4, callback type 1, id 0 entered Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:parse_headers: flags=78 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:mk_proxy: doing DNS lookup... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:set_timer: relative timeout is 500000 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:insert_timer_unsafe: [4]: 0xaeeb8830 (31900000) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:set_timer: relative timeout is 5 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:insert_timer_unsafe: [0]: 0xaeeb884c (36) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_relay_to: new transaction fwd'ed Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb86e4] after is 0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:dialog:unref_dlg: unref dlg 0xaeeb5110 with 1 -> 2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19988]: DBG:core:receive_msg: cleaning up Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: SIP Reply (status): Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: version: <SIP/2.0> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: status: <200> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_msg: reason: <OK> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1ec8.471796a4.0>; state=16 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: via found, flags=2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: this is the first via Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: After parse_msg... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=4 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.52.195>; state=6 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7960258682981536932-120752106>; state=16 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_via: end of header reached, state=5 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: via found, flags=4 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: parse_headers: this is the second via Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:forward_reply: found module tm, passing reply to it Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_check: start=0xffffffff Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=22 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to_param: tag=0b433034 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: end of header reached, state=29 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_to: display={}, ruri={sip:1000@video.longwave.eu:5060;user=phone} Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: <To> [59]; uri=[sip:1000@video.longwave.eu:5060;user=phone] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: to body [<sip:1000@video.longwave.eu:5060;user=phone>] Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:get_hdr_field: cseq <CSeq>: <3> <BYE> Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: hash 36065 label 1248424308 branch 0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaeeb86e4] after is 1 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_reply_matching: reply matched (T=0xaeeb86e4)! Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb86e4, callback type 2, id 1 entered Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:parse_headers: flags=8 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_check: end=0xaeeb86e4 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_should_relay_response: T_code=0, new_code=200 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:build_res_buf_from_sip_res: old size: 509, new size: 450 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:build_res_buf_from_sip_res: copied size: orig:75, new: 16, rest: 434 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 172.16.52.195:5060;rport=5060;received=172.16.52.195;branch=z9hG4bK7960258682981536932-120752106#015#012Contact: <sip:utente1@172.16.52.53:33606>#015#012To: <sip:1000@video.longwave.eu:5060;user=phone>;tag=0b433034#015#012From: "OPENSIPS"<sip:utente2@video.longwave.eu:5060;user=phone>;tag=c0a80101-7327839#015#012Call-ID: 29d66022-c0a80101-0-1d@172.16.52.195#015#012CSeq: 3 BYE#015#012User-Agent: Bria 3 release 3.4.2 stamp 67674#015#012Content-Length: 0#015#012#015#012 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:_shm_resize: resize(0) called Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:insert_timer_unsafe: [2]: 0xaeeb872c (36) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:relay_reply: sent buf=0xb721ab78: SIP/2.0 2..., shmem=0xaeeb8084: SIP/2.0 2 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:run_trans_callbacks: trans=0xaeeb86e4, callback type 128, id 1 entered Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb721983c (tail=-1222544604) MC=0xb7217358 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time ) values (?,?,?,?,?,?,?)| Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:re_init_statement: query is <insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time ) values (?,?,?,?,?,?,?)>, ptr=(nil) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0xb721bdc8) on connection: (0xb721983c) 0xb7217324 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=3; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=16; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=8; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=36; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=36; type=12; is_null=0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaeeb86e4] after is 0 Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:destroy_avp_list: destroying list (nil) Sep 6 09:32:50 opensips /usr/local/opensips_proxy/sbin/opensips[19990]: DBG:core:receive_msg: cleaning up Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:utimer_routine: timer routine:4,tl=0xaeeb8830 next=(nil), timeout=31900000 Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:timer_routine: timer routine:2,tl=0xaeeb572c next=(nil), timeout=32 Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:wait_handler: removing 0xaeeb56e4 from table Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:delete_cell: delete transaction 0xaeeb56e4 Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:dialog:next_state_dlg: dialog 0xaeeb5110 changed from state 5 to state 5, due event 1 Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:dialog:unref_dlg: unref dlg 0xaeeb5110 with 1 -> 1 Sep 6 09:32:51 opensips /usr/local/opensips_proxy/sbin/opensips[19996]: DBG:tm:wait_handler: done |
|
|
In reply to this post by Bogdan-Andrei Iancu-2
Hi, I am making some test and also changing configuration at opensips.cfg, i have always same issue.
The problem is related to this ERROR: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused But i cannot understand why RTPPROXY refuses connection. Any idea? |
|
|
Youve Local2 syslog facility for rtpproxy logs. View the syslog file for rtpproxy and see that it must be crashing/segfault on each connection attempt from the opensips. I asked you few things in my last email. Now please reply with those as well as with following info: Thanks On Sep 6, 2012 7:42 PM, "spady" <[hidden email]> wrote:
Hi, I am making some test and also changing configuration at opensips.cfg, i _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
Hi Sam, and thanks for reply.
OS is Debian 6.03 As you can see above i already posted log either from opnesips and rtpproxy. I post them again. STARTING RTPPROXY: ep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25020_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25020_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25020_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25020_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25020_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25020_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25020_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25020_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25020_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25020_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25021_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25021_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25022_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25022_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25021_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25021_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25022_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25022_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25021_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25021_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25021_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25021_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25021_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25021_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25024_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25024_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25024_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25024_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25019_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25019_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25019_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25019_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25022_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25022_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25022_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25022_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25022_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25022_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25018_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25018_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25018_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25018_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25018_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25018_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25018_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25018_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25018_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25018_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25019_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25019_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25019_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25019_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25019_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25019_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25017_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25017_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25017_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25017_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25024_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25024_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25024_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25024_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25024_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25024_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25017_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25017_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25017_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25017_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25027_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25027_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25017_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25017_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25027_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25027_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25027_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25027_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25026_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25026_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25026_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25026_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25027_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25027_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25027_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25027_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25026_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25026_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25026_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25026_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25026_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25026_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25023_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25023_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25023_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25023_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25023_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25023_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25023_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25023_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25023_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25023_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25030_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25030_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25030_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25030_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25016_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25016_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25016_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25016_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25016_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25016_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25016_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25016_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25016_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25016_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25030_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25030_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25030_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25030_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25030_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25030_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25028_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25028_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25028_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25028_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25029_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25029_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25029_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25029_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25028_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25028_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25028_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25028_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25028_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25028_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25029_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25029_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25029_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25029_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25029_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25029_4 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25035_0 V" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25035_0 20040107#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25035_1 VF 20050322" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25035_1 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25035_2 VF 20071116" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25035_2 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25035_3 VF 20081102" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25035_3 1#012" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:handle_command: received command "25035_4 VF 20090810" Sep 6 18:05:22 opensips rtpproxy[24996]: DBUG:doreply: sending reply "25035_4 1#012" AFTER CALL RTPPROXY IS EMPTY!!!!!!!!! OPENSIPS LOG: Sep 6 18:06:08 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 6 18:06:08 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 18:06:08 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 46 Sep 6 18:06:08 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 6 18:06:08 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=- 1346947567338250 1 IN IP4 172.16.52.53#015#012s=CounterPath Bria 3.3#015#012c=IN IP4 172.16.52.53#015#012t=0 0#015#012m=audio 57888 RTP/AVP 0 8 18 101#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012] Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 46 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=- 1346947567338250 1 IN IP4 172.16.52.53#015#012s=CounterPath Bria 3.3#015#012c=IN IP4 172.16.52.53#015#012t=0 0#015#012m=audio 57888 RTP/AVP 0 8 18 101#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012] Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 106, get_ticks = 46 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25019]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25017]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 107, get_ticks = 47 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 6 18:06:09 opensips /usr/local/opensips_proxy/sbin/opensips[25020]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 107, get_ticks = 50 Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: ERROR:rtpproxy:force_rtp_proxy: no available proxies Sep 6 18:06:13 opensips /usr/local/opensips_proxy/sbin/opensips[25018]: DBG:core:build_res_buf_from_sip_res: copied size: orig:516, new: 459, rest: 387 msg=#012SIP/2.0 200 OK#015#012v: SIP/2.0/UDP 172.16.52.53:53479;received=172.16.52.53;branch=z9hG4bK-d8754z-40ac1130ea0b7649-1---d8754z-;rport=53479#015#012f: "Utente1"<sip:utente1@video.longwave.eu>;tag=b308166f#015#012t: <sip:1001@video.longwave.eu>;tag=c0a80101-81d82cf#015#012i: MTI3NGFhZjgzNTM1ZDc3OGRlNmMxZDgwMjNkYmM4MWM#015#012CSeq: 2 INVITE#015#012Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO#015#012m: <sip:utente2@172.16.52.195:5060;transport=udp;user=phone>#015#012Record-Route: <sip:10.9.23.41;lr;did=85c.bce3da14;nat=yes>#015#012Allow-Events: refer,dialog,message-summary,check-sync,talk,hold#015#012c: application/sdp#015#012l: 229#015#012#015#012v=0#015#012o=1001 136153633 136153633 IN IP4 172.16.52.195#015#012s=-#015#012c=IN IP4 172.16.52.195#015#012t=0 0#015#012m=audio 41000 RTP/AVP 18 101#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012 I ALSO CHANGED FROM BRIDGE MODE TO NONE. SAME RELUST. WWHAT I CAN'T SEE IS WHY RTPPROXY REFUSE CONNECTION!!! IS THERE A WAY TO TEST IT AT SOCKET LEVEL?? SOME COMMANDS, FOR ISTANCE? THANKS |
|
|
Hi Spady,
These were opensips logs and I couldn't see rtpproxy anywhere in these logs. Anyway you said you've done all what I suggested I don't think I've anything more to get this issue resolved. Hope someone else can better help you from here.
You still haven't pasted the snippet of the opensips.cfg code where you are calling the rtpproxy forcing function so I'm assuming you are calling it like force_rtp_proxy("flags-here") - If thats the case I'd suggest you to call engage_rtp_proxy(). Don;t forget to start your rtpproxy like this.
That way you'll be able to see the logs of rtpproxy daemon in the same log-file as of opensips (again assuming opensips is using local0 for logs) At the end I'd suggest you to go through this very informative thread by one of my very good friend:
Thanks,
Hope your issue resolves. Sammy On Thu, Sep 6, 2012 at 9:11 PM, spady <[hidden email]> wrote: Hi Sam, and thanks for reply. _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
Hi Spady,
These were opensips logs and I couldn't see rtpproxy anywhere in these logs. Anyway you said you've done all what I suggested I don't think I've anything more to get this issue resolved. Hope someone else can better help you from here.
You still haven't pasted the snippet of the opensips.cfg code where you are calling the rtpproxy forcing function so I'm assuming you are calling it like force_rtp_proxy("flags-here") - If thats the case I'd suggest you to call engage_rtp_proxy(). Don;t forget to start your rtpproxy like this.
rtpproxy -F -s udp:127.0.0.1:7890 -l 10.9.23.41/151.x.x.201 -d DBUG:LOG_LOCAL0
That way you'll be able to see the logs of rtpproxy daemon in the same log-file as of opensips (again assuming opensips is using local0 for logs) At the end I'd suggest you to go through this very informative thread by one of my very good friend:
Thanks, Hope your issue resolves.
Sammy On Thu, Sep 6, 2012 at 10:38 PM, SamyGo <[hidden email]> wrote:
Hi Spady, _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
This post has NOT been accepted by the mailing list yet.
Hi Sam, first of all thanks for reply and for patience.
Here is my snippet of code: route[1] { # for INVITEs enable some additional helper routes if (is_method("INVITE")) { if (isflagset(10)) { rtpproxy_offer("ro"); } t_on_branch("2"); t_on_reply("2"); t_on_failure("1"); } if (isflagset(10)) { add_rr_param(";nat=yes"); } if (!t_relay()) { send_reply("500","Internal Error"); }; exit; } branch_route[2] { xlog("new branch at $ru\n"); } onreply_route[2] { if (nat_uac_test("1")) fix_nated_contact(); if ( isflagset(10) ) rtpproxy_answer("ro"); xlog("incoming reply\n"); } I started rtpproxy by: rtpproxy -F -s udp:127.0.0.1:7890 -l 10.9.23.41/151.8.12.201 -d DBUG:LOG_LOCAL0 and here is a log of a call ( from Utente1 to Utente2 ). Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: SIP Request: Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: method: <INVITE> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: uri: <sip:1001@video.longwave.eu> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-dfc2ae4fa6c10d55-1---d8754z->; ate=6 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: this is the first via Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:receive_msg: preparing to run routing scripts... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:sip_trace: nothing to trace... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=100 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:check_ip_address: params 172.16.81.184, 172.16.81.184, 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: end of header reached, state=10 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: <To> [30]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>#015#012] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: content_length=248 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: found end of header Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:uri:has_totag: no totag Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=78 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_lookup_request: start searching: hash=9165, isACK=0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_lookup_request: no transaction found Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to_param: tag=0a91bf4c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: display={"Utente1"}, ruri={sip:utente1@video.longwave.eu} Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=10000 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:auth:pre_auth: credentials with given realm not found Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:auth:reserve_nonce_index: second= 27, sec_monit= -1, index= 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:auth:build_auth_hf: nonce index= 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="video.longwave.eu", nonce="5049c81200000000b249 716d633e2ffe6544f7aca2cb1c"#015#012' Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:sl:run_sl_callbacks: callback id 0 entered Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:trace_sl_onreply_out: trace slonreply out Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=40 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:trace_sl_onreply_out: dest [udp:172.16.81.184:35484] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:pipport2su: the port string is 35484 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:receive_msg: cleaning up Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: SIP Request: Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: method: <ACK> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: uri: <sip:1001@video.longwave.eu> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-dfc2ae4fa6c10d55-1---d8754z->; ate=6 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: this is the first via Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:receive_msg: preparing to run routing scripts... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=8 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to_param: tag=2fd9d4a31f868720ea20de4261af08b1.871b Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: <To> [72]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:sl:sl_filter_ACK: local ACK found -> dropping it! Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:receive_msg: cleaning up Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_msg: SIP Request: Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_msg: method: <INVITE> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_msg: uri: <sip:1001@video.longwave.eu> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-deac491d4e76a115-1---d8754z->; ate=6 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: this is the first via Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:receive_msg: preparing to run routing scripts... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:siptrace:sip_trace: nothing to trace... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=100 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:check_ip_address: params 172.16.81.184, 172.16.81.184, 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_to: end of header reached, state=10 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:get_hdr_field: <To> [30]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>#015#012] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:get_hdr_field: content_length=248 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:get_hdr_field: found end of header Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:uri:has_totag: no totag Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=78 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_lookup_request: start searching: hash=9162, isACK=0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_lookup_request: no transaction found Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_to_param: tag=0a91bf4c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_to: display={"Utente1"}, ruri={sip:utente1@video.longwave.eu} Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:auth:check_nonce: comparing [5049c81200000000b249cc716d633e2ffe6544f7aca2cb1c] and [5049c81200000000b2 cc716d633e2ffe6544f7aca2cb1c] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb72019ac (tail=-1222643112) MC=0xb71ff28c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|select password from subscriber where username=? AND d ain=?| Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:re_init_statement: query is <select password from subscriber where username=? AND domain=?> ptr=(nil) Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0xb7202b38) on connection: (0xb72019ac) 0xb71ff258 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=7; type=254; is_null=0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=17; type=254; is_null=0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 1 columns in result Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_do_prepared_query: doing to BIND_PARAM out ... Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb72030bc Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0xb72030e8 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb72030ec)[0]=[password] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_allocate_rows: allocate 28 bytes for result rows and values at 0xb7203104 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_str2val: converting STRING [opensips] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:auth_db:get_ha1: HA1 string calculated: bcf65739e8922b29e26e087101635797 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:auth:check_response: our result = 'e7d7179749e78c7c658f80604e02d513' Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:auth:check_response: authorization is OK Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:auth:post_auth: nonce index= 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_columns: freeing result columns at 0xb72030e8 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_rows: freeing 1 rows Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_row: freeing row values at 0xb720310c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_rows: freeing rows at 0xb7203104 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_result: freeing result set at 0xb72030bc Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:uri:check_username: Digest username and URI username match Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=200 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rr:find_first_route: No Route headers found Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rr:loose_route: There is no Route HF Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:w_create_dialog2: bye on timeout activated Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:build_new_dlg: new dialog 0xaee9d0d0 (c=ZDVmNTUxY2U4Y2Y1MjdjNTJkNmFmYWNlNDYxMjBmYzA,f=sip:utent @video.longwave.eu,t=sip:1001@video.longwave.eu,ft=0a91bf4c) on hash 918 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:init_leg_info: route_set , contact sip:utente1@172.16.81.184:35484, cseq 2 and bind_addr udp:10 .23.41:5060 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0xaee9d0d0: tag=<0a91bf4c> rcseq=<0> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:link_dlg: ref dlg 0xaee9d0d0 with 3 -> 3 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rr:add_rr_param: adding (;did=693.c2a6e51) 0xb7203244 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb7203544 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_allocate_columns: allocate 32 bytes for result columns at 0xb7203570 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb7203578)[0]=[username] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb7203580)[1]=[domain] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_allocate_rows: allocate 48 bytes for result rows and values at 0xb720359c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_str2val: converting STRING [utente2] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:db_mysql:db_mysql_str2val: converting STRING [video.longwave.eu] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:alias_db:alias_db_query: new URI [0] is [sip:utente2@video.longwave.eu] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_columns: freeing result columns at 0xb7203570 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_rows: freeing 1 rows Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_row: freeing row values at 0xb72035a4 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_rows: freeing rows at 0xb720359c Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:db_free_result: freeing result set at 0xb7203544 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialplan:dp_get_ivalue: integer value Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialplan:dp_translate_f: dpid is 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialplan:dp_get_svalue: searching 15 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialplan:dp_translate_f: input is utente2 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialplan:dp_translate_f: no information available for dpid 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:registrar:lookup: found a complete match Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:registrar:lookup: setting as ruri <sip:utente2@172.16.52.195:5060;transport=udp;user=phone> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:registrar:lookup: looking for branches Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=40 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 27 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 7 12:09:56 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=- 1347012595122678 1 IN IP4 172.16.81.184#015 12s=CounterPath Bria 3.3#015#012c=IN IP4 172.16.81.184#015#012t=0 0#015#012m=audio 57428 RTP/AVP 0 8 18 101#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpm :101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_msg: SIP Request: Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_msg: method: <INVITE> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_msg: uri: <sip:1001@video.longwave.eu> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-deac491d4e76a115-1---d8754z->; ate=6 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: this is the first via Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:receive_msg: preparing to run routing scripts... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:sip_trace: nothing to trace... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=100 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:maxfwd:is_maxfwd_present: value = 70 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:check_ip_address: params 172.16.81.184, 172.16.81.184, 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_to: end of header reached, state=10 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:get_hdr_field: <To> [30]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>#015#012] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:get_hdr_field: content_length=248 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:get_hdr_field: found end of header Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:uri:has_totag: no totag Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=78 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_lookup_request: start searching: hash=9162, isACK=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_lookup_request: no transaction found Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_to_param: tag=0a91bf4c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_to: display={"Utente1"}, ruri={sip:utente1@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:auth:check_nonce: comparing [5049c81200000000b249cc716d633e2ffe6544f7aca2cb1c] and [5049c81200000000b2 cc716d633e2ffe6544f7aca2cb1c] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb7201874 (tail=-1222643112) MC=0xb71ff28c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|select password from subscriber where username=? AND d ain=?| Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:re_init_statement: query is <select password from subscriber where username=? AND domain=?> ptr=(nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0xb7202a10) on connection: (0xb7201874) 0xb71ff258 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=7; type=254; is_null=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=17; type=254; is_null=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: prepared statement has 1 columns in result Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_do_prepared_query: doing to BIND_PARAM out ... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb7202f94 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0xb7202fc0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb7202fc4)[0]=[password] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_allocate_rows: allocate 28 bytes for result rows and values at 0xb7202fdc Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_str2val: converting STRING [opensips] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:auth_db:get_ha1: HA1 string calculated: bcf65739e8922b29e26e087101635797 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:auth:check_response: our result = 'e7d7179749e78c7c658f80604e02d513' Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:auth:check_response: authorization is OK Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:auth:post_auth: nonce index= 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_columns: freeing result columns at 0xb7202fc0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_rows: freeing 1 rows Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_row: freeing row values at 0xb7202fe4 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_rows: freeing rows at 0xb7202fdc Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_result: freeing result set at 0xb7202f94 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:uri:check_username: Digest username and URI username match Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=200 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rr:find_first_route: No Route headers found Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rr:loose_route: There is no Route HF Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:w_create_dialog2: bye on timeout activated Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:build_new_dlg: new dialog 0xaee9d668 (c=ZDVmNTUxY2U4Y2Y1MjdjNTJkNmFmYWNlNDYxMjBmYzA,f=sip:utent @video.longwave.eu,t=sip:1001@video.longwave.eu,ft=0a91bf4c) on hash 918 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:init_leg_info: route_set , contact sip:utente1@172.16.81.184:35484, cseq 2 and bind_addr udp:10 .23.41:5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0xaee9d668: tag=<0a91bf4c> rcseq=<0> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:link_dlg: ref dlg 0xaee9d668 with 3 -> 3 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rr:add_rr_param: adding (;did=693.d2a6e51) 0xb720311c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_new_result: allocate 28 bytes for result set at 0xb720341c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_allocate_columns: allocate 32 bytes for result columns at 0xb7203448 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb7203450)[0]=[username] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0xb7203458)[1]=[domain] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_allocate_rows: allocate 48 bytes for result rows and values at 0xb7203474 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_str2val: converting STRING [utente2] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:db_mysql:db_mysql_str2val: converting STRING [video.longwave.eu] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:alias_db:alias_db_query: new URI [0] is [sip:utente2@video.longwave.eu] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_columns: freeing result columns at 0xb7203448 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_rows: freeing 1 rows Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_row: freeing row values at 0xb720347c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_rows: freeing rows at 0xb7203474 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:db_free_result: freeing result set at 0xb720341c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialplan:dp_get_ivalue: integer value Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialplan:dp_translate_f: dpid is 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialplan:dp_get_svalue: searching 15 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialplan:dp_translate_f: input is utente2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialplan:dp_translate_f: no information available for dpid 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:registrar:lookup: found a complete match Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:registrar:lookup: setting as ruri <sip:utente2@172.16.52.195:5060;transport=udp;user=phone> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:registrar:lookup: looking for branches Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <ro> and param2 <none> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 0, node->rn_recheck_ticks = 0, get_ticks = 28 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=- 1347012595122678 1 IN IP4 172.16.81.184#015 12s=CounterPath Bria 3.3#015#012c=IN IP4 172.16.81.184#015#012t=0 0#015#012m=audio 57428 RTP/AVP 0 8 18 101#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=yes#015#012a=rtpm :101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 88, get_ticks = 28 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:rr:add_rr_param: adding (;nat=yes) 0xb72033a8 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_newtran: transaction on entrance=(nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=78 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_lookup_request: start searching: hash=9162, isACK=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:matching_3261: RFC3261 transaction matching failed Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_lookup_request: no transaction found Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:run_reqin_callbacks: trans=0xaee9dc64, callback type 1, id 2 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:trace_onreq_in: trace on req in Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:run_reqin_callbacks: trans=0xaee9dc64, callback type 1, id 1 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:dlg_onreq: t hash_index = 9162, t label = 493600819 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:run_reqin_callbacks: trans=0xaee9dc64, callback type 1, id 0 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=78 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:_shm_resize: resize(0) called Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:_reply_light: reply sent out. buf=0xb72035e0: SIP/2.0 1..., shmem=0xaee9fec4: SIP/2.0 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:_reply_light: finished Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:buf_init: initializing... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: new branch at sip:utente2@172.16.52.195:5060;transport=udp;user=phone Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:set_timer: relative timeout is 500000 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:insert_timer_unsafe: [4]: 0xaee9ddb0 (28800000) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:set_timer: relative timeout is 5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:insert_timer_unsafe: [0]: 0xaee9ddcc (33) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 1024, id 1 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:trace_onreq_out: trace on req out Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:trace_msg_out: trace msg out Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:trace_msg_out: dest [udp:172.16.52.195:5060] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:pipport2su: the port string is 50601 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_relay_to: new transaction fwd'ed Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaee9dc64] after is 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:dialog:unref_dlg: unref dlg 0xaee9d668 with 1 -> 2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1459]: DBG:core:receive_msg: cleaning up Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: SIP Reply (status): Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: status: <100> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_msg: reason: <Trying> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKac32.330cb6d1.0>; state=16 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: this is the first via Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=4 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.81.184>; state=6 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-deac491d4e76a115-1---d8754z->; ate=6 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via_param: found param type 235, <rport> = <35484>; state=16 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: via found, flags=4 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: parse_headers: this is the second via Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:forward_reply: found module tm, passing reply to it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_check: start=0xffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=22 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: end of header reached, state=10 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: <t> [30]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>#015#012] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=8 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_reply_matching: hash 9162 label 493600819 branch 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaee9dc64] after is 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_reply_matching: reply matched (T=0xaee9dc64)! Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 2, id 4 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 2, id 2 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:trace_onreply_in: trace onreply in Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to_param: tag=0a91bf4c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_to: display={"Utente1"}, ruri={sip:utente1@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_check: end=0xaee9dc64 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: content_length=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:get_hdr_field: found end of header Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:buf_init: initializing... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: incoming reply Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_should_relay_response: T_code=100, new_code=100 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:relay_reply: branch=0, save=0, relay=-1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:set_timer: relative timeout is 30 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:insert_timer_unsafe: [1]: 0xaee9ddcc (58) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaee9dc64] after is 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: SIP Reply (status): Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: version: <SIP/2.0> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: status: <180> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_msg: reason: <Ringing> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKac32.330cb6d1.0>; state=16 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: via found, flags=2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: this is the first via Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:receive_msg: After parse_msg... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:forward_reply: found module nathelper, passing reply to it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=4 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 234, <received> = <172.16.81.184>; state=6 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-deac491d4e76a115-1---d8754z->; ate=6 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via_param: found param type 235, <rport> = <35484>; state=16 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_via: end of header reached, state=5 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: via found, flags=4 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: parse_headers: this is the second via Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:forward_reply: found module tm, passing reply to it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_check: start=0xffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=22 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to_param: tag=c0a80101-a0da43c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: display={}, ruri={sip:1001@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: <t> [51]; uri=[sip:1001@video.longwave.eu] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: to body [<sip:1001@video.longwave.eu>] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=8 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_reply_matching: hash 9162 label 493600819 branch 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_reply_matching: REF_UNSAFE:[0xaee9dc64] after is 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_reply_matching: reply matched (T=0xaee9dc64)! Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 2, id 4 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 2, id 2 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:trace_onreply_in: trace onreply in Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to_param: tag=0a91bf4c Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: end of header reached, state=29 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_to: display={"Utente1"}, ruri={sip:utente1@video.longwave.eu} Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_check: end=0xaee9dc64 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: content_length=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:get_hdr_field: found end of header Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: ERROR:rtpproxy:force_rtp_proxy: Unable to parse body Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:buf_init: initializing... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: incoming reply Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_should_relay_response: T_code=100, new_code=180 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:relay_reply: branch=0, save=0, relay=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 8, id 0 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:dialog:push_reply_in_dialog: 0xaee9d668 totag in rpl is <c0a80101-a0da43c> (16) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1458]: DBG:core:receive_msg: cleaning up Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:dialog:push_reply_in_dialog: new branch with tag <c0a80101-a0da43c> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:dialog:init_leg_info: route_set , contact , cseq 2 and bind_addr udp:10.9.23.41:5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0xaee9d668: tag=<c0a80101-a0da43c> rcseq=<2> Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:build_res_buf_from_sip_res: old size: 658, new size: 601 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:build_res_buf_from_sip_res: copied size: orig:523, new: 466, rest: 135 msg=#012SIP/2.0 180 Ringin 015#012v: SIP/2.0/UDP 172.16.81.184:35484;received=172.16.81.184;branch=z9hG4bK-d8754z-deac491d4e76a115-1---d8754z-;rport=35484#015#012f: "Utente1"<sip:utente1@video.longwave.eu> ag=0a91bf4c#015#012t: <sip:1001@video.longwave.eu>;tag=c0a80101-a0da43c#015#012i: ZDVmNTUxY2U4Y2Y1MjdjNTJkNmFmYWNlNDYxMjBmYzA#015#012CSeq: 2 INVITE#015#012Allow: INVITE,ACK,BYE,C CEL,OPTIONS,PRACK,SUBSCRIBE,NOTIFY,UPDATE,REFER,REGISTER,INFO#015#012m: <sip:utente2@172.16.52.195:5060;transport=udp;user=phone>#015#012Record-Route: <sip:10.9.23.41;lr;did=693. a6e51;nat=yes>#015#012Allow-Events: refer,dialog,message-summary,check-sync,talk,hold#015#012l: 0#015#012#015#012 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 64, id 0 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:dialog:next_state_dlg: dialog 0xaee9d668 changed from state 1 to state 2, due event 2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:relay_reply: sent buf=0xb7203b8c: SIP/2.0 1..., shmem=0xaeea056c: SIP/2.0 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 128, id 4 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:run_trans_callbacks: trans=0xaee9dc64, callback type 128, id 3 entered Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:trace_onreply_out: trace onreply out Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:parse_headers: flags=40 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:trace_onreply_out: dest [udp:172.16.81.184:35484] Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:pipport2su: the port string is 5060 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:siptrace:pipport2su: the port string is 35484 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:mk_proxy: doing DNS lookup... Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:set_timer: relative timeout is 30 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:insert_timer_unsafe: [1]: 0xaee9ddcc (58) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaee9dc64] after is 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1457]: DBG:core:receive_msg: cleaning up Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1465]: DBG:tm:utimer_routine: timer routine:4,tl=0xaee9ddb0 next=(nil), timeout=28800000 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: ERROR:rtpproxy:send_rtpp_command: can't send command to a RTP proxy Connection refused Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: ERROR:rtpproxy:send_rtpp_command: proxy <udp:127.0.0.1:7890> does not respond, disable it Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rtpproxy:raise_rtpproxy_event: no event sent Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:force_rtp_proxy_body: command sent to rtpproxy, cp = (null), err = 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: rtpproxy node count = 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: node->rn_disabled = 1, node->rn_recheck_ticks = 88, get_ticks = 28 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: INFO:rtpproxy:select_rtpp_node: result rtpp_test = 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: ERROR:rtpproxy:force_rtp_proxy_body: no available proxies Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:rr:add_rr_param: adding (;nat=yes) 0xb72034d0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_newtran: transaction on entrance=(nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=ffffffffffffffff Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:parse_headers: flags=78 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_lookup_request: start searching: hash=9162, isACK=0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d8754z-deac491d4e76a115-1---d8754z- Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_lookup_request: REF_UNSAFE:[0xaee9dc64] after is 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_lookup_request: transaction found (T=0xaee9dc64) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_retransmit_reply: buf=0xb71d26a0: SIP/2.0 1..., shmem=0xaeea056c: SIP/2.0 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:next_state_dlg: unref dlg 0xaee9d0d0 with 1 -> 2 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:next_state_dlg: dialog 0xaee9d0d0 changed from state 1 to state 5, due event 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:dlg_onreply: dialog 0xaee9d0d0 failed (negative reply) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:unref_dlg: unref dlg 0xaee9d0d0 with 1 -> 1 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:tm:t_unref: UNREF_UNSAFE: [0xaee9dc64] after is 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:unref_dlg: unref dlg 0xaee9d0d0 with 1 -> 0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:unref_dlg: ref <=0 for dialog 0xaee9d0d0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:destroy_dlg: destroing dialog 0xaee9d0d0 Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0xaee9d0d0 [918:22964780] with clid 'ZDVmNTUxY2U4 Y1MjdjNTJkNmFmYWNlNDYxMjBmYzA' and tags '0a91bf4c' 'NULL' Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:destroy_avp_list: destroying list (nil) Sep 7 12:09:57 opensips /usr/local/opensips_proxy/sbin/opensips[1456]: DBG:core:receive_msg: cleaning up As you can see there is not a clue about why rtpproxy does not accept connection done by opensips. Maybe Have I to add some LOG sentence inside the rtpproxy module and then recompile it? Is there a way to test the connection of the created socket? Thanks in advance for replies. |
|
|
In reply to this post by SamyGo
Hi,
I have a news regarding logs. Under /var/log/messages I found this error: Sep 7 12:52:52 opensips kernel: [584059.568944] rtpproxy[2256]: segfault at 0 ip 08051334 sp b6ce60f0 error 4 in rtpproxy[8048000+e000] Any idea about what that means?? |
|
|
That simply means your rtpproxy crashed.
How did you install the rtpproxy ? Paste here your few lines of opensips.cfg code where you are calling rtpproxy function !
On Fri, Sep 7, 2012 at 3:55 PM, spady <[hidden email]> wrote: Hi, _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
I installed it by
git clone git://sippy.git.sourceforge.net/gitroot/sippy/rtpproxy then ./configure and then make, make install. Sorry if i cannot understand but i'am not so skilled with opensips. I believe that code, where rtpproxy is called, is this: route[1] { # for INVITEs enable some additional helper routes if (is_method("INVITE")) { if (isflagset(10)) { rtpproxy_offer("ro"); } t_on_branch("2"); t_on_reply("2"); t_on_failure("1"); } if (isflagset(10)) { add_rr_param(";nat=yes"); } if (!t_relay()) { send_reply("500","Internal Error"); }; exit; } branch_route[2] { xlog("new branch at $ru\n"); } onreply_route[2] { if (nat_uac_test("1")) fix_nated_contact(); if ( isflagset(10) ) rtpproxy_answer("ro"); xlog("incoming reply\n"); } |
|
|
Hi again,
I dont see that installation has any issue with OS, next is the version of opensips you are using. Is there any specific reason you are using " rtpproxy_offer("ro");" 1- Is there any specific reason you are using "r" flag !? Next is you are starting your rtpproxy in bridged mode so RTPproxy wants you to tell which IP is Inernal and which is External i,e use "i" and "e" flag to tell your rtpproxy to replace the SDP address from internal to external direction on this INVITE.
If you use rtpproxy_offer() you've to manually do all the other functions like you did too in your reply route. But using engage_rtp_proxy() is far easier. all you need to do is engage, and then unforce RTPproxy on Byes.
Thats all I could possibly come up with to help you resplve your issue. BR Sammy On Fri, Sep 7, 2012 at 5:57 PM, spady <[hidden email]> wrote: I installed it by _______________________________________________ Users mailing list [hidden email] http://lists.opensips.org/cgi-bin/mailman/listinfo/users |
|
|
Hi again and sorry for big delay but i was out of office for long time.
Today I started to have some other test and always get same issue!!! I also tried with a new installation ( debian+opensips 1.8.1+new IPs+rtpproxy). As Sam suggested a tried using engage_rtpproxy but always same issue. I really think problem is just before that script is taken into account. Errors says that opensips CAN'T send command to rtpproxy because "connection " is refused!!. How can I test manually connection to RTPPROXY? Is there such a command from CLI that i can try? Hope someone can help me. Thanks. |
«
Return to OpenSIPS - Users
|
1 view|%1 views
| Free forum by Nabble | Edit this page |