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@127.0.0.1 sip%3A200-test@127.0.0.1Dec 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@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@linux.test.com:5060 http://sip:602@linux.test.com:5060</identity>\n <target uri="sip:602@linux.test.com:5060 http://sip:602@linux.test.com:5060"/>\n </remote>\n <local>\n <identity>sip:200-test@linux.test.com:5060 http://sip:200-test@linux.test.com:5060</identity>\n <target uri="sip:200-test@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@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@lists.kamailio.org *On Behalf Of *????????? ??????? *Sent:* Tuesday, December 17, 2019 1:19 PM *To:* Kamailio (SER) - Users Mailing List sr-users@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!