Hi list,
I'm new to OpenSIPS, so don't shoot me when i'm wrong ;-)
I think i found a problem in presence_xml on both 1.6.4-2-notls and
1.7.0-beta-notls.
When a PUBLISH message with "Expires: 0" created by pua_userloc is received,
presence_xml generates the following error:
Jul 15 10:07:46 [4971] DBG:presence_xml:event_agg_nbody: [user]=102 [domain]=
192.168.254.161
Entity: line 2: parser error : Attribute xmlns redefined
idf:cipid" entity="pres:[email protected]" xmlns="urn:ietf:params:xml:ns:pidf"
^
Jul 15 10:07:46 [4971] DBG:presence_xml:agregate_xmls: i = [0] - body: <?xml
version="1.0"?>
<presence xmlns="urn:ietf:params:xml:ns:pidf"
xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model"
xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid"
xmlns:c="urn:ietf:params:xml:ns:pidf:cipid" entity="pres:[email protected]"
xmlns="urn:ietf:params:xml:ns:pidf"><tuple xmlns="urn:ietf:params:xml:ns:pidf"
id="0x7fff92c0d560"><status
xmlns="urn:ietf:params:xml:ns:pidf"><basic>closed</basic></status></tuple></presence>
Jul 15 10:07:46 [4971] ERROR:presence_xml:agregate_xmls: while parsing xml body
message
Jul 15 10:07:46 [4971] ERROR:presence_xml:event_agg_nbody: while aggregating
body
Jul 15 10:07:46 [4971] ERROR:presence:get_p_notify_body: Failed to aggregate
notify body
I also included a attachment with the complete CLI debug output.
Hope someone can give me some advice on this.
Steven.Jul 15 10:07:46 [4971] DBG:core:parse_msg: SIP Request:
Jul 15 10:07:46 [4971] DBG:core:parse_msg: method: <REGISTER>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: uri: <sip:192.168.254.161>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: version: <SIP/2.0>
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK1646419361>; state=16
Jul 15 10:07:46 [4971] DBG:core:parse_via: end of header reached, state=5
Jul 15 10:07:46 [4971] DBG:core:parse_headers: via found, flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: this is the first via
Jul 15 10:07:46 [4971] DBG:core:receive_msg: After parse_msg...
Jul 15 10:07:46 [4971] DBG:core:receive_msg: preparing to run routing scripts...
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=100
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=10
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={"102"},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [33];
uri=[sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body ["102"
<sip:[email protected]>
]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: cseq <CSeq>: <7> <REGISTER>
Jul 15 10:07:46 [4971] DBG:maxfwd:is_maxfwd_present: value = 70
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=200
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: content_length=0
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: found end of header
Jul 15 10:07:46 [4971] DBG:rr:find_first_route: No Route headers found
Jul 15 10:07:46 [4971] DBG:rr:loose_route: There is no Route HF
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if host==us: 15==15 &&
[192.168.254.161] == [192.168.254.161]
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if port 5060 matches
port 5060
Jul 15 10:07:46 [4971] DBG:pua_usrloc:pua_set_publish: set send publish
Jul 15 10:07:46 [4971] DBG:auth:check_nonce: comparing
[4e1ff5610000000f2cd8561bddb5899a285a733ab6fd04fb] and
[4e1ff5610000000f2cd8561bddb5899a285a733ab6fd04fb]
Jul 15 10:07:46 [4971] DBG:db_mysql:has_stmt_ctx: ctx found for subscriber
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7cc870
(tail=8175528) MC=0x7cc288
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: set values for
the statement run
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_val2bind: added val (0): len=3;
type=254; is_null=0
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_val2bind: added val (1): len=15;
type=254; is_null=0
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: prepared
statement has 2 columns in result
Jul 15 10:07:46 [4971] DBG:core:db_new_result: allocate 48 bytes for result set
at 0x7d2658
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: 2 columns returned
from the query
Jul 15 10:07:46 [4971] DBG:core:db_allocate_columns: allocate 56 bytes for
result columns at 0x7d0de8
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d0df8)[0]=[password]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d0e08)[1]=[rpid]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Jul 15 10:07:46 [4971] DBG:core:db_allocate_rows: allocate 80 bytes for result
rows and values at 0x7d2820
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting STRING [123]
Jul 15 10:07:46 [4971] DBG:auth_db:get_ha1: HA1 string calculated:
599d33e6293d081f9e922876657430ad
Jul 15 10:07:46 [4971] DBG:auth:check_response: our result =
'1bbc33748b3dd95f3ec16dc379c35066'
Jul 15 10:07:46 [4971] DBG:auth:check_response: authorization is OK
Jul 15 10:07:46 [4971] DBG:auth:post_auth: nonce index= 15
Jul 15 10:07:46 [4971] DBG:auth:is_nonce_index_valid: nonce already used
Jul 15 10:07:46 [4971] DBG:auth:post_auth: nonce index not valid
Jul 15 10:07:46 [4971] DBG:core:db_free_columns: freeing result columns at
0x7d0de8
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing 1 rows
Jul 15 10:07:46 [4971] DBG:core:db_free_row: freeing row values at 0x7d2830
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing rows at 0x7d2820
Jul 15 10:07:46 [4971] DBG:core:db_free_result: freeing result set at 0x7d2658
Jul 15 10:07:46 [4971] DBG:auth:reserve_nonce_index: second= 25, sec_monit= 13,
index= 16
Jul 15 10:07:46 [4971] DBG:auth:build_auth_hf: nonce index= 16
Jul 15 10:07:46 [4971] DBG:auth:build_auth_hf: 'WWW-Authenticate: Digest
realm="192.168.254.161",
nonce="4e1ff57000000010cfac5ad6d7b49b3929793f193188d557", stale=true
'
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:check_ip_address: params 192.168.9.67,
192.168.9.67, 0
Jul 15 10:07:46 [4971] DBG:core:destroy_avp_list: destroying list (nil)
Jul 15 10:07:46 [4971] DBG:core:receive_msg: cleaning up
Jul 15 10:07:46 [4971] DBG:core:parse_msg: SIP Request:
Jul 15 10:07:46 [4971] DBG:core:parse_msg: method: <REGISTER>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: uri: <sip:192.168.254.161>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: version: <SIP/2.0>
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK1509097743>; state=16
Jul 15 10:07:46 [4971] DBG:core:parse_via: end of header reached, state=5
Jul 15 10:07:46 [4971] DBG:core:parse_headers: via found, flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: this is the first via
Jul 15 10:07:46 [4971] DBG:core:receive_msg: After parse_msg...
Jul 15 10:07:46 [4971] DBG:core:receive_msg: preparing to run routing scripts...
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=100
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=10
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={"102"},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [33];
uri=[sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body ["102"
<sip:[email protected]>
]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: cseq <CSeq>: <8> <REGISTER>
Jul 15 10:07:46 [4971] DBG:maxfwd:is_maxfwd_present: value = 70
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=200
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: content_length=0
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: found end of header
Jul 15 10:07:46 [4971] DBG:rr:find_first_route: No Route headers found
Jul 15 10:07:46 [4971] DBG:rr:loose_route: There is no Route HF
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if host==us: 15==15 &&
[192.168.254.161] == [192.168.254.161]
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if port 5060 matches
port 5060
Jul 15 10:07:46 [4971] DBG:pua_usrloc:pua_set_publish: set send publish
Jul 15 10:07:46 [4971] DBG:auth:check_nonce: comparing
[4e1ff57000000010cfac5ad6d7b49b3929793f193188d557] and
[4e1ff57000000010cfac5ad6d7b49b3929793f193188d557]
Jul 15 10:07:46 [4971] DBG:db_mysql:has_stmt_ctx: ctx found for subscriber
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7cc870
(tail=8175528) MC=0x7cc288
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: set values for
the statement run
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_val2bind: added val (0): len=3;
type=254; is_null=0
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_val2bind: added val (1): len=15;
type=254; is_null=0
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: doing
BIND_PARAM in...
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_do_prepared_query: prepared
statement has 2 columns in result
Jul 15 10:07:46 [4971] DBG:core:db_new_result: allocate 48 bytes for result set
at 0x7d2658
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: 2 columns returned
from the query
Jul 15 10:07:46 [4971] DBG:core:db_allocate_columns: allocate 56 bytes for
result columns at 0x7d0de8
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d0df8)[0]=[password]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d0e08)[1]=[rpid]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Jul 15 10:07:46 [4971] DBG:core:db_allocate_rows: allocate 80 bytes for result
rows and values at 0x7d2820
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting STRING [123]
Jul 15 10:07:46 [4971] DBG:auth_db:get_ha1: HA1 string calculated:
599d33e6293d081f9e922876657430ad
Jul 15 10:07:46 [4971] DBG:auth:check_response: our result =
'43a0e2adaff27ad3b43a3551c2762d78'
Jul 15 10:07:46 [4971] DBG:auth:check_response: authorization is OK
Jul 15 10:07:46 [4971] DBG:auth:post_auth: nonce index= 16
Jul 15 10:07:46 [4971] DBG:core:db_free_columns: freeing result columns at
0x7d0de8
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing 1 rows
Jul 15 10:07:46 [4971] DBG:core:db_free_row: freeing row values at 0x7d2830
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing rows at 0x7d2820
Jul 15 10:07:46 [4971] DBG:core:db_free_result: freeing result set at 0x7d2658
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=8000000
Jul 15 10:07:46 [4971] DBG:usrloc:run_ul_callbacks: contact=0x7f7c30f0cff0,
callback type 4/4, id 3 entered
Jul 15 10:07:46 [4971] DBG:pua_usrloc:ul_publish:
ul_publish: DELETE type
Jul 15 10:07:46 [4971] DBG:pua_usrloc:ul_publish: aor = 102
Jul 15 10:07:46 [4971] DBG:pua_usrloc:ul_publish: uri= sip:[email protected]
Jul 15 10:07:46 [4971] DBG:pua:send_publish: pres_uri=sip:[email protected]
Jul 15 10:07:46 [4971] DBG:pua:send_publish: Try to get hash lock [85]
Jul 15 10:07:46 [4971] DBG:pua:send_publish: Got hash lock 85
Jul 15 10:07:46 [4971] DBG:pua:search_htable: core_hash= 85
Jul 15 10:07:46 [4971] DBG:pua:search_htable: Searched:
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: pres_uri=
sip:[email protected] len= 23
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: etag= - len= 0
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: id= [email protected]
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: flag= 1
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: event= 1
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: expires= 0
Jul 15 10:07:46 [4971] DBG:pua:search_htable:
Jul 15 10:07:46 [4971] DBG:pua:search_htable: Found
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: pres_uri=
sip:[email protected] len= 23
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: etag= a.1310716806.4971.71.2 -
len= 22
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: id= [email protected]
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: flag= 1
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: event= 1
Jul 15 10:07:46 [4971] DBG:pua:print_ua_pres: expires= 46
Jul 15 10:07:46 [4971] DBG:pua:search_htable:
Jul 15 10:07:46 [4971] DBG:pua:search_htable: no etag restriction
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: start
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: presentity exists
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: expires= 0- delete from hash
table
Jul 15 10:07:46 [4971] DBG:pua:publ_build_hdr: UPDATE_TYPE [etag]=
a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: publ->pres_uri:
sip:[email protected]
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: str_hdr:
Max-Forwards: 70
Event: presence
Expires: 0
SIP-If-Match: a.1310716806.4971.71.2
85
Jul 15 10:07:46 [4971] DBG:pua:send_publish_int: cback param = 597
Jul 15 10:07:46 [4971] DBG:tm:t_uac: next_hop=<sip:[email protected]:5060>
Jul 15 10:07:46 [4971] DBG:core:mk_proxy: doing DNS lookup...
Jul 15 10:07:46 [4971] DBG:tm:dlg2hash: 2548
Jul 15 10:07:46 [4971] DBG:tm:print_request_uri: sip:[email protected]
Jul 15 10:07:46 [4971] DBG:tm:set_timer: relative timeout is 500000
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [4]: 0x7f7c30f1ba30
(460000000)
Jul 15 10:07:46 [4971] DBG:tm:set_timer: relative timeout is 30
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [0]: 0x7f7c30f1ba60 (489)
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:check_ip_address: params 192.168.9.67,
192.168.9.67, 0
Jul 15 10:07:46 [4971] DBG:core:destroy_avp_list: destroying list (nil)
Jul 15 10:07:46 [4971] DBG:core:receive_msg: cleaning up
Jul 15 10:07:46 [4971] DBG:core:parse_msg: SIP Request:
Jul 15 10:07:46 [4971] DBG:core:parse_msg: method: <PUBLISH>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: uri: <sip:[email protected]>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: version: <SIP/2.0>
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK4f9.98452357.0>; state=16
Jul 15 10:07:46 [4971] DBG:core:parse_via: end of header reached, state=5
Jul 15 10:07:46 [4971] DBG:core:parse_headers: via found, flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: this is the first via
Jul 15 10:07:46 [4971] DBG:core:receive_msg: After parse_msg...
Jul 15 10:07:46 [4971] DBG:core:receive_msg: preparing to run routing scripts...
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=100
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=9
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [25];
uri=[sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body [sip:[email protected]
]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: content_length=0
Jul 15 10:07:46 [4971] DBG:maxfwd:is_maxfwd_present: value = 70
Jul 15 10:07:46 [4971] DBG:core:parse_to_param:
tag=e04d7239189e505c3dcda280020cc873-1853
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=29
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=200
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: found end of header
Jul 15 10:07:46 [4971] DBG:rr:find_first_route: No Route headers found
Jul 15 10:07:46 [4971] DBG:rr:loose_route: There is no Route HF
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if host==us: 15==15 &&
[192.168.254.161] == [192.168.254.161]
Jul 15 10:07:46 [4971] DBG:core:grep_sock_info: checking if port 5060 matches
port 5060
Jul 15 10:07:46 [4971] DBG:tm:t_newtran: transaction on
entrance=0xffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=78
Jul 15 10:07:46 [4971] DBG:tm:t_lookup_request: start searching: hash=2548,
isACK=0
Jul 15 10:07:46 [4971] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jul 15 10:07:46 [4971] DBG:tm:t_lookup_request: no transaction found
Jul 15 10:07:46 [4971] DBG:tm:run_reqin_callbacks: trans=0x7f7c30f3d6a8,
callback type 1, id 0 entered
==================> HANDLE_PUBLISH
PUBLISH sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.254.161;branch=z9hG4bK4f9.98452357.0
To: sip:[email protected]
From: <sip:[email protected]>;tag=e04d7239189e505c3dcda280020cc873-1853
CSeq: 10 PUBLISH
Call-ID: [email protected]
Content-Length: 0
User-Agent: OpenSIPS (1.7.0-beta-notls (x86_64/linux))
Max-Forwards: 69
Event: presence
Expires: 0
SIP-If-Match: a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:presence:search_event: start event= [presence]
Jul 15 10:07:46 [4971] DBG:presence:handle_publish: Expires header found,
value= 0
Jul 15 10:07:46 [4971] DBG:presence:handle_publish: SIP-If-Match header found
Jul 15 10:07:46 [4971] DBG:presence:handle_publish: existing etag=
a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:presence:search_phtable_etag: pres_uri=
sip:[email protected], event=1, etag= a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:presence:search_phtable_etag: found etag =
a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:presence:delete_phtable: Count = 0, delete
Jul 15 10:07:46 [4971] DBG:presence:publ_send200ok: send 200OK reply, etag=
a.1310716806.4971.71.2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=ffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:check_ip_address: params 192.168.254.161,
192.168.254.161, 0
Jul 15 10:07:46 [4971] DBG:core:_shm_resize: resize(0) called
Jul 15 10:07:46 [4971] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [2]: 0x7f7c30f3d728 (464)
Jul 15 10:07:46 [4971] DBG:tm:_reply_light: reply sent out. buf=0x7d4dc0:
SIP/2.0 2..., shmem=0x7f7c30f1b3d0: SIP/2.0 2
Jul 15 10:07:46 [4971] DBG:tm:_reply_light: finished
Jul 15 10:07:46 [4971] DBG:presence:printf_subs:
[pres_uri]= sip:[email protected]
[to_user]= 102 [to_domain]= 192.168.254.161
[w_user]= 105 [w_domain]= 192.168.254.161
[event]= presence
[status]= active
[expires]= 1310719038
[callid]= YzBjMDkzYzhhZDhkOWYwY2E0OGZlOWVkNTdiYTZmODA. [local_cseq]=1
[to_tag]= 74d73c09b98fd87dc41009c44e814e47-46f4 [from_tag]= 4b273239
[contact]= sip:[email protected]:62746 [record_route]=
Jul 15 10:07:46 [4971] DBG:presence:get_subs_dialog: found 1 dialogs
Jul 15 10:07:46 [4971] DBG:presence:search_phtable: pres_uri=
sip:[email protected], event=1
Jul 15 10:07:46 [4971] DBG:presence:pres_search_db: qval [0] = 192.168.254.161
Jul 15 10:07:46 [4971] DBG:presence:pres_search_db: qval [1] = 102
Jul 15 10:07:46 [4971] DBG:presence:pres_search_db: qval [2] = presence
Jul 15 10:07:46 [4971] DBG:core:db_new_result: allocate 48 bytes for result set
at 0x7d1510
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: 4 columns returned
from the query
Jul 15 10:07:46 [4971] DBG:core:db_allocate_columns: allocate 112 bytes for
result columns at 0x7d2820
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d2840)[0]=[body]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result
type
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d2850)[1]=[extra_hdrs]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result
type
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d2860)[2]=[expires]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x7d2870)[3]=[etag]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result
type
Jul 15 10:07:46 [4971] DBG:core:db_allocate_rows: allocate 144 bytes for result
rows and values at 0x7d3c20
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting BLOB [<?xml
version="1.0"?>
<presence xmlns="urn:ietf:params:xml:ns:pidf"
xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model"
xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid"
xmlns:c="urn:ietf:params:xml:ns:pidf:cipid"
entity="pres:[email protected]"><tuple
id="0x7fff92c0d560"><status><basic>open</basic></status></tuple></presence>
]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting BLOB []
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting INT
[1310717312]
Jul 15 10:07:46 [4971] DBG:db_mysql:db_mysql_str2val: converting STRING
[a.1310716806.4971.71.2]
Jul 15 10:07:46 [4971] DBG:presence:get_p_notify_body: searched etag =
a.1310716806.4971.71.2 len= 22
Jul 15 10:07:46 [4971] DBG:presence:get_p_notify_body: etag not NULL
Jul 15 10:07:46 [4971] DBG:presence:get_p_notify_body: etag =
a.1310716806.4971.71.2 len= 22
Jul 15 10:07:46 [4971] DBG:presence:get_p_notify_body: found etag
Jul 15 10:07:46 [4971] DBG:core:db_free_columns: freeing result columns at
0x7d2820
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing 1 rows
Jul 15 10:07:46 [4971] DBG:core:db_free_row: freeing row values at 0x7d3c30
Jul 15 10:07:46 [4971] DBG:core:db_free_rows: freeing rows at 0x7d3c20
Jul 15 10:07:46 [4971] DBG:core:db_free_result: freeing result set at 0x7d1510
Jul 15 10:07:46 [4971] DBG:presence_xml:event_agg_nbody: [user]=102 [domain]=
192.168.254.161
Entity: line 2: parser error : Attribute xmlns redefined
idf:cipid" entity="pres:[email protected]" xmlns="urn:ietf:params:xml:ns:pidf"
^
Jul 15 10:07:46 [4971] DBG:presence_xml:agregate_xmls: i = [0] - body: <?xml
version="1.0"?>
<presence xmlns="urn:ietf:params:xml:ns:pidf"
xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model"
xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid"
xmlns:c="urn:ietf:params:xml:ns:pidf:cipid" entity="pres:[email protected]"
xmlns="urn:ietf:params:xml:ns:pidf"><tuple xmlns="urn:ietf:params:xml:ns:pidf"
id="0x7fff92c0d560"><status
xmlns="urn:ietf:params:xml:ns:pidf"><basic>closed</basic></status></tuple></presence>
Jul 15 10:07:46 [4971] ERROR:presence_xml:agregate_xmls: while parsing xml body
message
Jul 15 10:07:46 [4971] ERROR:presence_xml:event_agg_nbody: while aggregating
body
Jul 15 10:07:46 [4971] ERROR:presence:get_p_notify_body: Failed to aggregate
notify body
Jul 15 10:07:46 [4971] INFO:presence:publ_notify: notify
Jul 15 10:07:46 [4971] DBG:presence:send_notify_request: enter: have_body=0
force_null=0 dialog info:
Jul 15 10:07:46 [4971] DBG:presence:printf_subs:
[pres_uri]= sip:[email protected]
[to_user]= 102 [to_domain]= 192.168.254.161
[w_user]= 105 [w_domain]= 192.168.254.161
[event]= presence
[status]= active
[expires]= 1772
[callid]= YzBjMDkzYzhhZDhkOWYwY2E0OGZlOWVkNTdiYTZmODA. [local_cseq]=1
[to_tag]= 74d73c09b98fd87dc41009c44e814e47-46f4 [from_tag]= 4b273239
[contact]= sip:[email protected]:62746 [record_route]=
Jul 15 10:07:46 [4971] DBG:presence:search_phtable: pres_uri=
sip:[email protected], event=1
Jul 15 10:07:46 [4971] DBG:presence:get_p_notify_body: No record exists in
hash_table
Jul 15 10:07:46 [4971] DBG:presence:send_notify_request: Could not get the
notify_body
Jul 15 10:07:46 [4971] DBG:presence:send_notify_request: headers:
Max-Forwards: 70
Event: presence
Contact: <sip:192.168.254.161:5060>
Subscription-State: active;expires=1772
Jul 15 10:07:46 [4971] DBG:presence:build_dlg_t: CONTACT =
sip:[email protected]:62746
Jul 15 10:07:46 [4971] DBG:tm:t_uac: next_hop=<sip:[email protected]:62746>
Jul 15 10:07:46 [4971] DBG:core:mk_proxy: doing DNS lookup...
Jul 15 10:07:46 [4971] DBG:tm:dlg2hash: 61349
Jul 15 10:07:46 [4971] DBG:tm:print_request_uri: sip:[email protected]:62746
Jul 15 10:07:46 [4971] DBG:tm:set_timer: relative timeout is 500000
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [4]: 0x7f7c30f26320
(460000000)
Jul 15 10:07:46 [4971] DBG:tm:set_timer: relative timeout is 30
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [0]: 0x7f7c30f26350 (489)
Jul 15 10:07:46 [4971] INFO:presence:send_notify_request: NOTIFY
sip:[email protected] via sip:[email protected]:62746 on behalf of
sip:[email protected] for event presence,
to_tag=74d73c09b98fd87dc41009c44e814e47-46f4, cseq=2
Jul 15 10:07:46 [4971] DBG:presence:update_presentity: Expires=0, deleted from
db 102
Jul 15 10:07:46 [4971] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f7c30f3d6a8] after is 0
Jul 15 10:07:46 [4971] DBG:core:destroy_avp_list: destroying list (nil)
Jul 15 10:07:46 [4971] DBG:core:receive_msg: cleaning up
Jul 15 10:07:46 [4971] DBG:core:parse_msg: SIP Reply (status):
Jul 15 10:07:46 [4971] DBG:core:parse_msg: version: <SIP/2.0>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: status: <200>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: reason: <OK>
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK4f9.98452357.0>; state=16
Jul 15 10:07:46 [4971] DBG:core:parse_via: end of header reached, state=5
Jul 15 10:07:46 [4971] DBG:core:parse_headers: via found, flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: this is the first via
Jul 15 10:07:46 [4971] DBG:core:receive_msg: After parse_msg...
Jul 15 10:07:46 [4971] DBG:core:forward_reply: found module tm, passing reply
to it
Jul 15 10:07:46 [4971] DBG:tm:t_check: start=0xffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=22
Jul 15 10:07:46 [4971] DBG:core:parse_to_param:
tag=74d73c09b98fd87dc41009c44e814e47-92f0
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=29
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [67];
uri=[sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body [sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: hash 2548 label 1966232713
branch 0
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f7c30f1b810]
after is 1
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: reply matched
(T=0x7f7c30f1b810)!
Jul 15 10:07:46 [4971] DBG:tm:t_check: end=0x7f7c30f1b810
Jul 15 10:07:46 [4971] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Jul 15 10:07:46 [4971] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jul 15 10:07:46 [4971] DBG:tm:local_reply: branch=0, save=0, winner=0
Jul 15 10:07:46 [4971] DBG:tm:local_reply: local transaction completed
Jul 15 10:07:46 [4971] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [2]: 0x7f7c30f1b890 (464)
Jul 15 10:07:46 [4971] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f7c30f1b810] after is 0
Jul 15 10:07:46 [4971] DBG:core:destroy_avp_list: destroying list (nil)
Jul 15 10:07:46 [4971] DBG:core:receive_msg: cleaning up
Jul 15 10:07:46 [4971] DBG:core:parse_msg: SIP Reply (status):
Jul 15 10:07:46 [4971] DBG:core:parse_msg: version: <SIP/2.0>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: status: <200>
Jul 15 10:07:46 [4971] DBG:core:parse_msg: reason: <OK>
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_via_param: found param type 232, <branch>
= <z9hG4bK5afe.4d130dd4.0>; state=16
Jul 15 10:07:46 [4971] DBG:core:parse_via: end of header reached, state=5
Jul 15 10:07:46 [4971] DBG:core:parse_headers: via found, flags=2
Jul 15 10:07:46 [4971] DBG:core:parse_headers: this is the first via
Jul 15 10:07:46 [4971] DBG:core:receive_msg: After parse_msg...
Jul 15 10:07:46 [4971] DBG:core:forward_reply: found module tm, passing reply
to it
Jul 15 10:07:46 [4971] DBG:tm:t_check: start=0xffffffffffffffff
Jul 15 10:07:46 [4971] DBG:core:parse_headers: flags=22
Jul 15 10:07:46 [4971] DBG:core:parse_to_param: tag=4b273239
Jul 15 10:07:46 [4971] DBG:core:parse_to: end of header reached, state=29
Jul 15 10:07:46 [4971] DBG:core:parse_to: display={},
ruri={sip:[email protected]}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [40];
uri=[sip:[email protected]]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body
[<sip:[email protected]>]
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: cseq <CSeq>: <2> <NOTIFY>
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: hash 61349 label 1305489876
branch 0
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: REF_UNSAFE:[0x7f7c30f26100]
after is 1
Jul 15 10:07:46 [4971] DBG:tm:t_reply_matching: reply matched
(T=0x7f7c30f26100)!
Jul 15 10:07:46 [4971] DBG:tm:t_check: end=0x7f7c30f26100
Jul 15 10:07:46 [4971] DBG:tm:reply_received: org. status uas=0, uac[0]=0
local=2 is_invite=0)
Jul 15 10:07:46 [4971] DBG:tm:t_should_relay_response: T_code=0, new_code=200
Jul 15 10:07:46 [4971] DBG:tm:local_reply: branch=0, save=0, winner=0
Jul 15 10:07:46 [4971] DBG:tm:local_reply: local transaction completed
Jul 15 10:07:46 [4971] DBG:tm:run_trans_callbacks: trans=0x7f7c30f26100,
callback type 256, id 0 entered
Jul 15 10:07:46 [4971] DBG:presence:p_tm_callback: completed with status [200]
and to_tag [74d73c09b98fd87dc41009c44e814e47-46f4]
Jul 15 10:07:46 [4971] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jul 15 10:07:46 [4971] DBG:tm:insert_timer_unsafe: [2]: 0x7f7c30f26180 (464)
Jul 15 10:07:46 [4971] DBG:tm:t_unref: UNREF_UNSAFE: [0x7f7c30f26100] after is 0
Jul 15 10:07:46 [4971] DBG:core:destroy_avp_list: destroying list (nil)
Jul 15 10:07:46 [4971] DBG:core:receive_msg: cleaning up_______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
