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@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@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: nullsend 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@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users