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