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 information
Dec 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 0
Dec 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 0x7f84107ec398
Dec 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 query
Dec 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 0x7f84107eb6e8
Dec 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 0x7f84107ea800
Dec 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 0x7f84107ea668
Dec 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 type
Dec 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 0x7f84107eab30
Dec 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 type
Dec 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 0x7f84107ebdb0
Dec 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 type
Dec 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 0x7f84107ebb30
Dec 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 type
Dec 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 query
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: presence [publish.c:114]: msg_presentity_clean(): found n= 0 expires messages
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 4 columns
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f84107ea668
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[1] at 0x7f84107eab30
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[2] at 0x7f84107ebdb0
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[3] at 0x7f84107ebb30
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f84107eb6e8
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f84107ea800
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f84107ec398
Dec 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 0
Dec 20 13:58:36 linux /usr/sbin/kamailio[5671]: DEBUG: presence [subscribe.c:711]: msg_watchers_clean(): cleaning pending subscriptions
Dec 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 0
Dec 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 PUBLISH
Dec 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 found
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:86]: generate_ETag(): etag= a.1576843015.5661.1.0 / 21
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [publish.c:322]: ki_handle_publish_uri(): new etag  = a.1576843015.5661.1.0
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [publish.c:342]: ki_handle_publish_uri(): Expires header found, value= 43201
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:627]: update_presentity(): new presentity with etag a.1576843015.5661.1.0
Dec 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
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:649]: update_presentity(): new htable record added
Dec 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 0
Dec 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 0
Dec 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 0x7f8410e13900
Dec 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 query
Dec 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 0x7f8410e13a18
Dec 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 0x7f8410e13a90
Dec 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 0x7f8410e13b00
Dec 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 type
Dec 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 0x7f8410e13b78
Dec 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 type
Dec 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 query
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 2 columns
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f8410e13b00
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[1] at 0x7f8410e13b78
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f8410e13a18
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f8410e13a90
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f8410e13900
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:726]: update_presentity(): inserting 10 cols into table
Dec 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\">\n  <dialog id=\"NDcwYWU5NGYxYjY3NTc5M2Q4NDNmMTEwNzEwYzA0NjI.\" call-id=\"NDcwYWU5NGYxYjY3NTc5M2Q4NDNmMTEwNzEwYzA0NjI.\" direction=\"initiator\">\n    <state>Trying</state>\n    <remote>\n      <identity>sip:602@linux.test.com:5060</identity>\n      <target uri=\"sip:602@linux.test.com:5060\"/>\n    </remote>\n    <local>\n      <identity>sip:200-test@linux.test.com:5060</identity>\n      <target uri=\"sip:200-test@linux.test.com:5060\"/>\n    </local>\n  </dialog>\n</dialog-info>\n',1576845067,0,'pres-5dfcb708-161d-1',1576848667), result 0
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:102]: publ_send200ok(): send 200OK reply
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: presence [presentity.c:103]: publ_send200ok(): etag= a.1576843015.5661.1.0 - len= 21
Dec 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=0x7f840349bc80
Dec 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 reset
Dec 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 OK
Dec 20 14:31:07 linux /usr/sbin/kamailio[5661]: DEBUG: tm [t_reply.c:621]: _reply_light(): finished
Dec 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_dialog
Dec 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!