[Serusers] use_dns_cache and call forwarding
Miklos Tirpak
miklos at iptel.org
Thu Jul 24 17:16:11 CEST 2008
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 at 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 at 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 at wsa.lab F=sip:579951 at wsa.lab
> T=sip:579915 at 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 at 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 at 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 at 127.0.0.1:5061 F=sip:579951 at wsa.lab
> T=sip:579915 at 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:
> 1) usr_preferences table entries are these:
> +------+----------+---------+---------------+--------------------+------+---------------------+
> | uuid | username | domain | attribute | value |
> type | modified|
> +------+----------+---------+---------------+--------------------+------+---------------------+
> | | 579915 | wsa.lab | fwdnoanswer | sip:501855 at 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 at 127.0.0.1:5061 --> URI is the forwarding number (???)
> F=sip:579951 at wsa.lab --> FROM is our caller (ok)
> T=sip:579915 at 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 at 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 at 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
>>>
>>>
>>>
>
>
>
More information about the sr-users
mailing list