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(a)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@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(a)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(a)lists.kamailio.org> *On Behalf Of *?????????
???????
*Sent:* Tuesday, December 17, 2019 1:19 PM
*To:* Kamailio (SER) - Users Mailing List <sr-users(a)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!