[OpenSIPS-Users] Presentity deleted while registration still valid
Rob Dyck
rob.dyck at telus.net
Mon Oct 4 15:57:02 EST 2021
Context opensips-3.2.2
I am trying out module pua_usrloc. I think that it is expiring presentities
while the phone's registration is still valid. Then the phone re-registers and
the presentity has to be recreated. This creates too much churn which could be
avoided.
See attached time line.
-------------- next part --------------
Phone's registration expires at 7:28:37
Presentity expires prematurely, still 61 seconds remaining.
/* handle expired presentities with no sharing tag or with an
* active sharing tag (if clustering is enabled) */
if ( (p->expires -update_period < now ) &&
(!sh_tags || !p->sh_tag.s || sh_tag_matches(sh_tags,&p->sh_tag)) )
{
if((p->desired_expires> p->expires + 5) ||
(p->desired_expires== 0 ))
{
LM_DBG("Desired expires greater than expires -> send a "
"refresh PUBLISH desired_expires=%d - expires=%d\n",
p->desired_expires, p->expires);
if(update_pua(p, i, 0)< 0)
{
LM_ERR("while updating record\n");
lock_release(&HashT->p_records[i].lock);
return;
}
p= p->next;
continue;
}
LM_DBG("Found expired: uri= %.*s\n", p->pres_uri->len,
p->pres_uri->s);
if(update_pua(p, i, 1)< 0)
{
LM_ERR("while updating record\n");
}
/* delete it */
q = p->next;
delete_htable_safe(p, p->hash_index);
p = q;
Oct 4 07:27:38 [674854] DBG:pua:print_ua_pres: p=[0x7f0e44f57308] pres_uri=[sip:3 at bogus.com]
Oct 4 07:27:38 [674854] DBG:pua:print_ua_pres: etag=[a.1633196620.366952.1663.0] id=[146183bd-a708bacf at 192.168.1.5]
Oct 4 07:27:38 [674854] DBG:pua:print_ua_pres: flag=[1] event=[1]
Oct 4 07:27:38 [674854] DBG:pua:print_ua_pres: countdown=[61] expires=[1633357719] desired_expires=[1633357717]
Oct 4 07:27:38 [674854] DBG:pua:hashT_clean: ---
Oct 4 07:27:38 [674854] DBG:pua:hashT_clean: Found expired: uri= sip:3 at bogus.com
Publish with expiry = 0
PUBLISH sip:3 at bogus.com SIP/2.0
Via: SIP/2.0/UDP [2001::D2B4]:5060;branch=z9hG4bK1354.146fada4.0
To: sip:3 at bogus.com
From: <sip:3 at bogus.com>;tag=6b4c60f68c1b1746e6ff8978eb398ce8-d1d8
CSeq: 10 PUBLISH
Call-ID: 6036028b66e984c5-674854 at 192.168.1.2
Max-Forwards: 70
Content-Length: 0
User-Agent: OpenSIPS (3.2.2 (x86_64/linux))
Event: presence
Expires: 0
SIP-If-Match: a.1633196620.366952.1663.0
Deleted from hash table.
Oct 4 07:27:38 [674851] DBG:presence:search_event: start event= [presence]
Oct 4 07:27:38 [674851] DBG:presence:handle_publish: Expires header found, value= 0
Oct 4 07:27:38 [674851] DBG:presence:handle_publish: SIP-If-Match header found
Oct 4 07:27:38 [674851] DBG:presence:handle_publish: existing etag= a.1633196620.366952.1663.0
Oct 4 07:27:38 [674851] DBG:core:parse_headers: flags=ffffffffffffffff
Oct 4 07:27:38 [674851] DBG:presence:presence_raise_event: no event sent
Oct 4 07:27:38 [674851] DBG:presence:search_phtable_etag: pres_uri= sip:3 at bogus.com, event=1, etag= a.1633196620.366952.1663.0
Oct 4 07:27:38 [674851] DBG:presence:search_phtable_etag: found etag = a.1633196620.366952.1663.0
Oct 4 07:27:38 [674851] DBG:presence:update_presentity: pres <sip:3 at bogus.com> my turn is 0, current turn is 0
Oct 4 07:27:38 [674851] DBG:presence:delete_phtable: Count = 0, delete
Oct 4 07:27:38 [674851] DBG:tm:run_trans_callbacks: trans=0x7f0e4504dd28, callback type 256, id 0 entered
Oct 4 07:27:38 [674851] DBG:pua:publ_cback_func: cback param = 291
Oct 4 07:27:38 [674851] DBG:pua:publ_cback_func: hash_index= 291, local_index= 0
Oct 4 07:27:38 [674851] ERROR:pua:publ_cback_func: No record found
Phone updates registration.
Oct 4 07:28:33 [674850] DBG:core:parse_msg: SIP Request:
Oct 4 07:28:33 [674850] DBG:core:parse_msg: method: <REGISTER>
Oct 4 07:28:33 [674850] DBG:core:parse_msg: uri: <sip:192.168.1.2>
Oct 4 07:28:33 [674850] DBG:core:parse_msg: version: <SIP/2.0>
Pua_usrloc sees the update
Oct 4 07:28:33 [674850] DBG:pua_usrloc:pua_set_publish: set send publish
Oct 4 07:28:33 [674850] DBG:core:parse_headers: flags=ffffffffffffffff
Oct 4 07:28:33 [674850] DBG:core:parse_headers: flags=8000000
Oct 4 07:28:33 [674850] DBG:usrloc:get_ucontact: using ct matching mode 0
Oct 4 07:28:33 [674850] DBG:usrloc:get_ucontact: successfully matched contact 'sip:3 at 192.168.1.5:5061'
Oct 4 07:28:33 [674850] DBG:usrloc:update_ucontact: exists callback for type= UL_CONTACT_UPDATE
Oct 4 07:28:33 [674850] DBG:usrloc:run_ul_callbacks: contact=0x7f0e4504c020, callback type 2/2, id 2 entered
Oct 4 07:28:33 [674850] DBG:pua_usrloc:ul_contact_publish:
ul_publish: UPDATE type
Oops, update won't work
Oct 4 07:28:33 [674850] DBG:pua:search_htable: got presentity [(nil)]
Oct 4 07:28:33 [674850] DBG:pua:send_publish_int: start
Oct 4 07:28:33 [674850] ERROR:pua:send_publish_int: New 'presence' PUBLISH and no body found - invalid request
Oct 4 07:28:33 [674850] DBG:pua_usrloc:ul_contact_publish: Usrloc Publish for update failed - try Insert
Generate a PUBLISH to create a new entry.
Oct 4 07:28:33 [674850] DBG:core:parse_msg: method: <PUBLISH>
Oct 4 07:28:33 [674850] DBG:core:parse_msg: uri: <sip:3 at bogus.com>
Oct 4 07:28:33 [674850] DBG:core:parse_msg: version: <SIP/2.0>
New presence.
Oct 4 07:28:33 [674851] DBG:presence:search_event: start event= [presence]
Oct 4 07:28:33 [674851] DBG:presence:handle_publish: Expires header found, value= 601
Oct 4 07:28:33 [674851] DBG:presence:handle_publish: SIP-If-Match header not found
Oct 4 07:28:33 [674851] DBG:presence:generate_ETag: etag= a.1633357468.674851.2.0
Oct 4 07:28:33 [674851] DBG:presence:handle_publish: new etag= a.1633357468.674851.2.0
Set presence expiry.
Oct 4 07:28:33 [674851] DBG:pua:publ_cback_func: cback param = 291
Oct 4 07:28:33 [674851] DBG:pua:publ_cback_func: hash_index= 291, local_index= 0
Oct 4 07:28:33 [674851] DBG:core:parse_headers: flags=ffffffffffffffff
Oct 4 07:28:33 [674851] DBG:pua:publ_cback_func: lexpire= 601
Start counting down to the next presence expiry.
Oct 4 07:29:14 [674853] DBG:pua:print_ua_pres: p=[0x7f0e4504b898] pres_uri=[sip:3 at bogus.com]
Oct 4 07:29:14 [674853] DBG:pua:print_ua_pres: etag=[a.1633357468.674851.2.0] id=[146183bd-a708bacf at 192.168.1.5]
Oct 4 07:29:14 [674853] DBG:pua:print_ua_pres: flag=[1] event=[1]
Oct 4 07:29:14 [674853] DBG:pua:print_ua_pres: countdown=[560] expires=[1633358314] desired_expires=[1633358313]
More information about the Users
mailing list