Hi,
during simulating scenarios in relation with the notify problem I have so far, I became unsure, if Kamilio (in principal) is supporting handling of PUBLISH requests (event "dialog") that contain _more than_ one (1) dialog entry. I know that it can generate notify requests with a message body that contains more than one dialog entry. But that´s not automatically the same as handling publish requests....
So - is Kamailio able or not? Did anybody ever use it in such a scenario?
regards, Klaus
Hello,
I haven't meet that case yet, but xml aggregation in presence_dialoginfo seems to walk through all children of root note for each xml doc. Maybe you can post here the output with debug=3.
Cheers, Daniel
On 05/05/14 13:17, Klaus Feichtinger wrote:
Hi, during simulating scenarios in relation with the notify problem I have so far, I became unsure, if Kamilio (in principal) is supporting handling of PUBLISH requests (event "dialog") that contain _more than_ one (1) dialog entry. I know that it can generate notify requests with a message body that contains more than one dialog entry. But that´s not automatically the same as handling publish requests.... So - is Kamailio able or not? Did anybody ever use it in such a scenario? regards, Klaus
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
this is the output (in this example version 3.2.4) in debug level 3 after receiving a PUBLISH request (incl. forming the NOTIFY request):
May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [event_list.c:350]: start event= [dialog/5] May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:349]: SIP-If-Match header not found May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:85]: etag= a.1399299676.23439.2.0 / 22#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:358]: new etag = a.1399299676.23439.2.0 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:383]: Expires header found, value= 1800 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:468]: KLAUSDBG - body = <?xml version="1.0"?>#015#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87">#015#012<dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#015#012<state>terminated</state>#015#012<remote>#015#012<identity>sip:1101015004@172.31.60.13</identity>#015#012<target uri="sip:1101015004@172.31.60.13"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012<dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#015#012<state>confirmed</state>#015#012<remote>#015#012<identity>sip:117101@172.31.60.87</identity>#015#012<target uri="sip:117101@172.31.60.87"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012</dialog-info>#015#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [hash.c:470]: pres_uri= sip:116001@10.16.48.44 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:385]: inserting 8 cols into table May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:99]: send 200OK reply May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:100]: etag= a.1399299676.23439.2.0 - len= 22 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1041]: querying database table = active_watchers May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1116]: found 1 dialogs May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]= sip:117700@10.16.48.14:5070#011[record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1333]: found 1 dialogs( 1 in database and 0 in hash_table) May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:782]: Event requires aggregation May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:67]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:107]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:199]: node type: Element, name: dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:73]: [n_body]=0xb7a6daa4 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:76]: [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:328]: replace version with "1" May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1651]: updating subscription to database May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1468]: dialog info: May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]= sip:117700@10.16.48.14:5070#011[record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:236]: expires = 889 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1562]: headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=870#015#012Content-Type: application/dialog-info+xml#015#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:964]: CONTACT = sip:117700@10.16.48.14:5070 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1724]: === 22/6/37 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: INFO: presence [notify.c:1593]: NOTIFY sip:117700@10.16.48.14 via sip:117700@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1689]: completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-8c7d]
Main visible difference is the xml body output between PUBLISH (publish.c) and NOTIFY (notify_body.c).
regards, Klaus
Daniel-Constantin Mierla miconda@gmail.com hat am 5. Mai 2014 um 13:27 geschrieben:
Hello,
I haven't meet that case yet, but xml aggregation in presence_dialoginfo seems to walk through all children of root note for each xml doc. Maybe you can post here the output with debug=3.
Cheers, Daniel
On 05/05/14 13:17, Klaus Feichtinger wrote:
> > Hi,during simulating scenarios in relation with the notify problem I haveso far, I became unsure, if Kamilio (in principal) is supporting handling of PUBLISH requests (event "dialog") that contain _more than_ one (1) dialog entry. I know that it can generate notify requests with a message body that contains more than one dialog entry. But that´s not automatically the same as handling publish requests....
So - is Kamailio able or not? Did anybody ever use it in such ascenario?
regards, Klaus _______________________________________________ SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org <mailto:sr-users@lists.sip-router.org> <http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users>-- Daniel-Constantin Mierla - http://www.asipto.com http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Can you try with the latest version 4.1.x? It is where I looked in the code and seemed to walk through all dialog nodes.
Cheers, Daniel
On 05/05/14 16:28, Klaus Feichtinger wrote:
this is the output (in this example version 3.2.4) in debug level 3 after receiving a PUBLISH request (incl. forming the NOTIFY request): May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [event_list.c:350]: start event= [dialog/5] May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:349]: SIP-If-Match header not found May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:85]: etag= a.1399299676.23439.2.0 / 22#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:358]: new etag = a.1399299676.23439.2.0 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:383]: Expires header found, value= 1800 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:468]: KLAUSDBG - body = <?xml version="1.0"?>#015#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87">#015#012<dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#015#012<state>terminated</state>#015#012<remote>#015#012<identity>sip:1101015004@172.31.60.13</identity>#015#012<target uri="sip:1101015004@172.31.60.13"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012<dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#015#012<state>confirmed</state>#015#012<remote>#015#012<identity>sip:117101@172.31.60.87</identity>#015#012<target uri="sip:117101@172.31.60.87"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012</dialog-info>#015#012
May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [hash.c:470]: pres_uri= sip:116001@10.16.48.44 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:385]: inserting 8 cols into table May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:99]: send 200OK reply May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:100]: etag= a.1399299676.23439.2.0 - len= 22 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1041]: querying database table = active_watchers May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1116]: found 1 dialogs May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]= sip:117700@10.16.48.14:5070#011[record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1333]: found 1 dialogs( 1 in database and 0 in hash_table) May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:782]: Event requires aggregation May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:67]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:107]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:199]: node type: Element, name: dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:73]: [n_body]=0xb7a6daa4 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:76]: [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012
May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:328]: replace version with "1" May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1651]: updating subscription to database May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1468]: dialog info: May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]= sip:117700@10.16.48.14:5070#011[record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:236]: expires = 889 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1562]: headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=870#015#012Content-Type: application/dialog-info+xml#015#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:964]: CONTACT = sip:117700@10.16.48.14:5070 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1724]: === 22/6/37 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: INFO: presence [notify.c:1593]: NOTIFY sip:117700@10.16.48.14 via sip:117700@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1689]: completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-8c7d]
Main visible difference is the xml body output between PUBLISH (publish.c) and NOTIFY (notify_body.c). regards, Klaus
Daniel-Constantin Mierla miconda@gmail.com hat am 5. Mai 2014 um 13:27 geschrieben:
Hello,
I haven't meet that case yet, but xml aggregation in presence_dialoginfo seems to walk through all children of root note for each xml doc. Maybe you can post here the output with debug=3.
Cheers, Daniel
On 05/05/14 13:17, Klaus Feichtinger wrote:
Hi, during simulating scenarios in relation with the notify problem I have so far, I became unsure, if Kamilio (in principal) is supporting handling of PUBLISH requests (event "dialog") that contain _more than_ one (1) dialog entry. I know that it can generate notify requests with a message body that contains more than one dialog entry. But that´s not automatically the same as handling publish requests.... So - is Kamailio able or not? Did anybody ever use it in such a scenario? regards, Klaus
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list sr-users@lists.sip-router.org mailto:sr-users@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
-- Daniel-Constantin Mierla -http://www.asipto.com http://twitter.com/#!/miconda http://twitter.com/#%21/miconda -http://www.linkedin.com/in/miconda
Hello Daniel,
I´ve reproduced the scenario with Kamailio version 4.1.3. Behaviour is the same and this is the output from kamailio-4.1.3 with debug=3:
May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: INFO: -<|XLOG|>-: <PRESENCE> handle_subscribe From: sip:117711@10.16.48.14 executed May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1098]: extract_sdialog_info(): 'Expires' header found, value= 900 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1120]: extract_sdialog_info(): 'To' header ALREADY PARSED: sip:116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1191]: extract_sdialog_info(): generating to_tag May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1251]: extract_sdialog_info(): subs->contact= sip:117711@10.16.48.14:5070 - len = 27 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:981]: handle_subscribe(): subscription status= active - found in watcher table May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 0/20 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:130]: printf_subs(): version: 1 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 900 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:354]: insert_subs_db(): inserting subscription in active_watchers table May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1471]: send_notify_request(): dialog info: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 1/20 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:130]: printf_subs(): version: 2 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 898 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:616]: get_p_notify_body(): No record exists in hash_table May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=0 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1525]: send_notify_request(): Could not get the notify_body May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=898#015#012 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:117711@10.16.48.14:5070 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 898 status 1 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:117711@10.16.48.14 via sip:117711@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-56dd] May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: INFO: -<|XLOG|>-: <PRESENCE> handle_publish From: sip:117103@172.31.60.87 executed May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:318]: handle_publish(): SIP-If-Match header not found May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:87]: generate_ETag(): etag= a.1399360111.20480.4.0 / 22#012 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:327]: handle_publish(): new etag = a.1399360111.20480.4.0 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:352]: handle_publish(): Expires header found, value= 1800 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:396]: handle_publish(): KFe - the PUBLISH body is processed... May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:407]: handle_publish(): KFe - the content length is: 962 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:444]: handle_publish(): KFe - event->evs_publ_handl is executed... May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:467]: handle_publish(): KFe - update_presentity is executed May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:468]: handle_publish(): KFe - body = <?xml version="1.0"?>#015#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87">#015#012<dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#015#012<state>terminated</state>#015#012<remote>#015#012<identity>sip:1101015004@172.31.60.13</identity>#015#012<target uri="sip:1101015004@172.31.60.13"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012<dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#015#012<state>confirmed</state>#015#012<remote>#015#012<identity>sip:117101@172.31.60.87</identity>#015#012<target uri="sip:117101@172.31.60.87"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012</dialog-info>#015#012 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:398]: update_presentity(): inserting 8 cols into table May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:104]: publ_send200ok(): send 200OK reply May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:105]: publ_send200ok(): etag= a.1399360111.20480.4.0 - len= 22 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1471]: send_notify_request(): dialog info: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 2/20 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:130]: printf_subs(): version: 3 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 893 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:744]: get_p_notify_body(): Event requires aggregation May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:126]: agregate_xmls(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:145]: agregate_xmls(): parsing XML body: [n]=1, [i]=0, [j]=0 xml_array[j]=0x9bef820 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:166]: agregate_xmls(): number of bodies in total [n]=1, number of useful bodies [j]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:210]: agregate_xmls(): [n]=1, [i]=0, [j]=1 xml_array[i]=0xc0c0c0c0 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:219]: agregate_xmls(): node type: Element, name: dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:81]: dlginfo_agg_nbody(): [n_body]=0xb7a9d298 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:84]: dlginfo_agg_nbody(): [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="sip:116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=893#015#012Content-Type: application/dialog-info+xml#015#012 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:117711@10.16.48.14:5070 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 893 status 1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:117711@10.16.48.14 via sip:117711@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-56dd]
The DB query returned the whole body incl. 2 dialog entries, as traced with Wireshark: MySQL Query/Result, traced with Wireshark Command: Query Statement: select body,etag,sender from presentity where domain='10.16.48.44' AND username='116001' AND event='dialog' order by received_time
<?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87"> <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient"> <state>terminated</state> <remote> <identity>sip:1101015004@172.31.60.13</identity> <target uri="sip:1101015004@172.31.60.13"/> </remote> <local> <identity>sip:117103@172.31.60.87</identity> <target uri="sip:117103@172.31.60.87"/> </local> </dialog> <dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator"> <state>confirmed</state> <remote> <identity>sip:117101@172.31.60.87</identity> <target uri="sip:117101@172.31.60.87"/> </remote> <local> <identity>sip:117103@172.31.60.87</identity> <target uri="sip:117103@172.31.60.87"/> </local> </dialog> </dialog-info> a.1399360111.20480.4.0
regards, Klaus
Daniel-Constantin Mierla miconda@gmail.com hat am 5. Mai 2014 um 17:37 geschrieben:
Can you try with the latest version 4.1.x? It is where I looked in the code and seemed to walk through all dialog nodes.
Cheers, Daniel
On 05/05/14 16:28, Klaus Feichtinger wrote:
> > this is the output (in this example version 3.2.4) in debug > > level 3 after receiving a PUBLISH request (incl. forming the NOTIFY > > request):May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence[event_list.c:350]: start event= [dialog/5] May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:349]: SIP-If-Match header not found May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:85]: etag= a.1399299676.23439.2.0 / 22#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:358]: new etag = a.1399299676.23439.2.0 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:383]: Expires header found, value= 1800 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [publish.c:468]: KLAUSDBG - body = <?xml version="1.0"?>#015#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity= "sip:117103@172.31.60.87" sip:117103@172.31.60.87
#015#012<dialog id= "CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13"
mailto:CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13 call-id= "CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" mailto:CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13 direction="recipient">#015#012<state>terminated</state>#015#012<remote>#015#012<identity>sip:1101015004@172.31.60.13 </identity>#015#012<target uri= "sip:1101015004@172.31.60.13" sip:1101015004@172.31.60.13 />#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87 </identity>#015#012<target uri= "sip:117103@172.31.60.87" sip:117103@172.31.60.87 />#015#012</local>#015#012</dialog>#015#012<dialog id= "1041054395-29684904-1398759995534@172.31.60.53" mailto:1041054395-29684904-1398759995534@172.31.60.53 call-id= "1041054395-29684904-1398759995534@172.31.60.53" mailto:1041054395-29684904-1398759995534@172.31.60.53 direction="initiator">#015#012<state>confirmed</state>#015#012<remote>#015#012<identity>sip:117101@172.31.60.87 </identity>#015#012<target uri= "sip:117101@172.31.60.87" sip:117101@172.31.60.87 />#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87 </identity>#015#012<target uri= "sip:117103@172.31.60.87" sip:117103@172.31.60.87 />#015#012</local>#015#012</dialog>#015#012</dialog-info>#015#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [hash.c:470]: pres_uri=sip:116001@10.16.48.44 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:385]: inserting 8 cols into table May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:99]: send 200OK reply May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [presentity.c:100]: etag= a.1399299676.23439.2.0 - len= 22 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1041]: querying database table = active_watchers May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1116]: found 1 dialogs May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]=sip:117700@10.16.48.14:5070#011 [record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1333]: found 1 dialogs( 1 in database and 0 in hash_table) May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:782]: Event requires aggregation May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:67]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:107]: [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:199]: node type: Element, name: dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:73]: [n_body]=0xb7a6daa4 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:76]: [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity= "116001@10.16.48.44" mailto:116001@10.16.48.44 >#012 <dialog id= "CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" mailto:CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13 call-id= "CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" mailto:CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13 direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13 </identity>#012<target uri= "sip:1101015004@172.31.60.13" sip:1101015004@172.31.60.13 />#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87 </identity>#012<target uri= "sip:117103@172.31.60.87" sip:117103@172.31.60.87 />#012</local>#012</dialog>#012</dialog-info>#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence_dialoginfo [notify_body.c:328]: replace version with "1" May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1651]: updating subscription to database May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1468]: dialog info: May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:122]: #012#011[pres_uri]= sip:116001@10.16.48.44#012#011[to_user]= 116001#011[to_domain]= 10.16.48.44#012#011[w_user]= 117700#011[w_domain]= 10.16.48.14#012#011[event]= dialog#012#011[status]= active#012#011[expires]= 889#012#011[callid]= 1146821297#011[local_cseq]=1#012#011[to_tag]= 4f7a7e54f75c89f5b968c90011d693b5-8c7d#011[from_tag]= 154174339#012#011[contact]=sip:117700@10.16.48.14:5070#011 [record_route]= May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:236]: expires = 889 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1562]: headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060 sip:10.16.48.44:5060 #015#012Subscription-State: active;expires=870#015#012Content-Type: application/dialog-info+xml#015#012 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:964]: CONTACT =sip:117700@10.16.48.14:5070 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1724]: === 22/6/37 May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: INFO: presence [notify.c:1593]: NOTIFYsip:117700@10.16.48.14 viasip:117700@10.16.48.14:5070 on behalf ofsip:116001@10.16.48.44 for event dialog May 5 16:21:49 sipsrvnode1 /usr/sbin/kamailio[23439]: DEBUG: presence [notify.c:1689]: completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-8c7d]
Main visible difference is the xml body output between PUBLISH(publish.c) and NOTIFY (notify_body.c).
regards, Klaus
Hello Daniel,
I´ve reproduced the scenario with Kamailio version 4.1.3. Behaviour is the same and this is the output from kamailio-4.1.3 with debug=3:
May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: INFO: -<|XLOG|>-: <PRESENCE> handle_subscribe From: sip:117711@10.16.48.14 executed May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1098]: extract_sdialog_info(): 'Expires' header found, value= 900 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1120]: extract_sdialog_info(): 'To' header ALREADY PARSED: sip:116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1191]: extract_sdialog_info(): generating to_tag May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:1251]: extract_sdialog_info(): subs->contact= sip:117711@10.16.48.14:5070 - len = 27 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:981]: handle_subscribe(): subscription status= active - found in watcher table May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 0/20 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:130]: printf_subs(): version: 1 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 900 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:08:54 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [subscribe.c:354]: insert_subs_db(): inserting subscription in active_watchers table May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1471]: send_notify_request(): dialog info: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 1/20 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:130]: printf_subs(): version: 2 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 898 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:616]: get_p_notify_body(): No record exists in hash_table May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=0 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1525]: send_notify_request(): Could not get the notify_body May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=898#015#012 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:117711@10.16.48.14:5070 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 898 status 1 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:117711@10.16.48.14 via sip:117711@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 6 09:08:56 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-56dd] May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: INFO: -<|XLOG|>-: <PRESENCE> handle_publish From: sip:117103@172.31.60.87 executed May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:318]: handle_publish(): SIP-If-Match header not found May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:87]: generate_ETag(): etag= a.1399360111.20480.4.0 / 22#012 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:327]: handle_publish(): new etag = a.1399360111.20480.4.0 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:352]: handle_publish(): Expires header found, value= 1800 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:396]: handle_publish(): KFe - the PUBLISH body is processed... May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:407]: handle_publish(): KFe - the content length is: 962 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:444]: handle_publish(): KFe - event->evs_publ_handl is executed... May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:467]: handle_publish(): KFe - update_presentity is executed May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [publish.c:468]: handle_publish(): KFe - body = <?xml version="1.0"?>#015#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87">#015#012<dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#015#012<state>terminated</state>#015#012<remote>#015#012<identity>sip:1101015004@172.31.60.13</identity>#015#012<target uri="sip:1101015004@172.31.60.13"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012<dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#015#012<state>confirmed</state>#015#012<remote>#015#012<identity>sip:117101@172.31.60.87</identity>#015#012<target uri="sip:117101@172.31.60.87"/>#015#012</remote>#015#012<local>#015#012<identity>sip:117103@172.31.60.87</identity>#015#012<target uri="sip:117103@172.31.60.87"/>#015#012</local>#015#012</dialog>#015#012</dialog-info>#015#012 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:398]: update_presentity(): inserting 8 cols into table May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:104]: publ_send200ok(): send 200OK reply May 6 09:09:00 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [presentity.c:105]: publ_send200ok(): etag= a.1399360111.20480.4.0 - len= 22 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [event_list.c:351]: search_event(): start event= [dialog/5] May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1471]: send_notify_request(): dialog info: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:117]: printf_subs(): pres_uri: sip:116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:118]: printf_subs(): watcher_user@watcher_domain: 117711@10.16.48.14 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:119]: printf_subs(): to_user@to_domain: 116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:120]: printf_subs(): from_user@from_domain: 117711@10.16.48.14 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:121]: printf_subs(): callid/from_tag/to_tag: 1543162531/749132449/4f7a7e54f75c89f5b968c90011d693b5-56dd May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:122]: printf_subs(): local_cseq/remote_cseq: 2/20 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:123]: printf_subs(): local_contact/contact: sip:10.16.48.44:5060/sip:117711@10.16.48.14:5070 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:124]: printf_subs(): record_route: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:125]: printf_subs(): sockinfo_str: udp:10.16.48.44:5060 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:127]: printf_subs(): event: dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:128]: printf_subs(): status: active May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:129]: printf_subs(): reason: May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:130]: printf_subs(): version: 3 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:131]: printf_subs(): expires: 893 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:133]: printf_subs(): updated/updated_winfo: 46/-1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [hash.c:461]: search_phtable(): pres_uri= sip:116001@10.16.48.44 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:744]: get_p_notify_body(): Event requires aggregation May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:126]: agregate_xmls(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:145]: agregate_xmls(): parsing XML body: [n]=1, [i]=0, [j]=0 xml_array[j]=0x9bef820 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:166]: agregate_xmls(): number of bodies in total [n]=1, number of useful bodies [j]=1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:210]: agregate_xmls(): [n]=1, [i]=0, [j]=1 xml_array[i]=0xc0c0c0c0 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:219]: agregate_xmls(): node type: Element, name: dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:81]: dlginfo_agg_nbody(): [n_body]=0xb7a9d298 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence_dialoginfo [notify_body.c:84]: dlginfo_agg_nbody(): [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="sip:116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=893#015#012Content-Type: application/dialog-info+xml#015#012 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:117711@10.16.48.14:5070 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 893 status 1 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20485]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:117711@10.16.48.14 via sip:117711@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 6 09:09:01 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[20480]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-56dd]
The DB query returned the whole body incl. 2 dialog entries, as traced with Wireshark: MySQL Query/Result, traced with Wireshark Command: Query Statement: select body,etag,sender from presentity where domain='10.16.48.44' AND username='116001' AND event='dialog' order by received_time
<?xml version="1.0"?> <dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000004" state="full" entity="sip:117103@172.31.60.87"> <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient"> <state>terminated</state> <remote> <identity>sip:1101015004@172.31.60.13</identity> <target uri="sip:1101015004@172.31.60.13"/> </remote> <local> <identity>sip:117103@172.31.60.87</identity> <target uri="sip:117103@172.31.60.87"/> </local> </dialog> <dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator"> <state>confirmed</state> <remote> <identity>sip:117101@172.31.60.87</identity> <target uri="sip:117101@172.31.60.87"/> </remote> <local> <identity>sip:117103@172.31.60.87</identity> <target uri="sip:117103@172.31.60.87"/> </local> </dialog> </dialog-info> a.1399360111.20480.4.0
regards, Klaus
Daniel-Constantin Mierla miconda@gmail.com hat am 5. Mai 2014 um 17:37 geschrieben:
Can you try with the latest version 4.1.x? It is where I looked in the code and seemed to walk through all dialog nodes.
Cheers, Daniel
On 05/05/14 16:28, Klaus Feichtinger wrote:
Hi Daniel,
I think we´ve found the reason, why this problem occurs!
The problem is caused in the "agregate_xmls" function in file "notify_body.c" of the "presence_dialoginfo" module:
/* loop over all bodies and create the aggregated body */ for(i=0; i<j; i++) { /* LM_DBG("[n]=%d, [i]=%d, [j]=%d xml_array[i]=%p\n", n, i, j, xml_array[j] ); */ p_root= xmlDocGetRootElement(xml_array[i]); if(p_root ==NULL) { LM_ERR("while geting the xml_tree root element\n"); goto error; } if (p_root->children) { for (node = p_root->children; node; node = node->next) { if (node->type == XML_ELEMENT_NODE) { LM_DBG("node type: Element, name: %s\n", node->name); /* we do not copy the node, but unlink it and then add it ot the new node * this destroys the original document but we do not need it anyway. * using "copy" instead of "unlink" would also copy the namespace which * would then be declared redundant (libxml unfortunately can not remove * namespaces) */ if (!force_single_dialog || (j==1)) { xmlUnlinkNode(node); if(xmlAddChild(root_node, node)== NULL) { LM_ERR("while adding child\n"); goto error; }
It seems to be not the best idea to "unlink" the XML node (= "xmlUnlinkNode(node);"), as then no "node->next" is available any more. Therefore, this loop will _always_ stop after one dialog entry and ignore any additional one!
But we "solved" the problem in this way that the loop will not directly use "node->next", but a variable, which is set within the loop. It looks like this: xmlNodePtr next_node = NULL; [...] if (p_root->children) { for (node = p_root->children; node; node = next_node) { next_node = node->next; if (node->type == XML_ELEMENT_NODE) { [...]
This solution has been tested with 2 and 3 dialog entries in a single PUBLISH request and it is working fine. We should discuss if this is a problem that should be solved generally or if it is a "private" problem in our use case.
What do you mean?
regards, Klaus
P.S. debug output (excerpt) of the "adapted" src code of release 4.1.3: May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:744]: get_p_notify_body(): Event requires aggregation May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:127]: agregate_xmls(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:146]: agregate_xmls(): parsing XML body: [n]=1, [i]=0, [j]=0 xml_array[j]=0x9311820 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:167]: agregate_xmls(): number of bodies in total [n]=1, number of useful bodies [j]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:211]: agregate_xmls(): [n]=1, [i]=0, [j]=1 xml_array[i]=0xc0c0c0c0 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:81]: dlginfo_agg_nbody(): [n_body]=0xb7ab5274 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:84]: dlginfo_agg_nbody(): [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="sip:116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012 <dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#012<state>confirmed</state>#012<remote>#012<identity>sip:117101@172.31.60.87</identity>#012<target uri="sip:117101@172.31.60.87"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012 <dialog id="2081054457-54683129-1398759736821@172.31.60.54" call-id="2081054457-54683129-1398759736821@172.31.60.54" direction="recipient">#012<state>alerting</state>#012<remote>#012<identity>sip:1101015005@172.31.60.87</identity>#012<target uri="sip:1101015005@172.31.60.87"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=1799#015#012Content-Type: application/dialog-info+xml#015#012 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:116633@10.16.48.14:5070 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 1799 status 1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:116633@10.16.48.14 via sip:116633@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21025]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-9ec9]
Hello,
can you send the patch to be reviewed?
Cheers, Daniel
On 07/05/14 13:15, Klaus Feichtinger wrote:
Hi Daniel, I think we´ve found the reason, why this problem occurs! The problem is caused in the "agregate_xmls" function in file "notify_body.c" of the "presence_dialoginfo" module: /* loop over all bodies and create the aggregated body */ for(i=0; i<j; i++) { /* LM_DBG("[n]=%d, [i]=%d, [j]=%d xml_array[i]=%p\n", n, i, j, xml_array[j] ); */ p_root= xmlDocGetRootElement(xml_array[i]); if(p_root ==NULL) { LM_ERR("while geting the xml_tree root element\n"); goto error; } if (p_root->children) { for (node = p_root->children; node; node = node->next) { if (node->type == XML_ELEMENT_NODE) { LM_DBG("node type: Element, name: %s\n", node->name); /* we do not copy the node, but unlink it and then add it ot the new node * this destroys the original document but we do not need it anyway. * using "copy" instead of "unlink" would also copy the namespace which * would then be declared redundant (libxml unfortunately can not remove * namespaces) */ if (!force_single_dialog || (j==1)) { xmlUnlinkNode(node); if(xmlAddChild(root_node, node)== NULL) { LM_ERR("while adding child\n"); goto error; } It seems to be not the best idea to "unlink" the XML node (= "xmlUnlinkNode(node);"), as then no "node->next" is available any more. Therefore, this loop will _always_ stop after one dialog entry and ignore any additional one! But we "solved" the problem in this way that the loop will not directly use "node->next", but a variable, which is set within the loop. It looks like this: xmlNodePtr next_node = NULL; [...] if (p_root->children) { for (node = p_root->children; node; node = next_node) { next_node = node->next; if (node->type == XML_ELEMENT_NODE) { [...] This solution has been tested with 2 and 3 dialog entries in a single PUBLISH request and it is working fine. We should discuss if this is a problem that should be solved generally or if it is a "private" problem in our use case. What do you mean?
regards, Klaus P.S. debug output (excerpt) of the "adapted" src code of release 4.1.3: May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:744]: get_p_notify_body(): Event requires aggregation May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:75]: dlginfo_agg_nbody(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:127]: agregate_xmls(): [pres_user]=116001 [pres_domain]= 10.16.48.44, [n]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:146]: agregate_xmls(): parsing XML body: [n]=1, [i]=0, [j]=0 xml_array[j]=0x9311820 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:167]: agregate_xmls(): number of bodies in total [n]=1, number of useful bodies [j]=1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:211]: agregate_xmls(): [n]=1, [i]=0, [j]=1 xml_array[i]=0xc0c0c0c0 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:222]: agregate_xmls(): node type: Element, name: dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:81]: dlginfo_agg_nbody(): [n_body]=0xb7ab5274 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence_dialoginfo [notify_body.c:84]: dlginfo_agg_nbody(): [*n_body]=<?xml version="1.0"?>#012<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="00000000000" state="full" entity="sip:116001@10.16.48.44">#012 <dialog id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" call-id="CBE263FF-CEAE11E3-80E8CCBC-52135ACA@172.31.60.13" direction="recipient">#012<state>terminated</state>#012<remote>#012<identity>sip:1101015004@172.31.60.13</identity>#012<target uri="sip:1101015004@172.31.60.13"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012 <dialog id="1041054395-29684904-1398759995534@172.31.60.53" call-id="1041054395-29684904-1398759995534@172.31.60.53" direction="initiator">#012<state>confirmed</state>#012<remote>#012<identity>sip:117101@172.31.60.87</identity>#012<target uri="sip:117101@172.31.60.87"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012 <dialog id="2081054457-54683129-1398759736821@172.31.60.54" call-id="2081054457-54683129-1398759736821@172.31.60.54" direction="recipient">#012<state>alerting</state>#012<remote>#012<identity>sip:1101015005@172.31.60.87</identity>#012<target uri="sip:1101015005@172.31.60.87"/>#012</remote>#012<local>#012<identity>sip:117103@172.31.60.87</identity>#012<target uri="sip:117103@172.31.60.87"/>#012</local>#012</dialog>#012</dialog-info>#012
May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1564]: send_notify_request(): headers:#012Max-Forwards: 70#015#012Event: dialog#015#012Contact: sip:10.16.48.44:5060#015#012Subscription-State: active;expires=1799#015#012Content-Type: application/dialog-info+xml#015#012 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:926]: ps_build_dlg_t(): CONTACT = sip:116633@10.16.48.14:5070 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1574]: send_notify_request(): expires 1799 status 1 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: DEBUG: presence [notify.c:1727]: shm_dup_cbparam(): === 22/6/37 May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21030]: INFO: presence [notify.c:1601]: send_notify_request(): NOTIFY sip:116633@10.16.48.14 via sip:116633@10.16.48.14:5070 on behalf of sip:116001@10.16.48.44 for event dialog May 7 13:11:07 sipsrvnode1 /usr/local/kamailio41/sbin/kamailio[21025]: DEBUG: presence [notify.c:1701]: p_tm_callback(): completed with status 200 [to_tag:4f7a7e54f75c89f5b968c90011d693b5-9ec9]
-
Daniel-Constantin Mierla -
Klaus Feichtinger