[OpenSIPS-Users] Reg: help needed to get RLS module working
Visu.M
visumrs at gmail.com
Thu Feb 26 22:35:32 CET 2009
Thanks Anca for looking into the problem.
Here are the details you asked for. I earlier didn't include the fallback2db
parameter. now included it.
Now, the error changes to
"ERROR:presence:get_database_info: No matching subscription dialog found in
database"
Here is my Config file:
#--rls parameters --
modparam("rls","db_url", "mysql://opensips:opensipsrw@localhost/opensips")
modparam("rls", "server_address", "sip:128.61.113.210:5060")
modparam("rls", "xcap_root", "http://128.61.113.210/xcap-root:80")
modparam("rls|presence_xml", "integrated_xcap_server", 1)
modparam("rls", "presence_server", "sip:128.61.113.210:5060")
modparam("rls", "to_presence_code", 10)
modparam("rls", "waitn_time", 10)
# ----- presence params -----
/* uncomment the following lines if you want to enable presence */
modparam("presence|presence_xml", "db_url",
"mysql://opensips:opensipsrw@localhost/opensips")
modparam("presence_xml", "force_active", 0)
modparam("presence", "server_address", "sip:128.61.113.210:5060")
#-- mi_xmlrpc params --
/*set the same port in OpenXCAP configuration file*/
modparam("mi_xmlrpc","port", 8081)
#--pua parameters --
modparam("pua","db_url","mysql://opensips:opensipsrw@localhost/opensips")
----------------------------------*--------------------------------------
Also, another thing, I noted.
In watcher info of cnn which is buddy of 'alice', alice was listed when I
first subscribe to the list.
But subsequently from the next notify, 'alice' disappears from that list.
----
Received NOTIFY:
----
Active watchers:
sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210>
Terminated watchers:
Pending watchers:
Waiting watchers:
----
Received NOTIFY:
----
Active watchers:
Terminated watchers:
Pending watchers:
Waiting watchers:
----
-----------------------------&;--------------------------
Log file is attached with the mail.
It contains log from "DBG:core:parse_msg: method: <SUBSCRIBE>" with the
first occurrence of the error.
------------------------------------------------*--------------------------------------------------
Log of sip trace for alice-buddies. (adding the last notify message. other
notify's are similar in content)
---------------------------------------------------*-------------------------------------------
SENDING: Packet 24, +0:24:35.137175
2009-02-26 16:31:21.812429: 128.61.113.210:59003 -(UDP)->
128.61.113.210:5060
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP
128.61.113.210;received=128.61.113.210;branch=z9hG4bK0.2a071b83.0^M
Call-ID: I3mLPr-0nQkBLFy6swEoAI3NxNQxGFHx^M
From: <sip:alice-buddies at 128.61.113.210 <sip%3Aalice-buddies at 128.61.113.210>
>;tag=10.19334.1235682406.1^M
To: <sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210>
>;tag=EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp^M
CSeq: 6 NOTIFY^M
Contact: <sip:arQ7pqMfhm at 128.61.113.210:59003;transport=udp>^M
Allow: SUBSCRIBE, NOTIFY, PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, MESSAGE^M
Supported: 100rel^M
Content-Length: 0^M
Please let me know, if I need to add any other details.
Thanks,
Visu
On Thu, Feb 26, 2009 at 1:23 PM, Anca Vamanu <anca at opensips.org> wrote:
> Hi Visu,
>
> I have now tested RLS for 1.4.X branch and sipsimpleclient and did not saw
> that error. Please give me more details.
> What is the configuration that you use? Do you set the fallback2db
> parameter? Best if you print here the parameters for presence and rls
> modules.
> Also can you please increase the debug level to 6 and the print here the
> part of the log that contains the errors - for that process begining with
> the processing of the message - you should search upwards for a line
> containing DBG:core:parse_msg: method: <SUBSCRIBE>.
>
> regards,
> Anca
>
>
> Visu.M wrote:
>
>> Hi,
>>
>> Folks, I am using opensips with rls module integrated with openxcap
>> server. Client is sipsimpleclient.
>> I am playing around RLS and openXCAP to see the basic functionality of RLS
>> module.
>>
>> I created a buddy list for 'alice' with two buddies. I am able to
>> subscribe to the buddy list.
>> But, when one of the buddy publishes it presence information, 'alice' is
>> not receiving any notifications.
>>
>> On checking through the server logs, I am getting the following error
>> message in the server.
>> Here the info says that alice subscription has got expanded.
>> subsequent message says that send notify request to alice on behalf of one
>> of the buddy. But no notification is received in the client.
>> Then the error message and notification cycle continues.
>>
>> I am using 1.4.4 version of Opensips. Can someone throw some light?
>> Is the issue with config file (I dont think so) or is it some other error.
>> Please let me know.
>>
>> Thanks,
>> Visu M
>>
>> "
>> Feb 26 11:54:22 [7906] INFO:rls:resource_subscriptions: Subscription from
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for resource
>> list uri sip:alice-buddies at 128.61.113.210<sip%3Aalice-buddies at 128.61.113.210><mailto:
>> sip%3Aalice-buddies at 128.61.113.210 <sip%253Aalice-buddies at 128.61.113.210>>
>> expanded to 2 contacts
>> Feb 26 11:54:22 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:54:22 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>> Feb 26 11:54:22 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:54:22 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>> Feb 26 11:54:22 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> for event presence
>> Feb 26 11:54:22 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> for event
>> presence"
>>
>> sometimes, I get this error as well, "Feb 26 12:44:03 [7918]
>> ERROR:rls:rls_notify_callback: record not found in hash table".
>>
>>
>> ------------------complete Log file------------------
>> Feb 26 11:40:12 [7906] WARNING:core:main: no fork mode
>> Feb 26 11:40:12 [7906] INFO:core:init_tcp: using epoll_lt as the TCP io
>> watch method (auto detected)
>> Feb 26 11:40:12 [7906] NOTICE:core:main: version: opensips 1.4.4-notls
>> (i386/linux)
>> Feb 26 11:40:12 [7906] INFO:core:main: using 32 Mb shared memory
>> Feb 26 11:40:12 [7906] INFO:core:main: using 1 Mb private memory per
>> process
>> Feb 26 11:40:12 [7906] INFO:sl:mod_init: Initializing StateLess engine
>> Feb 26 11:40:12 [7906] INFO:tm:mod_init: TM - initializing...
>> Feb 26 11:40:12 [7906] INFO:maxfwd:mod_init: initializing...
>> Feb 26 11:40:12 [7906] INFO:usrloc:ul_init_locks: locks array size 512
>> Feb 26 11:40:12 [7906] INFO:registrar:mod_init: initializing...
>> Feb 26 11:40:12 [7906] INFO:textops:mod_init: initializing...
>> Feb 26 11:40:12 [7906] INFO:xlog:mod_init: initializing...
>> Feb 26 11:40:12 [7906] INFO:acc:mod_init: initializing...
>> Feb 26 11:40:12 [7906] NOTICE:presence:mod_init: initializing module ...
>> Feb 26 11:40:13 [7906] INFO:core:probe_max_receive_buffer: using a UDP
>> receive buffer of 255 kb
>> Feb 26 11:40:13 [7918] NOTICE:presence:child_init: init_child [-1] pid
>> [7918]
>> Feb 26 11:40:13 [7919] INFO:mi_xmlrpc:xmlrpc_process: starting xmlrpc
>> server
>> Feb 26 11:40:13 [7906] NOTICE:presence:child_init: init_child [1] pid
>> [7906]
>> Feb 26 11:46:59 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via
>> sip:zRyKH7i8zw at 128.61.113.210:36252;transport=udp on behalf of
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for event
>> presence
>> Feb 26 11:49:27 [7906] INFO:rls:resource_subscriptions: Subscription from
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for resource
>> list uri sip:alice-buddies at 128.61.113.210<sip%3Aalice-buddies at 128.61.113.210><mailto:
>> sip%3Aalice-buddies at 128.61.113.210 <sip%253Aalice-buddies at 128.61.113.210>>
>> expanded to 2 contacts
>> Feb 26 11:49:27 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> for event presence
>> Feb 26 11:49:27 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> for event presence
>> Feb 26 11:50:31 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> via
>> sip:SfXhTToFOs at 128.61.113.210:36762;transport=udp on behalf of
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> for event
>> presence.winfo
>> Feb 26 11:51:31 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> via
>> sip:xol3nysRsC at 128.61.113.210:49318;transport=udp on behalf of
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> for event
>> presence.winfo
>> Feb 26 11:53:33 [7918] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via
>> sip:zRyKH7i8zw at 128.61.113.210:36252;transport=udp on behalf of
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for event
>> presence
>> Feb 26 11:54:22 [7906] INFO:rls:resource_subscriptions: Subscription from
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for resource
>> list uri sip:alice-buddies at 128.61.113.210<sip%3Aalice-buddies at 128.61.113.210><mailto:
>> sip%3Aalice-buddies at 128.61.113.210 <sip%253Aalice-buddies at 128.61.113.210>>
>> expanded to 2 contacts
>> Feb 26 11:54:22 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:54:22 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>> Feb 26 11:54:22 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:54:22 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>> Feb 26 11:54:22 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> for event presence
>> Feb 26 11:54:22 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> via sip:
>> 128.61.113.210:5060 <http://128.61.113.210:5060> on behalf of
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> for event presence
>> Feb 26 11:55:26 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> via
>> sip:SfXhTToFOs at 128.61.113.210:36762;transport=udp on behalf of
>> sip:cnn at 128.61.113.210 <sip%3Acnn at 128.61.113.210> <mailto:
>> sip%3Acnn at 128.61.113.210 <sip%253Acnn at 128.61.113.210>> for event
>> presence.winfo
>> Feb 26 11:56:26 [7906] INFO:presence:send_notify_request: NOTIFY
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> via
>> sip:xol3nysRsC at 128.61.113.210:49318;transport=udp on behalf of
>> sip:bbc at 128.61.113.210 <sip%3Abbc at 128.61.113.210> <mailto:
>> sip%3Abbc at 128.61.113.210 <sip%253Abbc at 128.61.113.210>> for event
>> presence.winfo
>> Feb 26 11:59:17 [7906] INFO:rls:resource_subscriptions: Subscription from
>> sip:alice at 128.61.113.210 <sip%3Aalice at 128.61.113.210> <mailto:
>> sip%3Aalice at 128.61.113.210 <sip%253Aalice at 128.61.113.210>> for resource
>> list uri sip:alice-buddies at 128.61.113.210<sip%3Aalice-buddies at 128.61.113.210><mailto:
>> sip%3Aalice-buddies at 128.61.113.210 <sip%253Aalice-buddies at 128.61.113.210>>
>> expanded to 2 contacts
>> Feb 26 11:59:17 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:59:17 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>> Feb 26 11:59:17 [7906] ERROR:presence:get_stored_info: record not found in
>> hash_table
>> Feb 26 11:59:17 [7906] ERROR:presence:handle_subscribe: getting stored
>> info
>>
>> ---------------------------*----------------------------------------------------------
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> Users mailing list
>> Users at lists.opensips.org
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.opensips.org/pipermail/users/attachments/20090226/f38ca659/attachment-0001.htm
-------------- next part --------------
Feb 26 16:11:23 [19334] DBG:core:parse_msg: SIP Request:
Feb 26 16:11:23 [19334] DBG:core:parse_msg: method: <SUBSCRIBE>
Feb 26 16:11:23 [19334] DBG:core:parse_msg: uri: <sip:128.61.113.210:5060>
Feb 26 16:11:23 [19334] DBG:core:parse_msg: version: <SIP/2.0>
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=2
Feb 26 16:11:23 [19334] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Feb 26 16:11:23 [19334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjzJSsxYuxL.T7xyVe1R8L-pHcvI8DFnUn>; state=16
Feb 26 16:11:23 [19334] DBG:core:parse_via: end of header reached, state=5
Feb 26 16:11:23 [19334] DBG:core:parse_headers: via found, flags=2
Feb 26 16:11:23 [19334] DBG:core:parse_headers: this is the first via
Feb 26 16:11:23 [19334] DBG:core:receive_msg: After parse_msg...
Feb 26 16:11:23 [19334] DBG:core:receive_msg: preparing to run routing scripts...
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=100
Feb 26 16:11:23 [19334] DBG:maxfwd:is_maxfwd_present: value = 70
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=8
Feb 26 16:11:23 [19334] DBG:core:parse_to_param: tag=10.19334.1235682388.1
Feb 26 16:11:23 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:23 [19334] DBG:core:parse_to: display={"cnn"}, ruri={sip:cnn at 128.61.113.210}
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: <To> [58]; uri=[sip:cnn at 128.61.113.210]
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: to body ["cnn" <sip:cnn at 128.61.113.210>]
Feb 26 16:11:23 [19334] DBG:uri:has_totag: totag found
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=200
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: cseq <CSeq>: <18290> <SUBSCRIBE>
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: content_length=0
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: found end of header
Feb 26 16:11:23 [19334] DBG:rr:find_first_route: No Route headers found
Feb 26 16:11:23 [19334] DBG:rr:loose_route: There is no Route HF
Feb 26 16:11:23 [19334] DBG:core:comp_scriptvar: str 20 : 128.61.113.210
Feb 26 16:11:23 [19334] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=78
Feb 26 16:11:23 [19334] DBG:tm:t_lookup_request: start searching: hash=53949, isACK=0
Feb 26 16:11:23 [19334] DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 26 16:11:23 [19334] DBG:tm:t_lookup_request: no transaction found
Feb 26 16:11:23 [19334] DBG:tm:run_reqin_callbacks: trans=0xb59bc060, callback type 1, id 0 entered
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:23 [19334] DBG:rls:rls_handle_subscribe: no supported header found
Feb 26 16:11:23 [19334] DBG:core:comp_scriptvar: int 20 : 10 / 10
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:23 [19334] DBG:presence:search_event: start event= [presence.winfo]
Feb 26 16:11:23 [19334] DBG:presence:extract_sdialog_info: 'Expires' header found, value= 300
Feb 26 16:11:23 [19334] DBG:presence:extract_sdialog_info: 'To' header ALREADY PARSED: <sip:cnn at 128.61.113.210>
Feb 26 16:11:23 [19334] DBG:presence:extract_sdialog_info: 'From' header not parsed
Feb 26 16:11:23 [19334] DBG:core:parse_to_param: tag=1EnveC0rl7w.L5eLlWUkD-p2o0r7Ux1p
Feb 26 16:11:23 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:23 [19334] DBG:core:parse_to: display={"cnn"}, ruri={sip:cnn at 128.61.113.210}
Feb 26 16:11:23 [19334] DBG:presence:extract_sdialog_info: subs->contact= sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp - len = 49
Feb 26 16:11:23 [19334] DBG:presence:get_stored_info: Record found in hash_table
Feb 26 16:11:23 [19334] DBG:presence:handle_subscribe: subscription status= active - found in watcher table
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:23 [19334] DBG:core:check_via_address: params 128.61.113.210, 128.61.113.210, 0
Feb 26 16:11:23 [19334] DBG:presence:send_notify_request: dialog info:
Feb 26 16:11:23 [19334] DBG:presence:printf_subs:
[pres_uri]= sip:cnn at 128.61.113.210
[to_user]= cnn [to_domain]= 128.61.113.210
[w_user]= cnn [w_domain]= 128.61.113.210
[event]= presence.winfo
[status]= active
[expires]= 300
[callid]= cWwYyXXawITDXb51fEdNdO8gGLQX9Pzg [local_cseq]=2
[to_tag]= 10.19334.1235682388.1 [from_tag]= 1EnveC0rl7w.L5eLlWUkD-p2o0r7Ux1p
[contact]= sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp [record_route]=
Feb 26 16:11:23 [19334] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8191e50
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_get_columns: 5 columns returned from the query
Feb 26 16:11:23 [19334] DBG:core:db_allocate_columns: allocate 20 bytes for result names at 0x81967a8
Feb 26 16:11:23 [19334] DBG:core:db_allocate_columns: allocate 20 bytes for result types at 0x81966b8
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x8191a18
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191a18)[4]=[callid]
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:23 [19334] DBG:presence:get_wi_subs_db: The query in db table for active subscription returned no result
Feb 26 16:11:23 [19334] DBG:core:db_free_columns: freeing 5 columns
b 26 16:11:23 [19334] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:23 [19334] DBG:core:db_free_result: freeing result set at 0x8191e50
Feb 26 16:11:23 [19334] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8191e50
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Feb 26 16:11:23 [19334] DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x8191a18
Feb 26 16:11:23 [19334] DBG:core:db_allocate_columns: allocate 8 bytes for result types at 0x8191a28
Feb 26 16:11:23 [19334] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:23 [19334] DBG:presence:add_waiting_watchers: The query returned no result
Feb 26 16:11:23 [19334] DBG:core:db_free_columns: freeing 2 columns
Feb 26 16:11:23 [19334] DBG:core:db_free_result: freeing result set at 0x8191e50
Feb 26 16:11:23 [19334] DBG:presence:send_notify_request: headers:
Max-Forwards: 70
Event: presence.winfo
Contact: <sip:128.61.113.210:5060>
Subscription-State: active;expires=300
Content-Type: application/watcherinfo+xml
Feb 26 16:11:23 [19334] DBG:presence:build_dlg_t: CONTACT = sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp
Feb 26 16:11:23 [19334] DBG:core:grep_sock_info: checking if host==us: 14==14 && [128.61.113.210] == [128.61.113.210]
Feb 26 16:11:23 [19334] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 26 16:11:23 [19334] DBG:tm:t_uac: next_hop=<sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp>
Feb 26 16:11:23 [19334] DBG:core:mk_proxy: doing DNS lookup...
Feb 26 16:11:23 [19334] DBG:tm:dlg2hash: 240
Feb 26 16:11:23 [19334] DBG:tm:print_request_uri: sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp
Feb 26 16:11:23 [19334] DBG:tm:set_timer: relative timeout is 500000
Feb 26 16:11:23 [19334] DBG:tm:insert_timer_unsafe: [4]: 0xb59bd3c4 (299100000)
Feb 26 16:11:23 [19334] DBG:tm:set_timer: relative timeout is 30
Feb 26 16:11:23 [19334] DBG:tm:insert_timer_unsafe: [0]: 0xb59bd3e0 (328)
Feb 26 16:11:23 [19334] INFO:presence:send_notify_request: NOTIFY sip:cnn at 128.61.113.210 via sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp on behalf of sip:cnn at 128.61.113.210 for event presence.winfo
Feb 26 16:11:23 [19334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 26 16:11:23 [19334] DBG:tm:insert_timer_unsafe: [2]: 0xb59bc0a8 (303)
Feb 26 16:11:23 [19334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Feb 26 16:11:23 [19334] DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 16:11:23 [19334] DBG:core:receive_msg: cleaning up
Feb 26 16:11:23 [19334] DBG:core:parse_msg: SIP Reply (status):
Feb 26 16:11:23 [19334] DBG:core:parse_msg: version: <SIP/2.0>
Feb 26 16:11:23 [19334] DBG:core:parse_msg: status: <200>
Feb 26 16:11:23 [19334] DBG:core:parse_msg: reason: <OK>
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=2
Feb 26 16:11:23 [19334] DBG:core:parse_via_param: found param type 234, <received> = <128.61.113.210>; state=6
Feb 26 16:11:23 [19334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0f.7eef5675.0>; state=16
Feb 26 16:11:23 [19334] DBG:core:parse_via: end of header reached, state=5
Feb 26 16:11:23 [19334] DBG:core:parse_headers: via found, flags=2
Feb 26 16:11:23 [19334] DBG:core:parse_headers: this is the first via
Feb 26 16:11:23 [19334] DBG:core:receive_msg: After parse_msg...
Feb 26 16:11:23 [19334] DBG:core:forward_reply: found module tm, passing reply to it
Feb 26 16:11:23 [19334] DBG:tm:t_check: start=0xffffffff
Feb 26 16:11:23 [19334] DBG:core:parse_headers: flags=22
Feb 26 16:11:23 [19334] DBG:core:parse_to_param: tag=1EnveC0rl7w.L5eLlWUkD-p2o0r7Ux1p
Feb 26 16:11:23 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:23 [19334] DBG:core:parse_to: display={}, ruri={sip:cnn at 128.61.113.210}
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: <To> [63]; uri=[sip:cnn at 128.61.113.210]
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: to body [<sip:cnn at 128.61.113.210>]
Feb 26 16:11:23 [19334] DBG:core:get_hdr_field: cseq <CSeq>: <3> <NOTIFY>
Feb 26 16:11:23 [19334] DBG:tm:t_reply_matching: hash 240 label 1466302183 branch 0
Feb 26 16:11:23 [19334] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Feb 26 16:11:23 [19334] DBG:tm:t_reply_matching: reply matched (T=0xb59bd278)!
Feb 26 16:11:23 [19334] DBG:tm:t_check: end=0xb59bd278
Feb 26 16:11:23 [19334] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Feb 26 16:11:23 [19334] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Feb 26 16:11:23 [19334] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 26 16:11:23 [19334] DBG:tm:local_reply: local transaction completed
Feb 26 16:11:23 [19334] DBG:tm:run_trans_callbacks: trans=0xb59bd278, callback type 256, id 0 entered
Feb 26 16:11:23 [19334] DBG:presence:p_tm_callback: completed with status 200 [to_tag:10.19334.1235682388.1]
Feb 26 16:11:23 [19334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 26 16:11:23 [19334] DBG:tm:insert_timer_unsafe: [2]: 0xb59bd2c0 (303)
Feb 26 16:11:23 [19334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Feb 26 16:11:23 [19334] DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 16:11:23 [19334] DBG:core:receive_msg: cleaning up
Feb 26 16:11:24 [19338] DBG:tm:utimer_routine: timer routine:4,tl=0xb59bd3c4 next=(nil), timeout=299100000
Feb 26 16:11:25 [19338] DBG:presence:printf_subs:
[pres_uri]= sip:alice-buddies at 128.61.113.210
[to_user]= alice-buddies [to_domain]= 128.61.113.210
[w_user]= alice [w_domain]= 128.61.113.210
[event]= presence
[status]= (null)
[expires]= 1235682706
[callid]= I3mLPr-0nQkBLFy6swEoAI3NxNQxGFHx [local_cseq]=1
[to_tag]= 10.19334.1235682406.1 [from_tag]= EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp
[contact]= sip:arQ7pqMfhm at 128.61.113.210:59003;transport=udp [record_route]=
Feb 26 16:11:25 [19338] DBG:presence:update_db_subs: NO_UPDATEDB_FLAG
Feb 26 16:11:25 [19338] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187dd8
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: 6 columns returned from the query
Feb 26 16:11:25 [19338] DBG:core:db_allocate_columns: allocate 24 bytes for result names at 0x8187e00
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191a18)[5]=[presence_state]
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result type
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:25 [19338] DBG:core:db_free_columns: freeing 6 columns
Feb 26 16:11:25 [19338] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:25 [19338] DBG:core:db_free_result: freeing result set at 0x8187dd8
Feb 26 16:11:25 [19338] DBG:pua:db_update: NO_UPDATEDB_FLAG
Feb 26 16:11:25 [19338] DBG:presence:printf_subs:
[pres_uri]= sip:cnn at 128.61.113.210
[to_user]= cnn [to_domain]= 128.61.113.210
[w_user]= cnn [w_domain]= 128.61.113.210
[event]= presence.winfo
[status]= active
[expires]= 1235682983
[callid]= cWwYyXXawITDXb51fEdNdO8gGLQX9Pzg [local_cseq]=3
[to_tag]= 10.19334.1235682388.1 [from_tag]= 1EnveC0rl7w.L5eLlWUkD-p2o0r7Ux1p
[contact]= sip:WDDnpJIqYQ at 128.61.113.210:34413;transport=udp [record_route]=
Feb 26 16:11:25 [19338] DBG:presence:update_db_subs: UPDATEDB_FLAG
Feb 26 16:11:25 [19338] DBG:presence:printf_subs:
[pres_uri]= sip:bbc at 128.61.113.210
[to_user]= bbc [to_domain]= 128.61.113.210
[w_user]= bbc [w_domain]= 128.61.113.210
[event]= presence.winfo
[status]= active
[expires]= 1235682713
[callid]= l.4oR0dBzqqi.6yP4greLaD7i.1QCo2F [local_cseq]=1
[to_tag]= 10.19334.1235682413.4 [from_tag]= -Kpg-euKWyVNVtxyAOOz5gkeeGq3GxRu
[contact]= sip:BzPHs7DKai at 128.61.113.210:58571;transport=udp [record_route]=
Feb 26 16:11:25 [19338] DBG:presence:update_db_subs: NO_UPDATEDB_FLAG
Feb 26 16:11:25 [19338] DBG:presence:msg_watchers_clean: cleaning pending subscriptions
Feb 26 16:11:25 [19338] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187dd8
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:25 [19338] DBG:core:db_free_columns: freeing 1 columns
Feb 26 16:11:25 [19338] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:25 [19338] DBG:core:db_free_result: freeing result set at 0x8187dd8
Feb 26 16:11:25 [19338] DBG:presence:msg_presentity_clean: cleaning expired presentity information
Feb 26 16:11:25 [19338] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187dd8
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: 4 columns returned from the query
Feb 26 16:11:25 [19338] DBG:core:db_allocate_columns: allocate 16 bytes for result names at 0x8187ef8
Feb 26 16:11:25 [19338] DBG:core:db_allocate_columns: allocate 16 bytes for result types at 0x8187e38
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 26 16:11:25 [19338] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:25 [19338] DBG:core:db_free_columns: freeing 4 columns
Feb 26 16:11:25 [19338] DBG:core:db_free_columns: freeing result types at 0x8187e38
Feb 26 16:11:25 [19338] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:25 [19338] DBG:core:db_free_result: freeing result set at 0x8187dd8
Feb 26 16:11:28 [19338] DBG:tm:timer_routine: timer routine:2,tl=0xb59bc0a8 next=0xb59bd2c0, timeout=303
Feb 26 16:11:28 [19338] DBG:tm:wait_handler: removing 0xb59bc060 from table
Feb 26 16:11:28 [19338] DBG:tm:delete_cell: delete transaction 0xb59bc060
Feb 26 16:11:28 [19338] DBG:tm:wait_handler: done
Feb 26 16:11:28 [19338] DBG:tm:timer_routine: timer routine:2,tl=0xb59bd2c0 next=(nil), timeout=303
Feb 26 16:11:28 [19338] DBG:tm:wait_handler: removing 0xb59bd278 from table
Feb 26 16:11:28 [19338] DBG:tm:delete_cell: delete transaction 0xb59bd278
Feb 26 16:11:28 [19338] DBG:tm:wait_handler: done
Feb 26 16:11:35 [19338] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187dd8
Feb 26 16:11:35 [19338] DBG:db_mysql:db_mysql_get_columns: 6 columns returned from the query
Feb 26 16:11:35 [19338] DBG:core:db_allocate_columns: allocate 24 bytes for result names at 0x8187e00
Feb 26 16:11:35 [19338] DBG:core:db_allocate_columns: allocate 24 bytes for result types at 0x8187f98
Feb 26 16:11:35 [19338] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x8191ca8
Feb 26 16:11:35 [19338] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result type
Feb 26 16:11:35 [19338] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:35 [19338] DBG:core:db_free_columns: freeing 6 columns
Feb 26 16:11:35 [19338] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:35 [19338] DBG:core:db_free_result: freeing result set at 0x8187dd8
Feb 26 16:11:41 [19334] DBG:core:parse_msg: SIP Request:
Feb 26 16:11:41 [19334] DBG:core:parse_msg: method: <SUBSCRIBE>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: uri: <sip:128.61.113.210:5060>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: version: <SIP/2.0>
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Feb 26 16:11:41 [19334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKPjRQTv0YDgC1mdbj-xVwGx2JsI3tHu8EaX>; state=16
Feb 26 16:11:41 [19334] DBG:core:parse_via: end of header reached, state=5
Feb 26 16:11:41 [19334] DBG:core:parse_headers: via found, flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_headers: this is the first via
Feb 26 16:11:41 [19334] DBG:core:receive_msg: After parse_msg...
Feb 26 16:11:41 [19334] DBG:core:receive_msg: preparing to run routing scripts...
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=100
Feb 26 16:11:41 [19334] DBG:maxfwd:is_maxfwd_present: value = 70
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=8
Feb 26 16:11:41 [19334] DBG:core:parse_to_param: tag=10.19334.1235682406.1
Feb 26 16:11:41 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:41 [19334] DBG:core:parse_to: display={}, ruri={sip:alice-buddies at 128.61.113.210}
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: <To> [60]; uri=[sip:alice-buddies at 128.61.113.210]
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: to body [sip:alice-buddies at 128.61.113.210]
Feb 26 16:11:41 [19334] DBG:uri:has_totag: totag found
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=200
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: cseq <CSeq>: <17243> <SUBSCRIBE>
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: content_length=0
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: found end of header
Feb 26 16:11:41 [19334] DBG:rr:find_first_route: No Route headers found
Feb 26 16:11:41 [19334] DBG:rr:loose_route: There is no Route HF
Feb 26 16:11:41 [19334] DBG:core:comp_scriptvar: str 20 : 128.61.113.210
Feb 26 16:11:41 [19334] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=78
Feb 26 16:11:41 [19334] DBG:tm:t_lookup_request: start searching: hash=28078, isACK=0
Feb 26 16:11:41 [19334] DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 26 16:11:41 [19334] DBG:tm:t_lookup_request: no transaction found
Feb 26 16:11:41 [19334] DBG:tm:run_reqin_callbacks: trans=0xb59bd278, callback type 1, id 0 entered
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:presence:search_event: start event= [presence]
Feb 26 16:11:41 [19334] DBG:rls:rls_handle_subscribe: 'To' header ALREADY PARSED: <sip:alice-buddies at 128.61.113.210>
Feb 26 16:11:41 [19334] DBG:core:parse_to_param: tag=EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp
Feb 26 16:11:41 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:41 [19334] DBG:core:parse_to: display={"alice"}, ruri={sip:alice at 128.61.113.210}
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: 'Expires' header found, value= 300
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: 'To' header ALREADY PARSED: <sip:alice-buddies at 128.61.113.210>
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: subs->contact= sip:arQ7pqMfhm at 128.61.113.210:59003;transport=udp - len = 49
Feb 26 16:11:41 [19334] DBG:rls:get_resource_list: Searched RL document for user sip:alice at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187f00
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Feb 26 16:11:41 [19334] DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x8191920
Feb 26 16:11:41 [19334] DBG:core:db_allocate_columns: allocate 8 bytes for result types at 0x8191840
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_str2val: converting BLOB [<?xml version='1.0' encoding='UTF-8'?>
<rls-services xmlns:rl="urn:ietf:params:xml:ns:resource-lists" xmlns="urn:ietf:params:xml:ns:rls-services">
<service uri="sip:alice-buddies at 128.61.113.210">
<list>
<rl:entry uri="sip:bbc at 128.61.113.210"/>
<rl:entry uri="sip:cnn at 128.61.113.210"/>
</list>
<packages>
<package>presence</package>
</packages>
</service>
</rls-services>
]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_str2val: converting STRING [955ba69595002674d4436497bfd8bc8e]
Feb 26 16:11:41 [19334] DBG:rls:get_resource_list: rls_services document:
<?xml version='1.0' encoding='UTF-8'?>
<rls-services xmlns:rl="urn:ietf:params:xml:ns:resource-lists" xmlns="urn:ietf:params:xml:ns:rls-services">
<service uri="sip:alice-buddies at 128.61.113.210">
<list>
<rl:entry uri="sip:bbc at 128.61.113.210"/>
<rl:entry uri="sip:cnn at 128.61.113.210"/>
</list>
<packages>
<package>presence</package>
</packages>
</service>
</rls-services>
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing 2 columns
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x8191a18
Feb 26 16:11:41 [19334] DBG:core:db_free_rows: freeing 1 rows
Feb 26 16:11:41 [19334] DBG:core:db_free_row: freeing row values at 0x81969f8
Feb 26 16:11:41 [19334] DBG:core:db_free_rows: freeing rows at 0x8196710
Feb 26 16:11:41 [19334] DBG:core:db_free_result: freeing result set at 0x8187f00
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:core:check_via_address: params 128.61.113.210, 128.61.113.210, 0
Feb 26 16:11:41 [19334] DBG:rls:send_full_notify: start
Feb 26 16:11:41 [19334] DBG:rls:CONSTR_RLSUBS_DID: did= I3mLPr-0nQkBLFy6swEoAI3NxNQxGFHx;EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp;10.19334.1235682406.1
Feb 26 16:11:41 [19334] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8187f00
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: 5 columns returned from the query
Feb 26 16:11:41 [19334] DBG:core:db_allocate_columns: allocate 20 bytes for result names at 0x8196698
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:41 [19334] DBG:rls:constr_rlmi_doc: start
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: start
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: start
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: uri= sip:bbc at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:rls:add_resource: uri= sip:bbc at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: uri= sip:cnn at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:rls:add_resource: uri= sip:cnn at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:rls:rls_send_notify: start
Feb 26 16:11:41 [19334] DBG:core:grep_sock_info: checking if host==us: 14==14 && [128.61.113.210] == [128.61.113.210]
Feb 26 16:11:41 [19334] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 26 16:11:41 [19334] DBG:rls:rls_send_notify: constructed dlg_t struct
Feb 26 16:11:41 [19334] DBG:rls:rls_send_notify: constructed cb_param
Feb 26 16:11:41 [19334] DBG:rls:rls_send_notify: str_hdr= Max-Forwards: 70
Event: presence
Contact: <sip:128.61.113.210:5060>
Subscription-State: active;expires=300
Require: eventlist
Content-Type: multipart/related;type="application/rlmi+xml";start= "<1235682701.sip:alice-buddies at 128.61.113.210.807044399>";boundary="owhiOeOlCVZddgcoajWuHDGH"
Feb 26 16:11:41 [19334] DBG:tm:t_uac: next_hop=<sip:arQ7pqMfhm at 128.61.113.210:59003;transport=udp>
Feb 26 16:11:41 [19334] DBG:core:mk_proxy: doing DNS lookup...
Feb 26 16:11:41 [19334] DBG:tm:dlg2hash: 4
Feb 26 16:11:41 [19334] DBG:tm:print_request_uri: sip:arQ7pqMfhm at 128.61.113.210:59003;transport=udp
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 500000
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [4]: 0xb59bc1ac (317100000)
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 30
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [0]: 0xb59bc1c8 (346)
Feb 26 16:11:41 [19334] DBG:rls:CONSTR_RLSUBS_DID: did= I3mLPr-0nQkBLFy6swEoAI3NxNQxGFHx;EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp;10.19334.1235682406.1
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: start
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: start
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: uri= sip:bbc at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:pua:print_subs: pres_uri= sip:bbc at 128.61.113.210 - len: 22
Feb 26 16:11:41 [19334] DBG:pua:print_subs: watcher_uri= sip:alice at 128.61.113.210 - len: 24
Feb 26 16:11:41 [19334] DBG:pua:search_htable: core_hash= 316
Feb 26 16:11:41 [19334] DBG:pua:search_htable: found record
Feb 26 16:11:41 [19334] DBG:pua:pua_build_dlg_t: size = 284
Feb 26 16:11:41 [19334] DBG:pua:subs_cbparam_indlg: size= 426
Feb 26 16:11:41 [19334] DBG:pua:send_subscribe: event parameter: 1
Feb 26 16:11:41 [19334] DBG:tm:t_uac: next_hop=<sip:128.61.113.210:5060>
Feb 26 16:11:41 [19334] DBG:core:mk_proxy: doing DNS lookup...
Feb 26 16:11:41 [19334] DBG:tm:dlg2hash: 61336
Feb 26 16:11:41 [19334] DBG:tm:print_request_uri: sip:128.61.113.210:5060
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 500000
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [4]: 0xb59b9754 (317100000)
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 30
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [0]: 0xb59b9770 (346)
Feb 26 16:11:41 [19334] DBG:rls:process_list_and_exec: uri= sip:cnn at 128.61.113.210
Feb 26 16:11:41 [19334] DBG:pua:print_subs: pres_uri= sip:cnn at 128.61.113.210 - len: 22
Feb 26 16:11:41 [19334] DBG:pua:print_subs: watcher_uri= sip:alice at 128.61.113.210 - len: 24
Feb 26 16:11:41 [19334] DBG:pua:search_htable: core_hash= 248
Feb 26 16:11:41 [19334] DBG:pua:search_htable: found record
Feb 26 16:11:41 [19334] DBG:pua:pua_build_dlg_t: size = 284
Feb 26 16:11:41 [19334] DBG:pua:subs_cbparam_indlg: size= 426
Feb 26 16:11:41 [19334] DBG:pua:send_subscribe: event parameter: 1
Feb 26 16:11:41 [19334] DBG:tm:t_uac: next_hop=<sip:128.61.113.210:5060>
Feb 26 16:11:41 [19334] DBG:core:mk_proxy: doing DNS lookup...
Feb 26 16:11:41 [19334] DBG:tm:dlg2hash: 61329
Feb 26 16:11:41 [19334] DBG:tm:print_request_uri: sip:128.61.113.210:5060
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 500000
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [4]: 0xb59b523c (317100000)
Feb 26 16:11:41 [19334] DBG:tm:set_timer: relative timeout is 30
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [0]: 0xb59b5258 (346)
Feb 26 16:11:41 [19334] INFO:rls:resource_subscriptions: Subscription from sip:alice at 128.61.113.210 for resource list uri sip:alice-buddies at 128.61.113.210 expanded to 2 contacts
Feb 26 16:11:41 [19334] DBG:core:comp_scriptvar: int 20 : 1 / 10
Feb 26 16:11:41 [19334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [2]: 0xb59bd2c0 (321)
Feb 26 16:11:41 [19334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Feb 26 16:11:41 [19334] DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 16:11:41 [19334] DBG:core:receive_msg: cleaning up
Feb 26 16:11:41 [19334] DBG:core:parse_msg: SIP Reply (status):
Feb 26 16:11:41 [19334] DBG:core:parse_msg: version: <SIP/2.0>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: status: <200>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: reason: <OK>
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_via_param: found param type 234, <received> = <128.61.113.210>; state=6
Feb 26 16:11:41 [19334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4.b7fdfd81.0>; state=16
Feb 26 16:11:41 [19334] DBG:core:parse_via: end of header reached, state=5
Feb 26 16:11:41 [19334] DBG:core:parse_headers: via found, flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_headers: this is the first via
Feb 26 16:11:41 [19334] DBG:core:receive_msg: After parse_msg...
Feb 26 16:11:41 [19334] DBG:core:forward_reply: found module tm, passing reply to it
Feb 26 16:11:41 [19334] DBG:tm:t_check: start=0xffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=22
Feb 26 16:11:41 [19334] DBG:core:parse_to_param: tag=EtLEID3iRHnpXSPQXBwo.JW3UjEfawbp
Feb 26 16:11:41 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:41 [19334] DBG:core:parse_to: display={}, ruri={sip:alice at 128.61.113.210}
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: <To> [65]; uri=[sip:alice at 128.61.113.210]
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: to body [<sip:alice at 128.61.113.210>]
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: cseq <CSeq>: <2> <NOTIFY>
Feb 26 16:11:41 [19334] DBG:tm:t_reply_matching: hash 4 label 417324923 branch 0
Feb 26 16:11:41 [19334] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Feb 26 16:11:41 [19334] DBG:tm:t_reply_matching: reply matched (T=0xb59bc060)!
Feb 26 16:11:41 [19334] DBG:tm:t_check: end=0xb59bc060
Feb 26 16:11:41 [19334] DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Feb 26 16:11:41 [19334] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Feb 26 16:11:41 [19334] DBG:tm:local_reply: branch=0, save=0, winner=0
Feb 26 16:11:41 [19334] DBG:tm:local_reply: local transaction completed
Feb 26 16:11:41 [19334] DBG:tm:run_trans_callbacks: trans=0xb59bc060, callback type 256, id 0 entered
Feb 26 16:11:41 [19334] DBG:rls:rls_notify_callback: completed with status 200 [to_tag:10.19334.1235682406.1]
Feb 26 16:11:41 [19334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 26 16:11:41 [19334] DBG:tm:insert_timer_unsafe: [2]: 0xb59bc0a8 (321)
Feb 26 16:11:41 [19334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Feb 26 16:11:41 [19334] DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 16:11:41 [19334] DBG:core:receive_msg: cleaning up
Feb 26 16:11:41 [19334] DBG:core:parse_msg: SIP Request:
Feb 26 16:11:41 [19334] DBG:core:parse_msg: method: <SUBSCRIBE>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: uri: <sip:128.61.113.210:5060>
Feb 26 16:11:41 [19334] DBG:core:parse_msg: version: <SIP/2.0>
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK89fe.e02b3f13.0>; state=16
Feb 26 16:11:41 [19334] DBG:core:parse_via: end of header reached, state=5
Feb 26 16:11:41 [19334] DBG:core:parse_headers: via found, flags=2
Feb 26 16:11:41 [19334] DBG:core:parse_headers: this is the first via
Feb 26 16:11:41 [19334] DBG:core:receive_msg: After parse_msg...
Feb 26 16:11:41 [19334] DBG:core:receive_msg: preparing to run routing scripts...
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=100
Feb 26 16:11:41 [19334] DBG:core:parse_to_param: tag=10.19334.1235682406.2
Feb 26 16:11:41 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:41 [19334] DBG:core:parse_to: display={}, ruri={sip:bbc at 128.61.113.210}
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: <To> [50]; uri=[sip:bbc at 128.61.113.210]
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: to body [sip:bbc at 128.61.113.210]
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: cseq <CSeq>: <11> <SUBSCRIBE>
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: content_length=0
Feb 26 16:11:41 [19334] DBG:maxfwd:is_maxfwd_present: value = 70
Feb 26 16:11:41 [19334] DBG:uri:has_totag: totag found
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=200
Feb 26 16:11:41 [19334] DBG:core:get_hdr_field: found end of header
Feb 26 16:11:41 [19334] DBG:rr:find_first_route: No Route headers found
Feb 26 16:11:41 [19334] DBG:rr:loose_route: There is no Route HF
Feb 26 16:11:41 [19334] DBG:core:comp_scriptvar: str 20 : 128.61.113.210
Feb 26 16:11:41 [19334] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=78
Feb 26 16:11:41 [19334] DBG:tm:t_lookup_request: start searching: hash=61336, isACK=0
Feb 26 16:11:41 [19334] DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 26 16:11:41 [19334] DBG:tm:t_lookup_request: no transaction found
Feb 26 16:11:41 [19334] DBG:tm:run_reqin_callbacks: trans=0xb59b6d90, callback type 1, id 0 entered
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:rls:rls_handle_subscribe: no supported header found
Feb 26 16:11:41 [19334] DBG:core:comp_scriptvar: int 20 : 10 / 10
Feb 26 16:11:41 [19334] DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 16:11:41 [19334] DBG:presence:search_event: start event= [presence]
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: 'Expires' header found, value= 310
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: 'To' header ALREADY PARSED: <sip:bbc at 128.61.113.210>
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: 'From' header not parsed
Feb 26 16:11:41 [19334] DBG:core:parse_to_param: tag=3a3fe903b30a1c6fa555ce2f77f8518e-0193
Feb 26 16:11:41 [19334] DBG:core:parse_to: end of header reached, state=29
Feb 26 16:11:41 [19334] DBG:core:parse_to: display={}, ruri={sip:alice at 128.61.113.210}
Feb 26 16:11:41 [19334] DBG:presence:extract_sdialog_info: subs->contact= sip:128.61.113.210:5060 - len = 23
Feb 26 16:11:41 [19334] DBG:presence:get_stored_info: record not found using R-URI search iteratively
Feb 26 16:11:41 [19334] DBG:core:db_new_result: allocate 28 bytes for result set at 0x81961b8
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: 7 columns returned from the query
Feb 26 16:11:41 [19334] DBG:core:db_allocate_columns: allocate 28 bytes for result names at 0x8191e50
Feb 26 16:11:41 [19334] DBG:core:db_allocate_columns: allocate 28 bytes for result types at 0x8196190
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x8191a28
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191a28)[0]=[presentity_uri]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x81967c8
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x81967c8)[1]=[remote_cseq]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[2] at 0x8191a18
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191a18)[2]=[local_cseq]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[3] at 0x8191930
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191930)[3]=[status]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[4] at 0x8191920
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191920)[4]=[reason]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[5] at 0x8191840
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8191840)[5]=[record_route]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[6] at 0x8196710
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8196710)[6]=[version]
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Feb 26 16:11:41 [19334] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Feb 26 16:11:41 [19334] ERROR:presence:get_database_info: No matching subscription dialog found in database
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing 7 columns
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x8191a28
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x81967c8
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[2] at 0x8191a18
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[3] at 0x8191930
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[4] at 0x8191920
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[5] at 0x8191840
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing RES_NAMES[6] at 0x8196710
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing result names at 0x8191e50
Feb 26 16:11:41 [19334] DBG:core:db_free_columns: freeing result types at 0x8196190
Feb 26 16:11:41 [19334] DBG:core:db_free_rows: freeing 0 rows
Feb 26 16:11:41 [19334] DBG:core:db_free_result: freeing result set at 0x81961b8
Feb 26 16:11:41 [19334] ERROR:presence:handle_subscribe: getting stored info
More information about the Users
mailing list