[SR-Users] [Kamailio-Users] Rewrite $tU

Spinov Evgeniy spinov_evgeniy at intalisan.com
Fri Mar 25 13:30:00 CET 2011


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 at 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 at xxx.xxx.xxx.xxx] 
 6(28419) DEBUG: <core> [parser/msg_parser.c:189]: DEBUG: to body
[<sip:0 at 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 at 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 at 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 at 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 at 176.249.0.2	[local_cseq]=0
	[to_tag]= a6a1c5f60faecf035a1ae5b6e96e979a-6003	[from_tag]= 123926587
	[contact]= sip:17_100 at 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 at 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 at 176.249.0.2	[local_cseq]=0
	[to_tag]= a6a1c5f60faecf035a1ae5b6e96e979a-6003	[from_tag]= 123926587
	[contact]= sip:17_100 at 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 at 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 at 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 at lists.sip-router.org
> >>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
> >
> 





More information about the sr-users mailing list