[SR-Users] Questions about Presence

Володимир Іванець volodyaivanets at gmail.com
Fri Dec 20 13:58:30 CET 2019 

Hello Henning,

Thank you for your reply.

subs_db_mode set to 2  may not be representable because it is a copy of
internal hash table and watcher lookup is done against htable and not
active_watchers DB table. I have not seen this problem with subs_db_mode
set to 3. I forgot to mention in my first email that Kamailio is generating
NOTIFY packets correctly for a while after subscription is made. Then I'm
witnessing "Could not find subs_dialog" messages until UAC will resubscribe.
I was trying to add extra debugging but failed miserably :) My
"improvements" either caused worker process to crash or presence module to
compile. I guess I'll have to make a feature request as you suggested for a
RPC command and hope it can be implemented.


Testing was made on *Kamailio 5.3.0*.
pua module db_modeis set to 0. Debug shows following recurring activity by
"slow timer" process:
































*Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: presence
[publish.c:76]: msg_presentity_clean(): cleaning expired presentity
informationDec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core>
[db_query.c:72]: db_do_submit_query(): submitted query: select
`username`,`domain`,`etag`,`event` from `presentity` where
`expires`<1576843116 AND `expires`>0 order by username, result 0Dec 20
13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:120]:
db_new_result(): allocate 56 bytes for result set at 0x7f84107ec398Dec 20
13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:67]:
db_mysql_get_columns(): 4 columns returned from the queryDec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:158]:
db_allocate_columns(): allocate 32 bytes for result names at
0x7f84107eb6e8Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core>
[db_res.c:169]: db_allocate_columns(): allocate 16 bytes for result types
at 0x7f84107ea800Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG:
db_mysql [km_res.c:85]: db_mysql_get_columns(): allocate 16 bytes for
RES_NAMES[0] at 0x7f84107ea668Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:92]:
db_mysql_get_columns(): RES_NAMES(0x7f84107ea668)[0]=[username]Dec 20
13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:148]:
db_mysql_get_columns(): use DB1_STRING result typeDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:85]:
db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[1] at
0x7f84107eab30Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG:
db_mysql [km_res.c:92]: db_mysql_get_columns():
RES_NAMES(0x7f84107eab30)[1]=[domain]Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:148]:
db_mysql_get_columns(): use DB1_STRING result typeDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:85]:
db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[2] at
0x7f84107ebdb0Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG:
db_mysql [km_res.c:92]: db_mysql_get_columns():
RES_NAMES(0x7f84107ebdb0)[2]=[etag]Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:148]:
db_mysql_get_columns(): use DB1_STRING result typeDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:85]:
db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[3] at
0x7f84107ebb30Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG:
db_mysql [km_res.c:92]: db_mysql_get_columns():
RES_NAMES(0x7f84107ebb30)[3]=[event]Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_res.c:148]:
db_mysql_get_columns(): use DB1_STRING result typeDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: db_mysql [km_dbase.c:397]:
db_mysql_fetch_result(): no rows returned from the queryDec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: presence [publish.c:114]:
msg_presentity_clean(): found n= 0 expires messagesDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:79]: db_free_columns():
freeing 4 columnsDec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG:
<core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at
0x7f84107ea668Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core>
[db_res.c:83]: db_free_columns(): freeing RES_NAMES[1] at 0x7f84107eab30Dec
20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]:
db_free_columns(): freeing RES_NAMES[2] at 0x7f84107ebdb0Dec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]:
db_free_columns(): freeing RES_NAMES[3] at 0x7f84107ebb30Dec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:96]:
db_free_columns(): freeing result names at 0x7f84107eb6e8Dec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:101]:
db_free_columns(): freeing result types at 0x7f84107ea800Dec 20 13:58:36
linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:138]:
db_free_result(): freeing result set at 0x7f84107ec398Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: <core> [db_query.c:72]:
db_do_submit_query(): submitted query: delete from `presentity` where
`expires`<1576843116 AND `expires`>0, result 0Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: presence [subscribe.c:711]:
msg_watchers_clean(): cleaning pending subscriptionsDec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: <core> [db_query.c:72]:
db_do_submit_query(): submitted query: delete from `watchers` where
`inserted_time`<1576756716 AND `status`=2, result 0Dec 20 13:58:36 linux
/usr/sbin/kamailio[5671]: DEBUG: <core> [db_query.c:72]:
db_do_submit_query(): submitted query: delete from `pua` where
`expires`<1576843106, result 0*

And here is the output when handle_publish() is called for PUBLISH packet:










































*Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <script>: == TRACE.
PRESENCE. Method is PUBLISHDec 20 14:31:07 linux /usr/sbin/kamailio[5661]:
DEBUG: presence [event_list.c:325]: search_event(): start event=
[dialog/5]Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence
[publish.c:314]: ki_handle_publish_uri(): SIP-If-Match header not foundDec
20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence
[presentity.c:86]: generate_ETag(): etag= a.1576843015.5661.1.0 / 21Dec 20
14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [publish.c:322]:
ki_handle_publish_uri(): new etag  = a.1576843015.5661.1.0Dec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: presence [publish.c:342]:
ki_handle_publish_uri(): Expires header found, value= 43201Dec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:627]:
update_presentity(): new presentity with etag a.1576843015.5661.1.0Dec 20
14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [sruid.c:183]:
sruid_next(): new sruid is [pres-5dfcb708-161d-1] (1 / 20)Dec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: presence [hash.c:484]:
search_phtable(): pres_uri= sip:200-test at 127.0.0.1
<sip%3A200-test at 127.0.0.1>Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]:
DEBUG: presence [presentity.c:649]: update_presentity(): new htable record
addedDec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core>
[db_query.c:72]: db_do_submit_query(): submitted query: SET autocommit=0,
result 0Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core>
[db_query.c:72]: db_do_submit_query(): submitted query: select
`body`,`etag` from `presentity` where `domain`='127.0.0.1' AND
`username`='200-test' AND `event`='dialog', result 0Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:120]: db_new_result():
allocate 56 bytes for result set at 0x7f8410e13900Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:67]:
db_mysql_get_columns(): 2 columns returned from the queryDec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:158]:
db_allocate_columns(): allocate 16 bytes for result names at
0x7f8410e13a18Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core>
[db_res.c:169]: db_allocate_columns(): allocate 8 bytes for result types at
0x7f8410e13a90Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG:
db_mysql [km_res.c:85]: db_mysql_get_columns(): allocate 16 bytes for
RES_NAMES[0] at 0x7f8410e13b00Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:92]:
db_mysql_get_columns(): RES_NAMES(0x7f8410e13b00)[0]=[body]Dec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:133]:
db_mysql_get_columns(): use DB1_BLOB result typeDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:85]:
db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[1] at
0x7f8410e13b78Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG:
db_mysql [km_res.c:92]: db_mysql_get_columns():
RES_NAMES(0x7f8410e13b78)[1]=[etag]Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:148]:
db_mysql_get_columns(): use DB1_STRING result typeDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: db_mysql [km_res.c:181]:
db_mysql_convert_rows(): no rows returned from the queryDec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:79]:
db_free_columns(): freeing 2 columnsDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:83]: db_free_columns():
freeing RES_NAMES[0] at 0x7f8410e13b00Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:83]: db_free_columns():
freeing RES_NAMES[1] at 0x7f8410e13b78Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:96]: db_free_columns():
freeing result names at 0x7f8410e13a18Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:101]: db_free_columns():
freeing result types at 0x7f8410e13a90Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:138]: db_free_result():
freeing result set at 0x7f8410e13900Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:726]:
update_presentity(): inserting 10 cols into tableDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: <core> [db_query.c:72]:
db_do_submit_query(): submitted query: insert into `presentity`
(`domain`,`username`,`event`,`etag`,`sender`,`body`,`received_time`,`priority`,`ruid`,`expires`
) values ('127.0.0.1','200-test','dialog','a.1576843015.5661.1.0','','<?xml
version=\"1.0\"?>\n<dialog-info
xmlns=\"urn:ietf:params:xml:ns:dialog-info\" version=\"0\" state=\"full\"
entity=\"sip:200-test at linux.test.com:5060
<http://sip:200-test@linux.test.com:5060>\">\n  <dialog
id=\"NDcwYWU5NGYxYjY3NTc5M2Q4NDNmMTEwNzEwYzA0NjI.\"
call-id=\"NDcwYWU5NGYxYjY3NTc5M2Q4NDNmMTEwNzEwYzA0NjI.\"
direction=\"initiator\">\n    <state>Trying</state>\n    <remote>\n
 <identity>sip:602 at linux.test.com:5060
<http://sip:602@linux.test.com:5060></identity>\n      <target
uri=\"sip:602 at linux.test.com:5060
<http://sip:602@linux.test.com:5060>\"/>\n    </remote>\n    <local>\n
 <identity>sip:200-test at linux.test.com:5060
<http://sip:200-test@linux.test.com:5060></identity>\n      <target
uri=\"sip:200-test at linux.test.com:5060
<http://sip:200-test@linux.test.com:5060>\"/>\n    </local>\n
 </dialog>\n</dialog-info>\n',1576845067,0,'pres-5dfcb708-161d-1',1576848667),
result 0Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence
[presentity.c:102]: publ_send200ok(): send 200OK replyDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:103]:
publ_send200ok(): etag= a.1576843015.5661.1.0 - len= 21Dec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: tm [t_lookup.c:1036]: t_check_msg():
msg (0x7f8410df3160) id=119/5661 global id=119/5661 T
start=0x7f840349bc80Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG:
tm [t_lookup.c:1109]: t_check_msg(): T (0x7f840349bc80) already found for
msg (0x7f8410df3160)!Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG:
<core> [core/msg_translator.c:162]: check_via_address(): (127.0.0.1,
127.0.0.1, 0)Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: tm
[t_reply.c:1667]: cleanup_uac_timers(): RETR/FR timers resetDec 20 14:31:07
linux /usr/sbin/kamailio[5661]: DEBUG: tm [t_reply.c:611]: _reply_light():
reply sent out. buf=0x7f8410e13bc8: SIP/2.0 200 OKDec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: tm [t_reply.c:621]: _reply_light():
finishedDec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: sl
[sl.c:297]: send_reply(): reply in stateful mode (tm)Dec 20 14:31:07 linux
/usr/sbin/kamailio[5661]: DEBUG: presence [notify.c:1234]: publ_notify():
Could not find subs_dialogDec 20 14:31:07 linux /usr/sbin/kamailio[5661]:
DEBUG: <core> [db_query.c:72]: db_do_submit_query(): submitted query:
COMMIT, result 0*

