[SR-Users] Handling of messages with manipulated Event header.

Christopher Vella C.Vella at albourne.com
Mon Feb 15 19:50:49 CET 2016 

Hi,

I apologise if this is not the correct venue for such a question... 

I am running kamailio v4.3.4 (x86_64/linux) on debian Jessie, sourced from; 
 deb http://deb.kamailio.org/kamailio jessie main

In my routing logic I am handling SUBSCRIBE requests and striping extra Event 
package parameters appended to "ua-profile" event types. i.e.; 

  Event: ua-profile;model=somemodel;vendor=somevendor;profile-type=user 
  
  becomes; 

  Event: ua-profile

This is done with this code; 

      } else if( is_method("SUBSCRIBE")) {
                subst('/ua-profile.*/ua-profile/') ;
                handle_subscribe();
                t_release();

However, in such conditions "search_event()" doesn't correctly find the event. 
Even though it looks like it is searching for the right event type;

  start event= [ua-profile/7]
  handle_subscribe(): unsupported presence event ua-profile

--- Begin debug ----

]3(7664) DEBUG: <core> [re.c:457]: subst_run(): matched (332, 79): [Event: ua-profile;model=somemodel;vendor=somevendor;profile-type=user] with [Event: ua-profile]extops.c:680]: subst_f(): textops: replacing at offset 376[Event: ua-profile;model=somemodel;vendor=somevendor;profile-type=user]
13(7664) debug: textops [textops.c:696]: subst_f(): lst was 0x7fb391fd0da8
13(7664) error: *** cfgtrace:request_route=[presence] c=[/etc/kamailio/kamailio.cfg] l=365 a=24 n=handle_subscribe
13(7664) debug: presence [event_list.c:348]: search_event(): start event= [ua-profile/7]
13(7664) notice: presence [subscribe.c:1092]: handle_subscribe(): unsupported presence event ua-profile
13(7664) debug: tm [t_lookup.c:1011]: t_check_msg(): debug: t_check_msg: msg id=1 global id=1 t start=0x7fb388763290
13(7664) debug: tm [t_lookup.c:1083]: t_check_msg(): debug: t_check_msg: t already found!
13(7664) debug: <core> [mem/shm_mem.c:101]: _shm_resize(): warning:vqm_resize: resize(0) called
13(7664) debug: tm [t_reply.c:1591]: cleanup_uac_timers(): debug: cleanup_uac_timers: retr/fr timers reset
13(7664) debug: <core> [tcp_main.c:2196]: tcpconn_send_put(): send from reader (7664 (13)), reusing fd
13(7664) debug: <core> [tcp_main.c:2430]: tcpconn_do_send(): sending...
13(7664) debug: <core> [tcp_main.c:2464]: tcpconn_do_send(): after real write: c= 0x7fb38875ecf8 n=368 fd=9
13(7664) debug: <core> [tcp_main.c:2465]: tcpconn_do_send(): buf=
sip/2.0 489 bad event
via: sip/2.0/tcp 127.0.1.1:5060;branch=z9hg4bk-2999-1-0;rport=34679;received=192.168.88.88
cseq: 1 subscribe
call-id: 1-2999 at 127.0.1.1
from: <sip:c.vella at albourne.com>;tag=1
to: <sip:provisioning at albourne.com>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-811a

--- End debug ---

As a test, I send another message with clean "Event: ua-profile" and this works
, event= [ua-profile/7] is found.

