[Kamailio-Devel] 200 ok to pua does not work

[Juha Heinanen]

Klaus Darilion writes:

 > This is probably the same problem as I and Aurelien have reported. With 
 > debug=4 you should see in the logs that the process which sends the 
 > PUBLISH does "clean up" after the process which receives the PUBLISH and 
 > does 200 OK.

i tried many times and finally was able to reproduce the publish/200 ok 
problem when debug level was 4.  it was easier to reproduce with debug
level 3, so looks like a timing related thing.

below is what i got to syslog from the point when kamailio received
publish request via pua mi interface.

-- juha

Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:mi_xmlrpc:default_method: starting up.....
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:mi_xmlrpc:default_method: done looking the mi command.
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:mi_xmlrpc:default_method: done parsing the mi tree.
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: start
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: pres_uri 'sip:jh at vm.test.fi'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: expires '7776000'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: event 'message-summary'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: content type 'application/simple-message-summary'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: etag 'a.1229177868.2987.1.48'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: extra_headers 'P-Flags: 0#015#012'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: body 'Messages-Waiting: yes#015#012Voice-Message: 1/0 (0/0)#015#012'
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua_mi:mi_pua_publish: send publish
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:send_publish: pres_uri=sip:jh at vm.test.fi
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:search_htable: core_hash= 432
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:search_htable: found record
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:send_publish: etag:a.1229177868.2987.1.48
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:publ_build_hdr: UPDATE_TYPE [etag]= a.1229177868.2987.1.48
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:send_publish: publ->pres_uri:#012sip:jh at vm.test.fi#012 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:send_publish: str_hdr:#012Max-Forwards: 70#015#012Event: message-summary#015#012Expires: 7776001#015#012SIP-If-Match: a.1229177868.2987.1.48#015#012Content-Type: application/simple-message-summary#015#012P-Flags: 0#015#012 160#012 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:pua:send_publish: body:#012Messages-Waiting: yes#015#012Voice-Message: 1/0 (0/0)#015#012#012 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:t_uac: next_hop=<sip:127.0.0.1:5070>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:core:mk_proxy: doing DNS lookup...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:dlg2hash: 37495
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:print_request_uri: sip:jh at vm.test.fi
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_msg: SIP Request:
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_msg:  method:  <PUBLISH>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_msg:  uri:     <sip:jh at vm.test.fi>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7729.3b5a6cb1.0>; state=16
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:receive_msg: preparing to run routing scripts...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:check_via_address: params 192.98.101.10, 192.98.101.10, 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=100
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_to: end of header reached, state=9
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:get_hdr_field: <To> [19]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:get_hdr_field: to body [sip:jh at vm.test.fi#015#012]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:get_hdr_field: content_length=49
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:maxfwd:is_maxfwd_present: value = 70 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:uri:has_totag: no totag
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=78
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_lookup_request: start searching: hash=37495, isACK=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_lookup_request: no transaction found
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=200
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:get_hdr_field: found end of header
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:rr:find_first_route: No Route headers found
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:rr:loose_route: There is no Route HF
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_to_param: tag=b8e254941bdaebf23ba8b40adabb61f3-7bf8
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_to: end of header reached, state=29
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: INFO: PUBLISH <sip:jh at vm.test.fi> by <sip:jh at vm.test.fi> is from Local Proxy
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 10==13 &&  [vm.test.fi] == [192.98.101.10]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 10==9 &&  [vm.test.fi] == [127.0.0.1]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5070 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 10==9 &&  [vm.test.fi] == [127.0.0.1]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 10==13 &&  [vm.test.fi] == [192.98.101.10]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 10==13 &&  [vm.test.fi] == [192.98.101.10]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:check_self: host != me
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:comp_scriptvar: int 29 : 7 / -1
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:subst_run: running. r=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:subst_run: matched (6, 4): [@vm.]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:textops:subst_uri_f: textops match - old uri= [sip:jh at vm.test.fi], new uri= [sip:jh at test.fi]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:comp_scriptvar: int 20 : 7 / 7
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:subst_run: running. r=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:subst_run: matched (6, 1): [@]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:textops:subst_uri_f: textops match - old uri= [sip:jh at test.fi], new uri= [sip:jh at vm.test.fi]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_newtran: transaction on entrance=(nil)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=78
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_lookup_request: start searching: hash=37495, isACK=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_lookup_request: no transaction found
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:run_reqin_callbacks: trans=0xb587c2d8, callback type 1, id 0 entered
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: INFO: Handling PUBLISH to <sip:jh at vm.test.fi>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:search_event: start event= [message-summary]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:handle_publish: SIP-If-Match header found
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:handle_publish: existing etag  = a.1229177868.2987.1.48 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:handle_publish: Expires header found, value= 7776001
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_new_result: allocate 28 bytes for result set at 0x82271e8
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x8227210
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_allocate_columns: allocate 8 bytes for result types at 0x8227230
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[0] at 0x8227110
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8227110)[0]=[body]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: use DB_BLOB result type
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: allocate 8 bytes for RES_NAMES[1] at 0x8227090
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x8227090)[1]=[sender]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_convert_rows: allocate 8 bytes for rows at 0x8227220
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_convert_row: allocate 40 bytes for row values at 0x8227240
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_str2val: converting BLOB [Messages-Waiting: no#015#012Voice-Message: 0/0 (0/0)#015#012]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:db_mysql:db_mysql_str2val: converting STRING []
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_columns: freeing 2 columns
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x8227110
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_columns: freeing RES_NAMES[1] at 0x8227090
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_columns: freeing result names at 0x8227210
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_columns: freeing result types at 0x8227230
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_rows: freeing 1 rows
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_row: freeing row values at 0x8227240
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_rows: freeing rows at 0x8227220
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:db_free_result: freeing result set at 0x82271e8
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:generate_ETag: etag= a.1229177868.2985.3.49 / 22#012 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:publ_send200ok: send 200OK reply
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:publ_send200ok: etag= a.1229177868.2985.3.49 - len= 22
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:check_via_address: params 192.98.101.10, 192.98.101.10, 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_msg: SIP Reply  (status):
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:printf_subs: #012#011[pres_uri]= sip:jh at vm.test.fi#012#011[to_user]= jh#011[to_domain]= test.fi#012#011[w_user]= jh#011[w_domain]= test.fi#012#011[event]= message-summary#012#011[status]= active#012#011[expires]= 1229181486#012#011[callid]= tnlskzajbiadicl at localhost#011[local_cseq]=8#012#011[to_tag]= 25.2976.1229177886.1#011[from_tag]= ddtbc#012#011[contact]= sip:jh at 192.98.101.10:5036#011[record_route]= 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_msg:  status:  <200>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:get_subs_dialog: s->db_flag= INSERTDB_FLAG
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_msg:  reason:  <OK>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:get_subs_dialog: found 1 dialogs( 0 in database and 1 in hash_table)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:send_notify_request: dialog info:
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_headers: flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:printf_subs: #012#011[pres_uri]= sip:jh at vm.test.fi#012#011[to_user]= jh#011[to_domain]= test.fi#012#011[w_user]= jh#011[w_domain]= test.fi#012#011[event]= message-summary#012#011[status]= active#012#011[expires]= 3037#012#011[callid]= tnlskzajbiadicl at localhost#011[local_cseq]=8#012#011[to_tag]= 25.2976.1229177886.1#011[from_tag]= ddtbc#012#011[contact]= sip:jh at 192.98.101.10:5036#011[record_route]= 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7729.3b5a6cb1.0>; state=16
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:build_str_hdr: expires = 3037
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:send_notify_request: headers:#012Max-Forwards: 70#015#012Event: message-summary#015#012Contact: <sip:192.98.101.10:5060>#015#012Subscription-State: active;expires=3037#015#012Content-Type: application/simple-message-summary#015#012
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:presence:build_dlg_t: CONTACT = sip:jh at 192.98.101.10:5036
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [192.98.101.10] == [192.98.101.10]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:forward_reply: found module tm, passing reply to it
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_check: start=0xffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_uac: next_hop=<sip:jh at 192.98.101.10:5036>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:mk_proxy: doing DNS lookup...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_headers: flags=22
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:dlg2hash: 45510
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_to_param: tag=f4da76a2b06776614336233acf69fc96.2a90
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_to: end of header reached, state=29
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:print_request_uri: sip:jh at 192.98.101.10:5036
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:set_timer: relative timeout is 500000
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:insert_timer_unsafe: [4]: 0xb587fd2c (580100000)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:set_timer: relative timeout is 5
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:get_hdr_field: to body [sip:jh at vm.test.fi]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:insert_timer_unsafe: [0]: 0xb587fd48 (584)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_reply_matching: hash 37495 label 466003379 branch 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: INFO:presence:send_notify_request: NOTIFY sip:jh at test.fi via sip:jh at 192.98.101.10:5036 on behalf of sip:jh at test.fi for event message-summary
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:insert_timer_unsafe: [2]: 0xb587c320 (584)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_reply_matching: reply matched (T=0xb5880c18)!
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_check: end=0xb5880c18
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2985]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:local_reply: branch=0, save=0, winner=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:local_reply: local transaction completed
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:run_trans_callbacks: trans=0xb5880c18, callback type 256, id 0 entered
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:parse_headers: flags=ffffffffffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:get_hdr_field: content_length=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:get_hdr_field: found end of header
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:publ_cback_func: lexpire= 7776001
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:publ_cback_func: completed with status 200 [contact:sip:jh at vm.test.fi]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:search_htable: core_hash= 432
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:search_htable: found record
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:publ_cback_func: update record
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua:run_pua_callbacks: found callback
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:pua_mi:mi_publ_rpl_cback: lexpire= 7776001
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:insert_timer_unsafe: [2]: 0xb5880c60 (584)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2975]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:set_timer: relative timeout is 500000
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:insert_timer_unsafe: [4]: 0xb5880d4c (580100000)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:set_timer: relative timeout is 5
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:tm:insert_timer_unsafe: [0]: 0xb5880d68 (584)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:mi_xmlrpc:default_method: done running the mi command.
Dec 13 16:27:29 localhost /usr/sbin/kamailio[3493]: DBG:mi_xmlrpc:default_method: done building response.
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_msg: SIP Reply  (status):
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_msg:  status:  <200>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_msg:  reason:  <OK>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_headers: flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6c1b.5804f1f6.0>; state=16
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:forward_reply: found module tm, passing reply to it
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_check: start=0xffffffff
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_headers: flags=22
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_to_param: tag=ddtbc
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_to: end of header reached, state=29
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:parse_to: display={}, ruri={sip:jh at test.fi}
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:get_hdr_field: <To> [28]; uri=[sip:jh at test.fi] 
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:get_hdr_field: to body [<sip:jh at test.fi>]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:get_hdr_field: cseq <CSeq>: <9> <NOTIFY>
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_reply_matching: hash 45510 label 1864319109 branch 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_reply_matching: reply matched (T=0xb587fbf8)!
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_check: end=0xb587fbf8
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:local_reply: branch=0, save=0, winner=0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:local_reply: local transaction completed
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:run_trans_callbacks: trans=0xb587fbf8, callback type 256, id 0 entered
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:presence:p_tm_callback: completed with status 200 [to_tag:25.2976.1229177886.1]
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:presence:p_tm_callback: Empty wi_subs parameter
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:insert_timer_unsafe: [2]: 0xb587fc40 (584)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:29 localhost /usr/sbin/kamailio[2976]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:4,tl=0xb587d7ac next=0xb587fd2c, timeout=580100000
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb587d678, BYE sip:j ... )
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_msg: SIP Reply  (status):
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_msg:  status:  <200>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_msg:  reason:  <OK>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: flags=2
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKa161.8c6ed086.0>; state=16
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:forward_reply: found module tm, passing reply to it
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_check: start=0xffffffff
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: flags=22
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_via_param: found param type 235, <rport> = <5036>; state=6
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKmjmaydpl>; state=16
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: via found, flags=22
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: parse_headers: this is the second via
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_to_param: tag=030CF455-4943C648000B1741-B69E2B90
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_to: end of header reached, state=29
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:get_hdr_field: <To> [60]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:get_hdr_field: to body [<sip:jh at vm.test.fi>]
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:get_hdr_field: cseq <CSeq>: <115> <BYE>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_reply_matching: hash 5658 label 1745741512 branch 0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_reply_matching: reply matched (T=0xb587d678)!
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:run_trans_callbacks: trans=0xb587d678, callback type 2, id 0 entered
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:parse_headers: flags=8
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_check: end=0xb587d678
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=0)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_should_relay_response: T_code=200, new_code=200
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:relay_reply: branch=0, save=0, relay=-1
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2977]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:set_timer: relative timeout is 1000000
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:insert_timer_unsafe: [5]: 0xb587d7ac (581100000)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : done
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:4,tl=0xb587fd2c next=0xb5880d4c, timeout=580100000
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:4,tl=0xb5880d4c next=(nil), timeout=580100000
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb5880c18, PUBLISH s ... )
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_msg: SIP Request:
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_msg:  method:  <PUBLISH>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_msg:  uri:     <sip:jh at vm.test.fi>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_headers: flags=2
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7729.3b5a6cb1.0>; state=16
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:receive_msg: preparing to run routing scripts...
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:check_via_address: params 192.98.101.10, 192.98.101.10, 0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_headers: flags=100
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_to: end of header reached, state=9
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:get_hdr_field: <To> [19]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:get_hdr_field: to body [sip:jh at vm.test.fi#015#012]
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:get_hdr_field: content_length=49
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:maxfwd:is_maxfwd_present: value = 70 
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:uri:has_totag: no totag
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:parse_headers: flags=78
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:t_lookup_request: start searching: hash=37495, isACK=0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=7729.3b5a6cb1.0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:t_lookup_request: transaction found (T=0xb587c2d8)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:t_retransmit_reply: nothing to retransmit
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:tm:t_check_trans: UNREF_UNSAFE: after is 0
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[2983]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:set_timer: relative timeout is 1000000
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:insert_timer_unsafe: [5]: 0xb5880d4c (581100000)
Dec 13 16:27:30 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : done
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:5,tl=0xb587d7ac next=0xb5880d4c, timeout=581100000
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb587d678, BYE sip:j ... )
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_msg: SIP Reply  (status):
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_msg:  status:  <200>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_msg:  reason:  <OK>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: flags=2
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKa161.8c6ed086.0>; state=16
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:forward_reply: found module tm, passing reply to it
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_check: start=0xffffffff
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:set_timer: relative timeout is 2000000
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: flags=22
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:insert_timer_unsafe: [6]: 0xb587d7ac (583100000)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_via_param: found param type 235, <rport> = <5036>; state=6
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : done
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKmjmaydpl>; state=16
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:5,tl=0xb5880d4c next=(nil), timeout=581100000
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb5880c18, PUBLISH s ... )
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: via found, flags=22
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_msg: SIP Request:
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:set_timer: relative timeout is 2000000
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: parse_headers: this is the second via
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_msg:  method:  <PUBLISH>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:insert_timer_unsafe: [6]: 0xb5880d4c (583100000)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_to_param: tag=030CF455-4943C648000B1741-B69E2B90
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_msg:  uri:     <sip:jh at vm.test.fi>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : done
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_to: end of header reached, state=29
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_headers: flags=2
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:get_hdr_field: <To> [60]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7729.3b5a6cb1.0>; state=16
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:get_hdr_field: to body [<sip:jh at vm.test.fi>]
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:get_hdr_field: cseq <CSeq>: <115> <BYE>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_reply_matching: hash 5658 label 1745741512 branch 0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_reply_matching: reply matched (T=0xb587d678)!
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:receive_msg: preparing to run routing scripts...
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:run_trans_callbacks: trans=0xb587d678, callback type 2, id 0 entered
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:check_via_address: params 192.98.101.10, 192.98.101.10, 0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:parse_headers: flags=8
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_headers: flags=100
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_check: end=0xb587d678
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_to: end of header reached, state=9
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:reply_received: org. status uas=200, uac[0]=200 local=0 is_invite=0)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_should_relay_response: T_code=200, new_code=200
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:get_hdr_field: <To> [19]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:relay_reply: branch=0, save=0, relay=-1
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:get_hdr_field: to body [sip:jh at vm.test.fi#015#012]
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:get_hdr_field: content_length=49
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2979]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:maxfwd:is_maxfwd_present: value = 70 
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:uri:has_totag: no totag
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:parse_headers: flags=78
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:t_lookup_request: start searching: hash=37495, isACK=0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=7729.3b5a6cb1.0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:t_lookup_request: transaction found (T=0xb587c2d8)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:t_retransmit_reply: nothing to retransmit
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:tm:t_check_trans: UNREF_UNSAFE: after is 0
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:31 localhost /usr/sbin/kamailio[2987]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:6,tl=0xb587d7ac next=0xb5880d4c, timeout=583100000
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:utimer_routine: timer routine:6,tl=0xb5880d4c next=(nil), timeout=583100000
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb5880c18, PUBLISH s ... )
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_msg: SIP Request:
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_msg:  method:  <PUBLISH>
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_msg:  uri:     <sip:jh at vm.test.fi>
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_msg:  version: <SIP/2.0>
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_headers: flags=2
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7729.3b5a6cb1.0>; state=16
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_via: end of header reached, state=5
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_headers: via found, flags=2
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_headers: this is the first via
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:receive_msg: After parse_msg...
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:receive_msg: preparing to run routing scripts...
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:check_via_address: params 192.98.101.10, 192.98.101.10, 0
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_headers: flags=100
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_to: end of header reached, state=9
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_to: display={}, ruri={sip:jh at vm.test.fi}
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:get_hdr_field: <To> [19]; uri=[sip:jh at vm.test.fi] 
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:get_hdr_field: to body [sip:jh at vm.test.fi#015#012]
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:get_hdr_field: cseq <CSeq>: <10> <PUBLISH>
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:get_hdr_field: content_length=49
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:maxfwd:is_maxfwd_present: value = 70 
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:uri:has_totag: no totag
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:parse_headers: flags=78
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:t_lookup_request: start searching: hash=37495, isACK=0
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:matching_3261: RFC3261 transaction matched, tid=7729.3b5a6cb1.0
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:t_lookup_request: transaction found (T=0xb587c2d8)
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:t_retransmit_reply: nothing to retransmit
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:tm:t_check_trans: UNREF_UNSAFE: after is 0
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:destroy_avp_list: destroying list (nil)
Dec 13 16:27:33 localhost /usr/sbin/kamailio[2981]: DBG:core:receive_msg: cleaning up
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:set_timer: relative timeout is 4000000
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:insert_timer_unsafe: [7]: 0xb5880d4c (587100000)
Dec 13 16:27:33 localhost /usr/sbin/kamailio[3005]: DBG:tm:retransmission_handler: retransmission_handler : done
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:0,tl=0xb587d7c8 next=0xb587fd48, timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:0,tl=0xb587fd48 next=0xb5880d68, timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:0,tl=0xb5880d68 next=(nil), timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb5880c18)
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:t_should_relay_response: T_code=200, new_code=408
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:local_reply: branch=0, save=0, winner=-1
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:final_response_handler: done
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:2,tl=0xb587d6c0 next=0xb587c320, timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: removing 0xb587d678 from table 
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:delete_cell: delete transaction 0xb587d678
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: done
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:2,tl=0xb587c320 next=0xb5880c60, timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: removing 0xb587c2d8 from table 
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:delete_cell: delete transaction 0xb587c2d8
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: done
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:2,tl=0xb5880c60 next=0xb587fc40, timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: removing 0xb5880c18 from table 
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:delete_cell: delete transaction 0xb5880c18
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: done
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:timer_routine: timer routine:2,tl=0xb587fc40 next=(nil), timeout=584
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: removing 0xb587fbf8 from table 
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:delete_cell: delete transaction 0xb587fbf8
Dec 13 16:27:34 localhost /usr/sbin/kamailio[3005]: DBG:tm:wait_handler: done
Dec 13 16:27:41 localhost /usr/sbin/kamailio[3011]: DBG:mi_fifo:mi_parse_tree: adding node <> ; val <3>
Dec 13 16:27:41 localhost /usr/sbin/kamailio[3011]: DBG:mi_fifo:mi_parse_node: end of input tree
Dec 13 16:27:41 localhost /usr/sbin/kamailio[3011]: DBG:mi_fifo:mi_fifo_server: done parsing the mi tree