It is apparent that Kamailio respects presentity DB table. If there is a
record with "confirmed" state and long enough expiration stuck in the DB, I
can restart Kamailio and it will generate NOTIFy for a subscriber with the
state from DB even if appropriate phone is not yet registered.

Thank you!

Regards, Volodya Ivanets

чт, 19 груд. 2019 о 11:38 Henning Westerholt <hw at skalatan.de> пише:

> Hello,
>
>
>
> if you use subs_db_mode 2 then the list of activate watches should be
> available in the respective active_watchers table, I think. To the get the
> content of this in mode 0 there could be probably a RPC function to be
> added. If you thinking of adding an extra debugging line – this can be also
> done, just open a pull request for it in our tracker.
>
>
>
> About the second question – the presence modules are modular and they can
> be configured individually differently. Some modules also export an API
> that is used then from other modules..  It is probably a good idea to
> investigate this more from your side. You could for example execute it with
> debugging and see why the table is queried constantly and which module
> trigger this query.
>
>
>
> Cheers,
>
>
>
> Henning
>
>
>
>
>
> --
>
> Henning Westerholt – https://skalatan.de/blog/
>
> Kamailio services – https://gilawa.com
>
>
>
> *From:* sr-users <sr-users-bounces at lists.kamailio.org> *On Behalf Of *?????????
> ???????
> *Sent:* Tuesday, December 17, 2019 1:19 PM
> *To:* Kamailio (SER) - Users Mailing List <sr-users at lists.kamailio.org>
> *Subject:* [SR-Users] Questions about Presence
>
>
>
> Hello!
>
>
>
> I'm testing Kamailio as a presence server with configuration suggested by
> https://kb.asipto.com/kamailio:presence:k43-blf tutorial.
>
>
>
> When I set presence module subs_db_mode setting to 0 or 2 (did not test
> with 1 and 3 seemed to have no problems) I was getting "DEBUG: presence
> [notify.c:1234]: publ_notify(): Could not find subs_dialog" message after
> Kamailio received some PUBLISH requests. And NOTIFY is not being generated.
> It appears to be a mistake. There should be an active watcher according to
> Expires header values of the previous SUBSCRIBE request and the response to
> it. I could not find how to get the list of active watchers from Kamailio
> memory. *Is it possible or it can be done only by adding extra debug line
> in get_subs_dialog function?*
>
>
>
> Also I found that after setting pua module db_mode setting to 0, Kamailio
> is still writing records to presentity table. And it is constantly queried
> "select `username`,`domain`,`etag`,`event` from `presentity` where
> `expires`<1576584910 AND `expires`>0 order by username" during the run
> time. *Is it correct behavior?*
>
>
>
> Thank a lot!
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20191220/4d686847/attachment.html>

More information about the sr-users mailing list