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:102@192.168.254.161}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [33]; uri=[sip:102@192.168.254.161] 
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body ["102" <sip:102@192.168.254.161>
]
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:102@192.168.254.161}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [33]; uri=[sip:102@192.168.254.161] 
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body ["102" <sip:102@192.168.254.161>
]
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:102@192.168.254.161
Jul 15 10:07:46 [4971] DBG:pua:send_publish: pres_uri=sip:102@192.168.254.161
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:102@192.168.254.161   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= 1967120315@192.168.9.67
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:102@192.168.254.161   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= 1967120315@192.168.9.67
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:102@192.168.254.161
 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:ps@192.168.254.161: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:102@192.168.254.161
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:102@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> = <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:102@192.168.254.161}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [25]; uri=[sip:102@192.168.254.161] 
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body [sip:102@192.168.254.161
]
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:102@192.168.254.161}
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:102@192.168.254.161 SIP/2.0
Via: SIP/2.0/UDP 192.168.254.161;branch=z9hG4bK4f9.98452357.0
To: sip:102@192.168.254.161
From: <sip:102@192.168.254.161>;tag=e04d7239189e505c3dcda280020cc873-1853
CSeq: 10 PUBLISH
Call-ID: 5233221f053f5434-4971@192.168.254.161
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:102@192.168.254.161, 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:102@192.168.254.161
        [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:105@192.168.9.55: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:102@192.168.254.161, 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:102@192.168.254.161"><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:102@192.168.254.161" 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:102@192.168.254.161" 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:102@192.168.254.161
        [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:105@192.168.9.55:62746   [record_route]= 
Jul 15 10:07:46 [4971] DBG:presence:search_phtable: pres_uri= sip:102@192.168.254.161, 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:105@192.168.9.55:62746
Jul 15 10:07:46 [4971] DBG:tm:t_uac: next_hop=<sip:105@192.168.9.55: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:105@192.168.9.55: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:105@192.168.254.161 via sip:105@192.168.9.55:62746 on behalf of sip:102@192.168.254.161 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:102@192.168.254.161}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [67]; uri=[sip:102@192.168.254.161] 
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body [sip:102@192.168.254.161]
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:105@192.168.254.161}
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: <To> [40]; uri=[sip:105@192.168.254.161] 
Jul 15 10:07:46 [4971] DBG:core:get_hdr_field: to body [<sip:105@192.168.254.161>]
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