Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote:
Hi guys, I have a problem with call forwarding (on busy or not answer).., the call fall into the failure_route(1) block, and AVP checking and pushto does its job.
Here a snipped of code of failure_route(1) (flag 27 means call fwd if no answer):
if (isflagset(27) && t_check_status("408")) { # if fwd noanswer is set and reply msg is 408
if (avp_pushto("$ruri", "s:fwdnoanswer")) { avp_delete("s:fwdnoanswer"); resetflag(27); avp_print(); log(1, "LOG: --> appending new branch..."); if (!append_branch()){ t_reply("500", "Too many branches?!"); drop; } log(1, "LOG: --> Calling route_6..."); route(6); break;Route(6) finally calls route(1), where t_relay is called. But have a dns failure..and the call never is forwarded.
== ser.log ==
DEBUG: mk_proxy: doing DNS lookup... get_record: lookup(_sip._udp.wsa.lab, 33) failed_ sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ check_via_address(190.244.33.5, 190.244.33.5, 0)_ ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed_ DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ ERROR: w_t_relay (failure mode): forwarding failed_
A question regarding this trouble.....Can I disable use_dns_cache ? SER version is 0.9.7.
there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
What do you recommend? If you need my ser.cfg I can paste it...
Thanks..
-- caio
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote:
Hi guys, I have a problem with call forwarding (on busy or not answer).., the call fall into the failure_route(1) block, and AVP checking and pushto does its job.
Here a snipped of code of failure_route(1) (flag 27 means call fwd if no answer):
if (isflagset(27) && t_check_status("408")) { # if fwd noanswer is set and reply msg is 408
if (avp_pushto("$ruri", "s:fwdnoanswer")) { avp_delete("s:fwdnoanswer"); resetflag(27); avp_print(); log(1, "LOG: --> appending new branch..."); if (!append_branch()){ t_reply("500", "Too many branches?!"); drop; } log(1, "LOG: --> Calling route_6..."); route(6); break;Route(6) finally calls route(1), where t_relay is called. But have a dns failure..and the call never is forwarded.
== ser.log ==
DEBUG: mk_proxy: doing DNS lookup... get_record: lookup(_sip._udp.wsa.lab, 33) failed_ sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ check_via_address(190.244.33.5, 190.244.33.5, 0)_ ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed_ DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ ERROR: w_t_relay (failure mode): forwarding failed_
A question regarding this trouble.....Can I disable use_dns_cache ? SER version is 0.9.7.
there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
What do you recommend? If you need my ser.cfg I can paste it...
Thanks..
-- caio
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer - M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_ Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations: 1) usr_preferences table entries are these: +------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified| +------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
2) check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???) IP=<null> ---> why is it NULL ???
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote:
Hi guys, I have a problem with call forwarding (on busy or not answer).., the call fall into the failure_route(1) block, and AVP checking and pushto does its job.
Here a snipped of code of failure_route(1) (flag 27 means call fwd if no answer):
if (isflagset(27) && t_check_status("408")) { # if fwd noanswer is set and reply msg is 408
if (avp_pushto("$ruri", "s:fwdnoanswer")) { avp_delete("s:fwdnoanswer"); resetflag(27); avp_print(); log(1, "LOG: --> appending new branch..."); if (!append_branch()){ t_reply("500", "Too many branches?!"); drop; } log(1, "LOG: --> Calling route_6..."); route(6); break;Route(6) finally calls route(1), where t_relay is called. But have a dns failure..and the call never is forwarded.
== ser.log ==
DEBUG: mk_proxy: doing DNS lookup... get_record: lookup(_sip._udp.wsa.lab, 33) failed_ sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ check_via_address(190.244.33.5, 190.244.33.5, 0)_ ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed_ DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ ERROR: w_t_relay (failure mode): forwarding failed_
A question regarding this trouble.....Can I disable use_dns_cache ? SER version is 0.9.7.
there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
What do you recommend? If you need my ser.cfg I can paste it...
Thanks..
-- caio
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified| +------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote:
Hi guys, I have a problem with call forwarding (on busy or not answer).., the call fall into the failure_route(1) block, and AVP checking and pushto does its job.
Here a snipped of code of failure_route(1) (flag 27 means call fwd if no answer):
if (isflagset(27) && t_check_status("408")) { # if fwd noanswer is set and reply msg is 408
if (avp_pushto("$ruri", "s:fwdnoanswer")) { avp_delete("s:fwdnoanswer"); resetflag(27); avp_print(); log(1, "LOG: --> appending new branch..."); if (!append_branch()){ t_reply("500", "Too many branches?!"); drop; } log(1, "LOG: --> Calling route_6..."); route(6); break;Route(6) finally calls route(1), where t_relay is called. But have a dns failure..and the call never is forwarded.
== ser.log ==
DEBUG: mk_proxy: doing DNS lookup... get_record: lookup(_sip._udp.wsa.lab, 33) failed_ sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ check_via_address(190.244.33.5, 190.244.33.5, 0)_ ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed_ DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ ERROR: w_t_relay (failure mode): forwarding failed_
A question regarding this trouble.....Can I disable use_dns_cache ? SER version is 0.9.7.
there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
What do you recommend? If you need my ser.cfg I can paste it...
Thanks..
-- caio
It is ok 127.0.0.1:5061 as next hop because here it is asterisk service running at same box.
I set mhomed=yes but not changes at all..
I also make a call direct to 501855 and the call was routed Ok to asterisk but via tcp..
Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:501855@wsa.lab IP=<null>i ID=MDdlY2Q4MWZiNDJjYzBlMDQ0MTdiYTkwYWM4ZWEwNjM._ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_newtran: msg id=18 , global msg id=5 , T on entrance=0xffffffffffffffff_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=60_ Jul 24 14:14:36 [/usr/sbin/ser] t_lookup_request: start searching: hash=8755, isACK=0_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: RFC3261 transaction matching failed_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_lookup_request: no transaction found_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new INVITE_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] WARNING:vqm_resize: resize(0) called_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: reply sent out. buf=0x6ccac8: SIP/2.0 1..., shmem=0x2b540cf4f8b8: SIP/2.0 1_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: _reply_light: finished_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b540cf4cee8_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b540cf4cf08_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new transaction fwd'ed_ Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> T_RELAY okkkkkkk
On Thu, Jul 24, 2008 at 12:16 PM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified|
+------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote:
Hi guys, I have a problem with call forwarding (on busy or not answer).., the call fall into the failure_route(1) block, and AVP checking and pushto does its job.
Here a snipped of code of failure_route(1) (flag 27 means call fwd if no answer):
if (isflagset(27) && t_check_status("408")) { # if fwd noanswer is set and reply msg is 408
if (avp_pushto("$ruri", "s:fwdnoanswer")) { avp_delete("s:fwdnoanswer"); resetflag(27); avp_print(); log(1, "LOG: --> appending new branch..."); if (!append_branch()){ t_reply("500", "Too many branches?!"); drop; } log(1, "LOG: --> Calling route_6..."); route(6); break;Route(6) finally calls route(1), where t_relay is called. But have a dns failure..and the call never is forwarded.
== ser.log ==
DEBUG: mk_proxy: doing DNS lookup... get_record: lookup(_sip._udp.wsa.lab, 33) failed_ sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._ check_via_address(190.244.33.5, 190.244.33.5, 0)_ ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed_ DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ ERROR: w_t_relay (failure mode): forwarding failed_
A question regarding this trouble.....Can I disable use_dns_cache ? SER version is 0.9.7.
there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
What do you recommend? If you need my ser.cfg I can paste it...
Thanks..
-- caio
On 07/24/2008 07:38 PM, caio wrote:
It is ok 127.0.0.1:5061 as next hop because here it is asterisk service running at same box.
I set mhomed=yes but not changes at all..
I also make a call direct to 501855 and the call was routed Ok to asterisk but via tcp..
Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:501855@wsa.lab IP=<null>i ID=MDdlY2Q4MWZiNDJjYzBlMDQ0MTdiYTkwYWM4ZWEwNjM._ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_newtran: msg id=18 , global msg id=5 , T on entrance=0xffffffffffffffff_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=60_ Jul 24 14:14:36 [/usr/sbin/ser] t_lookup_request: start searching: hash=8755, isACK=0_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: RFC3261 transaction matching failed_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_lookup_request: no transaction found_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new INVITE_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] WARNING:vqm_resize: resize(0) called_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: reply sent out. buf=0x6ccac8: SIP/2.0 1..., shmem=0x2b540cf4f8b8: SIP/2.0 1_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: _reply_light: finished_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._
This part of the log is different from the previous one, because there is no SRV lookup. It seems that SER tries to send the call to wsa.lab even if the RURI was rewritten to 127.0.0.1:5061 in case of call forwarding, and in the above log there was probably no DNS lookup at all, just the log message.
Do you set the destination URI to wsa.lab in failure_route, or in any other route that is called from there? Could you print out the RURI and the destination URI as well just before t_relay() is called?
Miklos
Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b540cf4cee8_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b540cf4cf08_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new transaction fwd'ed_ Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> T_RELAY okkkkkkk
On Thu, Jul 24, 2008 at 12:16 PM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified|
+------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/23/2008 05:22 PM, caio wrote: > Hi guys, > I have a problem with call forwarding (on busy or not answer).., the > call fall into the failure_route(1) block, and AVP checking and pushto > does its job. > > Here a snipped of code of failure_route(1) (flag 27 means call fwd if > no answer): > > if (isflagset(27) && t_check_status("408")) { # if fwd no > answer is set and reply msg is 408 > > if (avp_pushto("$ruri", "s:fwdnoanswer")) { > avp_delete("s:fwdnoanswer"); > resetflag(27); > > avp_print(); > > log(1, "LOG: --> appending new branch..."); > if (!append_branch()){ > t_reply("500", "Too many branches?!"); > drop; > } > > log(1, "LOG: --> Calling route_6..."); > route(6); > break; > > Route(6) finally calls route(1), where t_relay is called. > But have a dns failure..and the call never is forwarded. > > == ser.log == > > DEBUG: mk_proxy: doing DNS lookup... > get_record: lookup(_sip._udp.wsa.lab, 33) failed_ > sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' > lookup..._ > check_via_address(190.244.33.5, 190.244.33.5, 0)_ > ERROR: udp_send: sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): > Operation not permitted(1)_ > msg_send: ERROR: udp_send failed_ > ERROR: t_forward_nonack: sending request failed_ > DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ > DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ > ERROR: w_t_relay (failure mode): forwarding failed_ > > A question regarding this trouble.....Can I disable use_dns_cache ? > SER version is 0.9.7. there is no DNS cache in version 0.9.x as I recall, but anyway, your problem does not seem to be related to DNS, but to the UDP message sending: SER fails to send out the UDP packet, "Operation not permitted". Is there no firewall or routing problem at the proxy side?
Miklos
> What do you recommend? > If you need my ser.cfg I can paste it... > > Thanks.. >
-- caio
do you mean rewriting with rewritehostport? No is the answer, in failure_route the host port is not touched.
previously to take route(1), sip-message look like this:
Jul 25 09:25:37 [/usr/sbin/ser] LOG ==> Route 1 <==
Jul 25 09:25:37 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 160_ Jul 25 09:25:37 [/usr/sbin/ser] XLOG: t_relay: M=INVITE ___ RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=OTc0YWI0YzkzZTQxNjJkNGQ2ZmFkNWI4NzdhNzZhNmQ.
Once I tried to do a "#rewritehostport("wsa.lab");" in failure_route, but the error was the same..
ERROR: udp_send: sendto(sock,0x2b3c700159c0,907,0,0x2b3c70018b38,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed
I think the best would be do a ser.cfg from scratch again.., if you know about links or ser.cfg running under SER 0.9.7 ok please tell me..
Any comment is welcome.. Thank you Miklos...
On Fri, Jul 25, 2008 at 3:56 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 07:38 PM, caio wrote:
It is ok 127.0.0.1:5061 as next hop because here it is asterisk service running at same box.
I set mhomed=yes but not changes at all..
I also make a call direct to 501855 and the call was routed Ok to asterisk but via tcp..
Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:501855@wsa.lab IP=<null>i ID=MDdlY2Q4MWZiNDJjYzBlMDQ0MTdiYTkwYWM4ZWEwNjM._ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_newtran: msg id=18 , global msg id=5 , T on entrance=0xffffffffffffffff_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=60_ Jul 24 14:14:36 [/usr/sbin/ser] t_lookup_request: start searching: hash=8755, isACK=0_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: RFC3261 transaction matching failed_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_lookup_request: no transaction found_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new INVITE_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] WARNING:vqm_resize: resize(0) called_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: reply sent out. buf=0x6ccac8: SIP/2.0 1..., shmem=0x2b540cf4f8b8: SIP/2.0 1_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: _reply_light: finished_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._
This part of the log is different from the previous one, because there is no SRV lookup. It seems that SER tries to send the call to wsa.lab even if the RURI was rewritten to 127.0.0.1:5061 in case of call forwarding, and in the above log there was probably no DNS lookup at all, just the log message.
Do you set the destination URI to wsa.lab in failure_route, or in any other route that is called from there? Could you print out the RURI and the destination URI as well just before t_relay() is called?
Miklos
Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b540cf4cee8_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b540cf4cf08_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new transaction fwd'ed_ Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> T_RELAY okkkkkkk
On Thu, Jul 24, 2008 at 12:16 PM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified|
+------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote:
Hi Miklos, This happens only when I try to do a call to a subcriber having forwarding enabled.
Normal calls success ok. I'm not sure about the append_branch() usage and how to work with 'on busy' and 'no answer' forwarding features.
The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
Thanks your comments..
Claudio
On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org wrote: > > Hi, > > On 07/23/2008 05:22 PM, caio wrote: >> >> Hi guys, >> I have a problem with call forwarding (on busy or not answer).., the >> call fall into the failure_route(1) block, and AVP checking and >> pushto >> does its job. >> >> Here a snipped of code of failure_route(1) (flag 27 means call fwd >> if >> no answer): >> >> if (isflagset(27) && t_check_status("408")) { # if fwd no >> answer is set and reply msg is 408 >> >> if (avp_pushto("$ruri", "s:fwdnoanswer")) { >> avp_delete("s:fwdnoanswer"); >> resetflag(27); >> >> avp_print(); >> >> log(1, "LOG: --> appending new branch..."); >> if (!append_branch()){ >> t_reply("500", "Too many branches?!"); >> drop; >> } >> >> log(1, "LOG: --> Calling route_6..."); >> route(6); >> break; >> >> Route(6) finally calls route(1), where t_relay is called. >> But have a dns failure..and the call never is forwarded. >> >> == ser.log == >> >> DEBUG: mk_proxy: doing DNS lookup... >> get_record: lookup(_sip._udp.wsa.lab, 33) failed_ >> sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' >> lookup..._ >> check_via_address(190.244.33.5, 190.244.33.5, 0)_ >> ERROR: udp_send: >> sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): >> Operation not permitted(1)_ >> msg_send: ERROR: udp_send failed_ >> ERROR: t_forward_nonack: sending request failed_ >> DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ >> DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ >> ERROR: w_t_relay (failure mode): forwarding failed_ >> >> A question regarding this trouble.....Can I disable use_dns_cache ? >> SER version is 0.9.7. > > there is no DNS cache in version 0.9.x as I recall, but anyway, your > problem > does not seem to be related to DNS, but to the UDP message sending: > SER > fails to send out the UDP packet, "Operation not permitted". Is there > no > firewall or routing problem at the proxy side? > > Miklos > >> What do you recommend? >> If you need my ser.cfg I can paste it... >> >> Thanks.. >>
-- caio
Hi,
On 07/25/2008 11:22 PM, caio wrote:
do you mean rewriting with rewritehostport? No is the answer, in failure_route the host port is not touched.
you do rewrite the RURI with avp_pushto("$ruri", "s:fwdnoanswer") in failure_route, it substitutes the host and port as well just like rewritehostport.
Actually I meant destination URI not Request URI. Destination URI does not appear in the SIP message, but it takes precedence over the RURI in the next hop determination.
Anyway you wrote previously that calls are successfully routed to Asterisk via TCP, but this is a different case, because SER fails to send out the UDP packets. So it would be worth verifying that a simple call can be routed to Asterisk via UDP as well.
previously to take route(1), sip-message look like this:
Jul 25 09:25:37 [/usr/sbin/ser] LOG ==> Route 1 <==
Jul 25 09:25:37 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 160_ Jul 25 09:25:37 [/usr/sbin/ser] XLOG: t_relay: M=INVITE ___ RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=OTc0YWI0YzkzZTQxNjJkNGQ2ZmFkNWI4NzdhNzZhNmQ.
Once I tried to do a "#rewritehostport("wsa.lab");" in failure_route, but the error was the same..
ERROR: udp_send: sendto(sock,0x2b3c700159c0,907,0,0x2b3c70018b38,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed
I think the best would be do a ser.cfg from scratch again.., if you know about links or ser.cfg running under SER 0.9.7 ok please tell me..
If you would like to set up a new proxy, than forget 0.9.7, and do it with 2.0, it is supposed to be stable by now.
Miklos
Any comment is welcome.. Thank you Miklos...
On Fri, Jul 25, 2008 at 3:56 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 07:38 PM, caio wrote:
It is ok 127.0.0.1:5061 as next hop because here it is asterisk service running at same box.
I set mhomed=yes but not changes at all..
I also make a call direct to 501855 and the call was routed Ok to asterisk but via tcp..
Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:501855@wsa.lab IP=<null>i ID=MDdlY2Q4MWZiNDJjYzBlMDQ0MTdiYTkwYWM4ZWEwNjM._ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_newtran: msg id=18 , global msg id=5 , T on entrance=0xffffffffffffffff_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=60_ Jul 24 14:14:36 [/usr/sbin/ser] t_lookup_request: start searching: hash=8755, isACK=0_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: RFC3261 transaction matching failed_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_lookup_request: no transaction found_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new INVITE_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] WARNING:vqm_resize: resize(0) called_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: reply sent out. buf=0x6ccac8: SIP/2.0 1..., shmem=0x2b540cf4f8b8: SIP/2.0 1_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: _reply_light: finished_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._
This part of the log is different from the previous one, because there is no SRV lookup. It seems that SER tries to send the call to wsa.lab even if the RURI was rewritten to 127.0.0.1:5061 in case of call forwarding, and in the above log there was probably no DNS lookup at all, just the log message.
Do you set the destination URI to wsa.lab in failure_route, or in any other route that is called from there? Could you print out the RURI and the destination URI as well just before t_relay() is called?
Miklos
Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b540cf4cee8_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b540cf4cf08_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new transaction fwd'ed_ Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> T_RELAY okkkkkkk
On Thu, Jul 24, 2008 at 12:16 PM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified|
+------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 01:11 PM, caio wrote: > Hi Miklos, > This happens only when I try to do a call to a subcriber having > forwarding enabled. > > Normal calls success ok. I'm not sure about the append_branch() usage > and how to work with 'on busy' and 'no answer' forwarding features. The config script looks fine, I suppose you see the log messages "LOG: --> appending new branch..." and "LOG: --> Calling route_6..." before the error logs you posted.
SER tries to forward the call to wsa.lab. It tries to resolve the SRV record first without success, than resolves the A record (there is no error, so the resolution is ok).
I believe there is a routing or firewall problem, because sendto() function returns with error, so the issue is not SER-related in my opinion, try to google for "sendto operation not permitted". Disable iptables or any other firewall you have, verify that the routing is correct, and SER listens on the interface that is used to send out the packet.
I would also try to send a call to wsa.lab without failure route with a very simple ser script.
Miklos
> Thanks your comments.. > > Claudio > > On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org > wrote: >> Hi, >> >> On 07/23/2008 05:22 PM, caio wrote: >>> Hi guys, >>> I have a problem with call forwarding (on busy or not answer).., the >>> call fall into the failure_route(1) block, and AVP checking and >>> pushto >>> does its job. >>> >>> Here a snipped of code of failure_route(1) (flag 27 means call fwd >>> if >>> no answer): >>> >>> if (isflagset(27) && t_check_status("408")) { # if fwd no >>> answer is set and reply msg is 408 >>> >>> if (avp_pushto("$ruri", "s:fwdnoanswer")) { >>> avp_delete("s:fwdnoanswer"); >>> resetflag(27); >>> >>> avp_print(); >>> >>> log(1, "LOG: --> appending new branch..."); >>> if (!append_branch()){ >>> t_reply("500", "Too many branches?!"); >>> drop; >>> } >>> >>> log(1, "LOG: --> Calling route_6..."); >>> route(6); >>> break; >>> >>> Route(6) finally calls route(1), where t_relay is called. >>> But have a dns failure..and the call never is forwarded. >>> >>> == ser.log == >>> >>> DEBUG: mk_proxy: doing DNS lookup... >>> get_record: lookup(_sip._udp.wsa.lab, 33) failed_ >>> sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' >>> lookup..._ >>> check_via_address(190.244.33.5, 190.244.33.5, 0)_ >>> ERROR: udp_send: >>> sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): >>> Operation not permitted(1)_ >>> msg_send: ERROR: udp_send failed_ >>> ERROR: t_forward_nonack: sending request failed_ >>> DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ >>> DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ >>> ERROR: w_t_relay (failure mode): forwarding failed_ >>> >>> A question regarding this trouble.....Can I disable use_dns_cache ? >>> SER version is 0.9.7. >> there is no DNS cache in version 0.9.x as I recall, but anyway, your >> problem >> does not seem to be related to DNS, but to the UDP message sending: >> SER >> fails to send out the UDP packet, "Operation not permitted". Is there >> no >> firewall or routing problem at the proxy side? >> >> Miklos >> >>> What do you recommend? >>> If you need my ser.cfg I can paste it... >>> >>> Thanks.. >>> > -- > caio > > >
I've just upgrade my system kernel (2.6.24-r3 --> 2.6.25-r7) and things have changed, but only when I restart SER service.
If a I restart SER, the first call I make to a user who has forward on no answer enabled, it seem to work., but at the second call it fails again (with udp_send msg). Then, restart SER again, and first call works, but all the following calls fail..., and etc..
I think there is something crashing when the forward is made, do not know if is kernel-related or ser-0.9.x.
Next step, surely ser version 2.0.
If you're courious I can paste you the logs...
Regards, claudio.
On Mon, Jul 28, 2008 at 4:43 AM, Miklos Tirpak miklos@iptel.org wrote:
Hi,
On 07/25/2008 11:22 PM, caio wrote:
do you mean rewriting with rewritehostport? No is the answer, in failure_route the host port is not touched.
you do rewrite the RURI with avp_pushto("$ruri", "s:fwdnoanswer") in failure_route, it substitutes the host and port as well just like rewritehostport.
Actually I meant destination URI not Request URI. Destination URI does not appear in the SIP message, but it takes precedence over the RURI in the next hop determination.
Anyway you wrote previously that calls are successfully routed to Asterisk via TCP, but this is a different case, because SER fails to send out the UDP packets. So it would be worth verifying that a simple call can be routed to Asterisk via UDP as well.
previously to take route(1), sip-message look like this:
Jul 25 09:25:37 [/usr/sbin/ser] LOG ==> Route 1 <==
Jul 25 09:25:37 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 160_ Jul 25 09:25:37 [/usr/sbin/ser] XLOG: t_relay: M=INVITE ___ RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=OTc0YWI0YzkzZTQxNjJkNGQ2ZmFkNWI4NzdhNzZhNmQ.
Once I tried to do a "#rewritehostport("wsa.lab");" in failure_route, but the error was the same..
ERROR: udp_send: sendto(sock,0x2b3c700159c0,907,0,0x2b3c70018b38,16): Operation not permitted(1)_ msg_send: ERROR: udp_send failed_ ERROR: t_forward_nonack: sending request failed
I think the best would be do a ser.cfg from scratch again.., if you know about links or ser.cfg running under SER 0.9.7 ok please tell me..
If you would like to set up a new proxy, than forget 0.9.7, and do it with 2.0, it is supposed to be stable by now.
Miklos
Any comment is welcome.. Thank you Miklos...
On Fri, Jul 25, 2008 at 3:56 AM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 07:38 PM, caio wrote:
It is ok 127.0.0.1:5061 as next hop because here it is asterisk service running at same box.
I set mhomed=yes but not changes at all..
I also make a call direct to 501855 and the call was routed Ok to asterisk but via tcp..
Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 14:14:36 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:501855@wsa.lab IP=<null>i ID=MDdlY2Q4MWZiNDJjYzBlMDQ0MTdiYTkwYWM4ZWEwNjM._ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_newtran: msg id=18 , global msg id=5 , T on entrance=0xffffffffffffffff_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=60_ Jul 24 14:14:36 [/usr/sbin/ser] t_lookup_request: start searching: hash=8755, isACK=0_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: RFC3261 transaction matching failed_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: t_lookup_request: no transaction found_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new INVITE_ Jul 24 14:14:36 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] WARNING:vqm_resize: resize(0) called_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: reply sent out. buf=0x6ccac8: SIP/2.0 1..., shmem=0x2b540cf4f8b8: SIP/2.0 1_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: _reply_light: finished_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._
This part of the log is different from the previous one, because there is no SRV lookup. It seems that SER tries to send the call to wsa.lab even if the RURI was rewritten to 127.0.0.1:5061 in case of call forwarding, and in the above log there was probably no DNS lookup at all, just the log message.
Do you set the destination URI to wsa.lab in failure_route, or in any other route that is called from there? Could you print out the RURI and the destination URI as well just before t_relay() is called?
Miklos
Jul 24 14:14:36 [/usr/sbin/ser] check_via_address(190.244.33.5, 190.244.33.5, 0)_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b540cf4cee8_ Jul 24 14:14:36 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b540cf4cf08_ Jul 24 14:14:36 [/usr/sbin/ser] SER: new transaction fwd'ed_ Jul 24 14:14:36 [/usr/sbin/ser] LOG: --> T_RELAY okkkkkkk
On Thu, Jul 24, 2008 at 12:16 PM, Miklos Tirpak miklos@iptel.org wrote:
On 07/24/2008 04:38 PM, caio wrote:
Ok, I understand the dns lookup is working (however no SRV resolution, doesn't matter).. I've disabled iptables (via shorewall) and verify that ser listen on:
# netstat -nlp Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 <public_ip>:5060 0.0.0.0:* LISTEN 29557/ser udp 0 0 <public_ip>:5060 0.0.0.0:* 29557/ser
But still the same error... Here the log (from when the failure_route begins), you can observe what you've told before, those logs are printed before the "sendto" failure..
Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> FAILURE_ROUTE[1] BLOCK BEGINS.... Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: msg id=1 global id=1 T start=0x2b7003fb9d90_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: t_check: T already found!_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:t_check_status: checked status is <408>_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding call on NO Answer (isflagset(27) and timedout call)... _ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:pushto_avps: 1 avps were processed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9d48, flags=1_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<inv_timeout>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_int=<15>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:print_avp: p=0x2b7003fb9ce8, flags=B_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___name=<fwdnoanswer>_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:___val_str=sip:501855@wsa.lab_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> appending new branch... Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 37_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: current uri: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 175_ Jul 24 11:23:06 [/usr/sbin/ser] failure_route - call forward no answer
- M=INVITE RURI=sip:501855@wsa.lab F=sip:579951@wsa.lab
T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
This is fine, the RURI is rewritten to the forwarding destination.
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG:avpops:remove_avps: 1 avps were removed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling route_6... Jul 24 11:23:06 [/usr/sbin/ser] lookup(): '501855@wsa.lab' Not found in usrloc_ - Last output repeated twice - Jul 24 11:23:06 [/usr/sbin/ser] does_uri_exit(): User in request uri does not exist_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 80_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: After a NEW lookup(location) in route_6 block .. R-URI: sip:501855@wsa.lab Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Calling Route_5 block Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> Forwarding to Asterisk GW _ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: xl_print_log: final buffer length 158_ Jul 24 11:23:06 [/usr/sbin/ser] XLOG: t_relay: - M=INVITE RURI=sip:501855@127.0.0.1:5061 F=sip:579951@wsa.lab T=sip:579915@wsa.lab IP=<null>i ID=Y2E0ZGQyZDNjM2IzYzBmZjhmMWI1YjE3NWFiYWQ5YWQ._
The RURI no longer contains wsa.lab, it points to 127.0.0.1:5061 Is this what you want?
Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: mk_proxy: doing DNS lookup..._ Jul 24 11:23:06 [/usr/sbin/ser] get_record: lookup(_sip._udp.wsa.lab, 33) failed_ Jul 24 11:23:06 [/usr/sbin/ser] sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' lookup..._
From this it seems that SER still tries to get the IP for wsa.lab, did this is confusing.
Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: udp_send: sendto(sock,0x2b7003fbc920,908,0,0x2b7003fba070,16): Operation not permitted(1)_
Try to verify somehow, that the next host SER is trying to send the packet is not 127.0.0.1:5061. If 127.0.0.1:5061 is the next hop, and no process listens on port 5061, than you can get this error I guess.
Or if you want SER to forward the request to 127.0.0.1:5061, and this is the correct next hop, than it may happen that the outgoing interface was wrongly determined, try to enable mhomed in the config file.
Jul 24 11:23:06 [/usr/sbin/ser] msg_send: ERROR: udp_send failed_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: t_forward_nonack: sending request failed_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[4]: 0x2b7003fba088_ Jul 24 11:23:06 [/usr/sbin/ser] DEBUG: add_to_tail_of_timer[0]: 0x2b7003fba0a8_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: w_t_relay (failure mode): forwarding failed_ Jul 24 11:23:06 [/usr/sbin/ser] LOG: --> T_RELAY failed! fuck... Jul 24 11:23:06 [/usr/sbin/ser] parse_headers: flags=-1_ Jul 24 11:23:06 [/usr/sbin/ser] check_via_address(a.b.c.d, a.b.c.d, 0)_ Jul 24 11:23:06 [/usr/sbin/ser] ERROR: sl_reply_error used: I'm terribly sorry, server error occurred (1/SL)_
Observations:
- usr_preferences table entries are these:
+------+----------+---------+---------------+--------------------+------+---------------------+ | uuid | username | domain | attribute | value | type | modified|
+------+----------+---------+---------------+--------------------+------+---------------------+ | | 579915 | wsa.lab | fwdnoanswer | sip:501855@wsa.lab | 0 | 2008-07-24 10:55:37 |
where 579915 are a local subscriber, and 501855 is a PSTN-user (via asterisk gw)..
- check_via_address(a.b.c.d, a.b.c.d, 0) where a.b.c.d is the IP of
the caller SIP-UA (xlite softphone) 3) look at the current URI at the moment of t_relay() call...the line before this msg "DEBUG: mk_proxy: doing DNS lookup" Is it well-formed? M=INVITE RURI=sip:501855@127.0.0.1:5061 --> URI is the forwarding number (???) F=sip:579951@wsa.lab --> FROM is our caller (ok) T=sip:579915@wsa.lab --> TO field is the subscriber who has callfwd enabled, (???)
Yes this is correct. The To HF cannot be modified, the RURI should contain the new destination.
IP=<null> ---> why is it NULL ???
The destination ip address is probably not yet known at the time the log message is issued, it should not be a problem.
Miklos
claudio
On Thu, Jul 24, 2008 at 10:32 AM, Miklos Tirpak miklos@iptel.org wrote: > > On 07/24/2008 01:11 PM, caio wrote: >> >> Hi Miklos, >> This happens only when I try to do a call to a subcriber having >> forwarding enabled. >> >> Normal calls success ok. I'm not sure about the append_branch() >> usage >> and how to work with 'on busy' and 'no answer' forwarding features. > > The config script looks fine, I suppose you see the log messages > "LOG: > --> > appending new branch..." and "LOG: --> Calling route_6..." before the > error > logs you posted. > > SER tries to forward the call to wsa.lab. It tries to resolve the SRV > record > first without success, than resolves the A record (there is no error, > so > the > resolution is ok). > > I believe there is a routing or firewall problem, because sendto() > function > returns with error, so the issue is not SER-related in my opinion, > try > to > google for "sendto operation not permitted". Disable iptables or any > other > firewall you have, verify that the routing is correct, and SER > listens > on > the interface that is used to send out the packet. > > I would also try to send a call to wsa.lab without failure route with > a > very > simple ser script. > > Miklos > >> Thanks your comments.. >> >> Claudio >> >> On Thu, Jul 24, 2008 at 4:58 AM, Miklos Tirpak miklos@iptel.org >> wrote: >>> >>> Hi, >>> >>> On 07/23/2008 05:22 PM, caio wrote: >>>> >>>> Hi guys, >>>> I have a problem with call forwarding (on busy or not answer).., >>>> the >>>> call fall into the failure_route(1) block, and AVP checking and >>>> pushto >>>> does its job. >>>> >>>> Here a snipped of code of failure_route(1) (flag 27 means call fwd >>>> if >>>> no answer): >>>> >>>> if (isflagset(27) && t_check_status("408")) { # if fwd no >>>> answer is set and reply msg is 408 >>>> >>>> if (avp_pushto("$ruri", "s:fwdnoanswer")) { >>>> avp_delete("s:fwdnoanswer"); >>>> resetflag(27); >>>> >>>> avp_print(); >>>> >>>> log(1, "LOG: --> appending new branch..."); >>>> if (!append_branch()){ >>>> t_reply("500", "Too many branches?!"); >>>> drop; >>>> } >>>> >>>> log(1, "LOG: --> Calling route_6..."); >>>> route(6); >>>> break; >>>> >>>> Route(6) finally calls route(1), where t_relay is called. >>>> But have a dns failure..and the call never is forwarded. >>>> >>>> == ser.log == >>>> >>>> DEBUG: mk_proxy: doing DNS lookup... >>>> get_record: lookup(_sip._udp.wsa.lab, 33) failed_ >>>> sip_resolvehost: no SRV record found for wsa.lab, trying 'normal' >>>> lookup..._ >>>> check_via_address(190.244.33.5, 190.244.33.5, 0)_ >>>> ERROR: udp_send: >>>> sendto(sock,0x2ab32599c720,910,0,0x2ab325999e68,16): >>>> Operation not permitted(1)_ >>>> msg_send: ERROR: udp_send failed_ >>>> ERROR: t_forward_nonack: sending request failed_ >>>> DEBUG: add_to_tail_of_timer[4]: 0x2ab325999e80_ >>>> DEBUG: add_to_tail_of_timer[0]: 0x2ab325999ea0_ >>>> ERROR: w_t_relay (failure mode): forwarding failed_ >>>> >>>> A question regarding this trouble.....Can I disable use_dns_cache >>>> ? >>>> SER version is 0.9.7. >>> >>> there is no DNS cache in version 0.9.x as I recall, but anyway, >>> your >>> problem >>> does not seem to be related to DNS, but to the UDP message sending: >>> SER >>> fails to send out the UDP packet, "Operation not permitted". Is >>> there >>> no >>> firewall or routing problem at the proxy side? >>> >>> Miklos >>> >>>> What do you recommend? >>>> If you need my ser.cfg I can paste it... >>>> >>>> Thanks.. >>>> >> -- >> caio >> >> >>
-
caio -
Miklos Tirpak