[Serusers] use_dns_cache and call forwarding
Miklos Tirpak
miklos at iptel.org
Mon Jul 28 09:43:45 CEST 2008
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 at 127.0.0.1:5061 F=sip:579951 at wsa.lab
> T=sip:579915 at 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 at 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 at 127.0.0.1:5061 F=sip:579951 at wsa.lab
>>> T=sip:501855 at 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 at 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 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