25 Mar
2011
25 Mar
'11
2:30 p.m.
On Thu, 2011-03-24 at 14:14 +0100, Daniel-Constantin Mierla wrote:
Are you calling msg apply changes after
record_route()? Try to do
record_route() after since it tries to discover the outgoing local
interface which might not be set at that point.
This has fixed the problem.
Also I'm wondering how exactly mechanics of reparsing works?
1. Message has been changed. By the way, can I change the $rU and $tU
variables and then use msg_apply_changes()? Will it work or I can work
only with adding/removing headers from the packet?
2. Function msg_apply_changes() is used, just like
msg_apply_changes();
Question is execution of script will continue just after this call with
reparsed packet or will run the script again? Debug shows that will
continue from that point, but I'm unsure that I'm working with reparsed
packet.
Can you clearify this?
Thank you.
Btw, is Kamailio bridging between two networks?
The output with '-E -ddd' will be helpful anyho
6(28419) NOTICE: <script>: [Fri Mar 25 12:09:43 2011] SUBSCRIBE
Authorized 17_100 -> 0
6(28419) DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking
if host==us: 14==9 && [xxx.xxx.xxx.xxx] == [127.0.0.1]
6(28419) DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking
if port 5060 matches port 5060
6(28419) DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking
if host==us: 14==14 && [xxx.xxx.xxx.xxx] == [xxx.xxx.xxx.xxx]
6(28419) DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking
if port 5060 matches port 5060
6(28419) DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=2 ,
global msg id=2 , T on entrance=(nil)
6(28419) DEBUG: tm [t_lookup.c:528]: t_lookup_request: start searching:
hash=19412, isACK=0
6(28419) DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction
matching failed
6(28419) DEBUG: tm [t_lookup.c:711]: DEBUG: t_lookup_request: no
transaction found
6(28419) DEBUG: tm [t_hooks.c:374]: DBG: trans=0xb6153c00, callback
type 1, id 0 entered
6(28419) DEBUG: tm [t_hooks.c:374]: DBG: trans=0xb6153c00, callback
type 1, id 0 entered
6(28419) DEBUG: <core> [re.c:454]: subst_run: running. r=1
6(28419) DEBUG: <core> [re.c:523]: subst_str: no match
6(28419) DEBUG: textops [txt_var.c:69]: no match for subst expression
6(28419) DEBUG: <core> [re.c:454]: subst_run: running. r=0
6(28419) DEBUG: <core> [re.c:475]: subst_run: matched (0, 6): [17_100]
6(28419) NOTICE: <script>: [Fri Mar 25 12:09:43 2011] Prepending number
with customer ID: 0 -> 17_0
6(28419) DEBUG: <core> [re.c:454]: subst_run: running. r=0
6(28419) DEBUG: <core> [re.c:475]: subst_run: matched (0, 6): [17_100]
6(28419) NOTICE: <script>: [Fri Mar 25 12:09:43 2011] Converted request
URI to: 17_0
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:859]: FIXME: lumps_len called with
null send_sock
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:1340]: FIXME: process_lumps: null
bind_address
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) : <core> [msg_translator.c:519]: ERROR: lump_check_opt: null
send socket
6(28419) DEBUG: textopsx [textopsx.c:140]: SIP Request content updated
- reparsing
6(28419) DEBUG: <core> [parser/msg_parser.c:630]: SIP Request:
6(28419) DEBUG: <core> [parser/msg_parser.c:632]: method: <SUBSCRIBE>
6(28419) DEBUG: <core> [parser/msg_parser.c:634]: uri:
<sip:17_0@xxx.xxx.xxx.xxx>
6(28419) DEBUG: <core> [parser/msg_parser.c:636]: version: <SIP/2.0>
6(28419) DEBUG: <core> [parser/parse_via.c:1287]: Found param type 232,
<branch> = <z9hG4bK307388744>; state=16
6(28419) DEBUG: <core> [parser/parse_via.c:2300]: end of header
reached, state=5
6(28419) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: Via
found, flags=2
6(28419) DEBUG: <core> [parser/msg_parser.c:517]: parse_headers: this
is the first via
6(28419) DEBUG: <core> [parser/parse_to.c:803]: end of header reached,
state=10
6(28419) DEBUG: <core> [parser/msg_parser.c:187]: DEBUG: get_hdr_field:
<To> [24]; uri=[sip:0@xxx.xxx.xxx.xxx]
6(28419) DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body
[<sip:0@xxx.xxx.xxx.xxx>
]
6(28419) DEBUG: <core> [parser/msg_parser.c:167]: get_hdr_field: cseq
<CSeq>: <3> <SUBSCRIBE>
6(28419) DEBUG: <core> [parser/msg_parser.c:201]: DEBUG: get_hdr_body :
content_length=0
6(28419) DEBUG: <core> [parser/msg_parser.c:103]: found end of header
6(28419) DEBUG: presence [event_list.c:354]: start event= [dialog/5]
6(28419) DEBUG: presence [subscribe.c:773]: 'Expires' header found,
value= 60
6(28419) DEBUG: presence [subscribe.c:795]: 'To' header ALREADY PARSED:
<sip:0@xxx.xxx.xxx.xxx>
6(28419) DEBUG: presence [subscribe.c:834]: 'From' header not parsed
6(28419) DEBUG: <core> [parser/parse_to.c:174]: DEBUG: add_param:
tag=123926587
6(28419) DEBUG: <core> [parser/parse_to.c:803]: end of header reached,
state=29
6(28419) DEBUG: presence [subscribe.c:864]: generating to_tag
6(28419) DEBUG: sl [sl.c:327]: totag stateful mode (tm)
6(28419) DEBUG: presence [subscribe.c:918]: subs->contact=
sip:17_100@91.72.15.26:1081 - len = 27
6(28419) DEBUG: <core> [parser_helpers.c:104]: current rr is
<sip:;r2=on;lr=on;ftag=123926587>
6(28419) DEBUG: <core> [parser_helpers.c:104]: current rr is
<sip:xxx.xxx.xxx.xxx;r2=on;lr=on;ftag=123926587>
6(28419) DEBUG: <core> [parser_helpers.c:167]: out rr
[<sip:;r2=on;lr=on;ftag=123926587>,<sip:xxx.xxx.xxx.xxx;r2=on;lr=on;ftag=123926587>]
6(28419) DEBUG: <core> [parser_helpers.c:168]: we have 2 records
6(28419) DEBUG: presence [subscribe.c:682]: subscription status= active
- found in watcher table
6(28419) DEBUG: presence [notify.c:122]:
[pres_uri]= sip:17_0@xxx.xxx.xxx.xxx
[to_user]= 0 [to_domain]= xxx.xxx.xxx.xxx
[w_user]= 17_100 [w_domain]= xxx.xxx.xxx.xxx
[event]= dialog
[status]= active
[expires]= 60
[callid]= 940932806(a)176.249.0.2 [local_cseq]=0
[to_tag]= a6a1c5f60faecf035a1ae5b6e96e979a-6003 [from_tag]= 123926587
[contact]= sip:17_100@91.72.15.26:1081 [record_route]=
<sip:;r2=on;lr=on;ftag=123926587>,<sip:xxx.xxx.xxx.xxx;r2=on;lr=on;ftag=123926587>
6(28419) DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=2
global id=2 T start=0xb6153c00
6(28419) DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already
found!
6(28419) DEBUG: <core> [msg_translator.c:204]:
check_via_address(91.72.15.26, yyy.yyy.yyy.yyy, 0)
6(28419) DEBUG: <core> [mem/shm_mem.c:105]: WARNING:vqm_resize:
resize(0) called
6(28419) DEBUG: tm [t_reply.c:1470]: DEBUG: cleanup_uac_timers: RETR/FR
timers reset
6(28419) DEBUG: tm [t_reply.c:659]: DEBUG: reply sent out.
buf=0x834f5dc: SIP/2.0 202 OK
Reco..., shmem=0xb6155c8c: SIP/2.0 202 OK
Reco
6(28419) DEBUG: tm [t_reply.c:669]: DEBUG: _reply_light: finished
6(28419) DEBUG: sl [sl.c:273]: reply in stateful mode (tm)
6(28419) DEBUG: presence [notify.c:1461]: dialog info:
6(28419) DEBUG: presence [notify.c:122]:
[pres_uri]= sip:17_0@xxx.xxx.xxx.xxx
[to_user]= 0 [to_domain]= xxx.xxx.xxx.xxx
[w_user]= 17_100 [w_domain]= xxx.xxx.xxx.xxx
[event]= dialog
[status]= active
[expires]= 60
[callid]= 940932806(a)176.249.0.2 [local_cseq]=0
[to_tag]= a6a1c5f60faecf035a1ae5b6e96e979a-6003 [from_tag]= 123926587
[contact]= sip:17_100@yyy.yyy.yyy.yyy:1081 [record_route]=
<sip:;r2=on;lr=on;ftag=123926587>,<sip:xxx.xxx.xxx.xxx;r2=on;lr=on;ftag=123926587>
6(28419) DEBUG: presence [hash.c:471]: pres_uri=
sip:17_0@xxx.xxx.xxx.xxx
6(28419) DEBUG: presence [notify.c:643]: No record exists in hash_table
6(28419) DEBUG: presence_dialoginfo [notify_body.c:67]:
[pres_user]=17_0 [pres_domain]= xxx.xxx.xxx.xxx, [n]=0
6(28419) DEBUG: presence [notify.c:1515]: Could not get the notify_body
6(28419) DEBUG: presence [notify.c:234]: expires = 60
6(28419) DEBUG: presence [notify.c:1555]: headers:
Max-Forwards: 70
Event: dialog
Contact: <sip:xxx.xxx.xxx.xxx:5060>
Subscription-State: active;expires=70
6(28419) DEBUG: presence [notify.c:940]: CONTACT =
sip:17_100@yyy.yyy.yyy.yyy:1081
6(28419) DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking
if host==us: 14==9 && [xxx.xxx.xxx.xxx] == [127.0.0.1]
6(28419) DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking
if port 5060 matches port 5060
6(28419) DEBUG: <core> [socket_info.c:501]: grep_sock_info - checking
if host==us: 14==14 && [xxx.xxx.xxx.xxx] == [xxx.xxx.xxx.xxx]
6(28419) DEBUG: <core> [socket_info.c:504]: grep_sock_info - checking
if port 5060 matches port 5060
6(28419) DEBUG: presence [notify.c:1729]: === 23/6/37
6(28419) DEBUG: tm [uac.c:240]: DEBUG:tm:t_uac:
next_hop=<sip:;r2=on;lr=on;ftag=123926587>
6(28419) DEBUG: <core> [dns_cache.c:567]:
dns_hash_find(_sip._udp.;r2=on(16), 33), h=399
6(28419) DEBUG: <core> [dns_cache.c:567]: dns_hash_find(;r2=on(6), 1),
h=1013
6(28419) ERROR: <core> [resolve.c:1540]: ERROR: sip_hostport2su: could
not resolve hostname: ";r2=on"
6(28419) ERROR: tm [ut.h:318]: failed to resolve ";r2=on"
6(28419) ERROR: tm [uac.c:263]: t_uac: no socket found
6(28419) ERROR: presence [notify.c:1577]: in function
tmb.t_request_within
6(28419) ERROR: presence [notify.c:1673]: sending Notify not successful
6(28419) ERROR: presence [subscribe.c:428]: Could not send notify
6(28419) ERROR: presence [subscribe.c:454]: occured
6(28419) ERROR: presence [subscribe.c:686]: in update_subscription
6(28419) DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=2
global id=2 T start=0xb6153c00
6(28419) DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already
found!
6(28419) DEBUG: tm [t_reply.c:1470]: DEBUG: cleanup_uac_timers: RETR/FR
timers reset
6(28419) DEBUG: <core> [timer.c:595]: timer_add called on an active
timer 0xb6153c48 (0xb5fd5bac, 0xb5fd5bac), flags 201
6(28419) DEBUG: tm [t_funcs.c:184]: tm: put_on_wait: transaction
0xb6153c00 already on wait
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [usr_avp.c:646]: DEBUG:destroy_avp_list:
destroying list (nil)
6(28419) DEBUG: <core> [receive.c:289]: receive_msg: cleaning up
w.
Cheers,
Daniel
On 3/24/11 8:25 AM, Spinov Evgeniy wrote:
On Thu, 2011-03-24 at 07:42 +0100,
Daniel-Constantin Mierla wrote:
Hello,
if you watch the SIP traffic with ngrep, do you see the message sent out?
First of
all I would like to thank you your time devoted to this
problem.
To not flood mail with long text, I've written it in short, without
fulldumps.
Messages are sent, however, for some reason Record-Route header look
like this:
Record-Route:<sip:;r2=on;lr=on;ftag=323895591>
Record-Route:<sip:KAMAILIO_IP;r2=on;lr=on;ftag=323895591>
i.e. first header is empty? I've called this header invalid in the rest
of the text.
Via header and rest of the packet looks good.
First part of exchange looks like this. Let's assume that I'm calling
from 100 to 101:
Kamailio<-> Asterisk
INVITE 100 -> 101 ( header is invalid )
<- 100 Trying ( header is invalid )
<- INVITE 101
100 Trying ->
180 Ringing ( header is invalid )->
At this stage 101 rings, however 100 is not getting "waiting" tone.
After call reply at 101:
OK 101 -> 100
101 <- ACK 100 ( header is invalid )
OK 101 -> 100
100 <- OK 101, header is invalid )
OK ( from 101 ) -> 100
100 <- OK ( from 101, header is invalid )
etc....
Looks like message is not being delivered correctly.
Can you reproduce this case easily? If yes, can
you start kamailio with
extra parameters '-E -ddd' and send here all the debug messages printed
for such case, from the moment the SIP request is received.
While on Kamailio side
in debug messages I have error regarding failure
of resolution host IP ";r2=on" from the SIP header.
So it seems, that Record-Router header is doing the mess.
Without msg_apply_changes() invalid Record route header just do not
appear.
If I've provided you not enough info to find out the reason, I can do
the full dumps, as problem is easily repeated.
Thank you.
Cheers,
Daniel
On 3/24/11 6:48 AM, Spinov Evgeniy wrote:
> On Wed, 2011-03-23 at 15:16 +0100, Daniel-Constantin Mierla wrote:
>
> Well, unfortunately no. When I use msg_apply_changes() and I see this
> messages, signalization doesn't work fine. Actually call is not being
> established - it's just getting timeouts from K and failure routes are
> being executed.
>
> As function is removed - everything runs good and calls are passing
> fine.
>
>> Hello,
>>
>> I have to look into the sources and doubel check, but the log messages
>> seem to be harmless.
>>
>> For the moment, you can just set a flag when you change something in the
>> message and then call msg_apply_changes() only when the flag is set, e.g.,
>>
>> remove_hf("From");
>> setflag(20);
>>
>> ...
>>
>> if(isflagset(20))
>> msg_apply_changes();
>>
>> However, I will update the sources so such log messages will not appear
>> unless they are necessary.
>>
>> Thanks,
>> Daniel
>>
>>
>> On 3/23/11 2:52 PM, Spinov Evgeniy wrote:
>>> Hi,
>>>
>>> I've installed, as you advised Kamailio 3.1.2 and used
>>> msg_apply_changes(). However, even when I'm not changing anything in the
>>> packet and just calling msg_apply_changes() I get errors from K:
>>>
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:859]: FIXME: lumps_len called
with
>>> null send_sock
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:1340]: FIXME: process_lumps:
null
>>> bind_address
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>> 7(31755) :<core> [msg_translator.c:519]: ERROR: lump_check_opt:
null
>>> send socket
>>>
>>> when function is not used - everything runs fine. However I need to
>>> modify the message.
>>>
>>> Please, advice.
>>>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users(a)lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users