[Serusers] use_dns_cache and call forwarding

caio elcaio at gmail.com
Tue Jul 29 22:52:11 CEST 2008


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 at 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 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
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>
>>>>
>>>>
>>
>>
>>
>



-- 
caio



More information about the sr-users mailing list