--- Begin debug ---

]4(7665) DEBUG: <core> [re.c:457]: subst_run(): matched (332, 18): [Event: ua-profile
] with [Event: ua-profile]extops.c:680]: subst_f(): textops: replacing at offset 376 [Event: ua-profile
14(7665) DEBUG: textops [textops.c:696]: subst_f(): lst was 0x7fb391fd0da8
14(7665) ERROR: *** cfgtrace:request_route=[PRESENCE] c=[/etc/kamailio/kamailio.cfg] l=365 a=24 n=handle_subscribe
14(7665) DEBUG: presence [event_list.c:348]: search_event(): start event= [ua-profile/7]
14(7665) DEBUG: presence [subscribe.c:1161]: extract_sdialog_info_ex(): 'Expires' header found, value= 3600
14(7665) DEBUG: presence [subscribe.c:1195]: extract_sdialog_info_ex(): 'To' header ALREADY PARSED: <sip:provisioning at albourne.com>
14(7665) DEBUG: presence [subscribe.c:1266]: extract_sdialog_info_ex(): generating to_tag
14(7665) DEBUG: sl [sl.c:329]: get_reply_totag(): totag stateful mode (tm)
14(7665) DEBUG: presence [subscribe.c:1326]: extract_sdialog_info_ex(): subs->contact= sip:c.vella at 192.168.88.179:59206;transport=tcp - len = 46
14(7665) DEBUG: presence [subscribe.c:1043]: handle_subscribe(): subscription status= active - inserted
14(7665) DEBUG: presence [subscribe.c:554]: update_subscription(): update subscription
14(7665) DEBUG: presence [notify.c:115]: printf_subs(): pres_uri: sip:c.vella at albourne.com
14(7665) DEBUG: presence [notify.c:116]: printf_subs(): watcher_user at watcher_domain: c.vella at albourne.com
14(7665) DEBUG: presence [notify.c:117]: printf_subs(): to_user at to_domain: provisioning at albourne.com
14(7665) DEBUG: presence [notify.c:118]: printf_subs(): from_user at from_domain: c.vella at albourne.com
14(7665) DEBUG: presence [notify.c:119]: printf_subs(): callid/from_tag/to_tag: 1-3002 at 127.0.1.1/1/a6a1c5f60faecf035a1ae5b6e96e979a-1030
14(7665) DEBUG: presence [notify.c:120]: printf_subs(): local_cseq/remote_cseq: 0/1
14(7665) DEBUG: presence [notify.c:121]: printf_subs(): local_contact/contact: sip:192.168.88.85:5060;transport=tcp/sip:c.vella at 192.168.88.179:59206;transport=tcp
14(7665) DEBUG: presence [notify.c:122]: printf_subs(): record_route:
14(7665) DEBUG: presence [notify.c:123]: printf_subs(): sockinfo_str: tcp:192.168.88.85:5060
14(7665) DEBUG: presence [notify.c:125]: printf_subs(): event: ua-profile
14(7665) DEBUG: presence [notify.c:126]: printf_subs(): status: active
14(7665) DEBUG: presence [notify.c:127]: printf_subs(): reason:
14(7665) DEBUG: presence [notify.c:128]: printf_subs(): version: 1
14(7665) DEBUG: presence [notify.c:129]: printf_subs(): expires: 3600
14(7665) DEBUG: presence [notify.c:131]: printf_subs(): updated/updated_winfo: -1/-1
14(7665) DEBUG: presence [subscribe.c:629]: update_subscription(): subscription not in dialog
14(7665) DEBUG: presence [subscribe.c:634]: update_subscription(): inserting in shtable
14(7665) DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T start=0x7fb388763290
14(7665) DEBUG: tm [t_lookup.c:1083]: t_check_msg(): DEBUG: t_check_msg: T already found!
14(7665) DEBUG: <core> [mem/shm_mem.c:101]: _shm_resize(): WARNING:vqm_resize: resize(0) called
14(7665) DEBUG: tm [t_reply.c:1591]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset
14(7665) DEBUG: <core> [tcp_main.c:2196]: tcpconn_send_put(): send from reader (7665 (14)), reusing fd
14(7665) DEBUG: <core> [tcp_main.c:2430]: tcpconn_do_send(): sending...
14(7665) DEBUG: <core> [tcp_main.c:2464]: tcpconn_do_send(): after real write: c= 0x7fb38875ecf8 n=399 fd=9
14(7665) DEBUG: <core> [tcp_main.c:2465]: tcpconn_do_send(): buf=
SIP/2.0 202 OK
Via: SIP/2.0/TCP 127.0.1.1:5060;branch=z9hG4bK-3002-1-0;rport=34680;received=192.168.88.88
CSeq: 1 SUBSCRIBE
Call-ID: 1-3002 at 127.0.1.1
From: <sip:c.vella at albourne.com>;tag=1
To: <sip:provisioning at albourne.com>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-1030
Expires: 3600
Contact: <sip:192.168.88.85:5060;transport=tcp>

--- End debug ---

I suspect I am not understanding this correctly. Is there a proper way around
this? I wonder if I am wrong to think that textops Module manipulates the 
actual request message?

Thank you!

Regards,

-- 

Chris Vella
Albourne Partners (Canada) Limited

More information about the sr-users mailing list