[Serusers] use_dns_cache and call forwarding
caio
elcaio at gmail.com
Thu Jul 24 19:38:31 CEST 2008
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..._
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