Mar 23 10:33:43 [2344] DBG:core:handle_tcpconn_ev: data available on 0x7f35bdf9d7f0 23
Mar 23 10:33:43 [2344] DBG:core:io_watch_del: io_watch_del (0x74ee80, 23, -1, 0x0) fd_no=17 called
Mar 23 10:33:43 [2344] DBG:core:send2child: to tcp child 0 0(2340), 0x7f35bdf9d7f0
Mar 23 10:33:43 [2340] DBG:core:handle_io: received n=8 con=0x7f35bdf9d7f0, fd=17
Mar 23 10:33:43 [2340] DBG:core:io_watch_add: io_watch_add(0x74efe0, 17, 2, 0x7f35bdf9d7f0), fd_no=1
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 1557 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 815
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  method:  <INVITE>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1337273695>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [42]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <60> <INVITE>
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: value = 70 
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: no totag
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43957, isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=272384034
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={"1001"}, ruri={sip:1001@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5090 matches port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5091 matches port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091]
Mar 23 10:33:43 [2340] DBG:core:check_self: host == me
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=10000
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:auth:pre_auth: credentials with given realm not found
Mar 23 10:33:43 [2340] DBG:auth:reserve_nonce_index: second= 30, sec_monit= 37,  index= 40
Mar 23 10:33:43 [2340] DBG:auth:build_auth_hf: nonce index= 40
Mar 23 10:33:43 [2340] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="172.16.16.218", nonce="4ba84bcd000000289547d96a6775a0ed93350e7b16af1340"
'
Mar 23 10:33:43 [2340] DBG:sl:send_reply: reply in stateless mode (sl)
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:check_via_address: params 172.16.16.206, 172.16.16.206, 0
Mar 23 10:33:43 [2340] DBG:core:tcp_send: tcp connection found (0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2340] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0, 1, fd -1 from 7 (2340)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0 n=8 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 18
Mar 23 10:33:43 [2340] DBG:core:tls_write: write was successful (511 bytes)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=511 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: buf=
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TLS 172.16.16.206:5060;branch=z9hG4bK1337273695;rport=4972;alias
From: "1001" <sip:1001@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1000@172.16.16.218:5091;user=phone>;tag=2cf7f9a22b6374f465182a893bba7dec.a34e
Call-ID: 875232337-5060-7@BHC.BG.BG.CAG
CSeq: 60 INVITE
Proxy-Authenticate: Digest realm="172.16.16.218", nonce="4ba84bcd000000289547d96a6775a0ed93350e7b16af1340"
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0


Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 359 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 0
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  method:  <ACK>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1337273695>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.a34e
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [84]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2340] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 1788 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 815
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  method:  <INVITE>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [42]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: value = 70 
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: no totag
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958, isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=272384034
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={"1001"}, ruri={sip:1001@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5090 matches port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if host==us: 13==13 &&  [172.16.16.218] == [172.16.16.218]
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: checking if port 5091 matches port 5091
Mar 23 10:33:43 [2340] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091]
Mar 23 10:33:43 [2340] DBG:core:check_self: host == me
Mar 23 10:33:43 [2340] DBG:auth:check_nonce: comparing [4ba84bcd000000289547d96a6775a0ed93350e7b16af1340] and [4ba84bcd000000289547d96a6775a0ed93350e7b16af1340]
Mar 23 10:33:43 [2340] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78d560
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Mar 23 10:33:43 [2340] DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x78a918
Mar 23 10:33:43 [2340] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x78ce58
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: allocate 16 bytes for RES_NAMES[0] at 0x78d210
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78d210)[0]=[password]
Mar 23 10:33:43 [2340] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Mar 23 10:33:43 [2340] DBG:core:db_allocate_rows: allocate 16 bytes for rows at 0x79ebe0
Mar 23 10:33:43 [2340] DBG:core:db_allocate_row: allocate 32 bytes for row values at 0x78d230
Mar 23 10:33:43 [2340] DBG:core:db_str2val: converting STRING [1234]
Mar 23 10:33:43 [2340] DBG:auth_db:get_ha1: HA1 string calculated: 6e66d4925dd533f54199f801c85894f5
Mar 23 10:33:43 [2340] DBG:auth:check_response: our result = '24b0cb91322b8e3c3ec3576ad62fbce8'
Mar 23 10:33:43 [2340] DBG:auth:check_response: authorization is OK
Mar 23 10:33:43 [2340] DBG:auth:post_auth: nonce index= 40
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing 1 columns
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x78d210
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing result names at 0x78a918
Mar 23 10:33:43 [2340] DBG:core:db_free_columns: freeing result types at 0x78ce58
Mar 23 10:33:43 [2340] DBG:core:db_free_rows: freeing 1 rows
Mar 23 10:33:43 [2340] DBG:core:db_free_row: freeing row values at 0x78d230
Mar 23 10:33:43 [2340] DBG:core:db_free_rows: freeing rows at 0x79ebe0
Mar 23 10:33:43 [2340] DBG:core:db_free_result: freeing result set at 0x78d560
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=14000
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:core:comp_scriptvar: str 29 : 1001


---- Invite  ----

Mar 23 10:33:43 [2340] DBG:core:comp_scriptvar: str 29 : 1001
Mar 23 10:33:43 [2340] ERROR:rr:w_record_route: Double attempt to record-route
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: set [1]
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: alg hash [2504030904]
Mar 23 10:33:43 [2340] DBG:dispatcher:ds_select_dst: selected [0-1/0] <sip:172.16.16.218:5070>
Mar 23 10:33:43 [2340] DBG:tm:t_newtran: transaction on entrance=(nil)
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958, isACK=0
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: no transaction found
Mar 23 10:33:43 [2340] DBG:tm:run_reqin_callbacks: trans=0x7f35bdf67498, callback type 1, id 0 entered
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2340] DBG:core:check_via_address: params 172.16.16.206, 172.16.16.206, 0
Mar 23 10:33:43 [2340] DBG:core:_shm_resize: resize(0) called
Mar 23 10:33:43 [2340] DBG:core:tcp_send: tcp connection found (0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2340] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0, 1, fd -1 from 7 (2340)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0 n=8 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 18
Mar 23 10:33:43 [2340] DBG:core:tls_write: write was successful (343 bytes)
Mar 23 10:33:43 [2340] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=343 fd=18
Mar 23 10:33:43 [2340] DBG:core:tcp_send: buf=
SIP/2.0 100 Giving a try
Via: SIP/2.0/TLS 172.16.16.206:5060;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1001@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1000@172.16.16.218:5091;user=phone>
Call-ID: 875232337-5060-7@BHC.BG.BG.CAG
CSeq: 61 INVITE
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0


Mar 23 10:33:43 [2340] DBG:tm:_reply_light: reply sent out. buf=0x79f4a0: SIP/2.0 1..., shmem=0x7f35bdf56b10: SIP/2.0 1
Mar 23 10:33:43 [2340] DBG:tm:_reply_light: finished
Mar 23 10:33:43 [2340] DBG:core:mk_proxy: doing DNS lookup...
Mar 23 10:33:43 [2340] DBG:core:build_req_buf_from_sip_req: id added: <;i=82>, rcv proto=3
Mar 23 10:33:43 [2340] DBG:tm:set_timer: relative timeout is 500000
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [4]: 0x7f35bdf676b8 (2883200000)
Mar 23 10:33:43 [2340] DBG:tm:set_timer: relative timeout is 30
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [0]: 0x7f35bdf676e8 (2912)
Mar 23 10:33:43 [2340] DBG:tm:t_relay_to: new transaction fwd'ed
Mar 23 10:33:43 [2340] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2337] DBG:core:parse_msg: SIP Reply  (status):
Mar 23 10:33:43 [2337] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2337] DBG:core:parse_msg:  status:  <100>
Mar 23 10:33:43 [2337] DBG:core:parse_msg:  reason:  <Trying>
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 236, <i> = <82>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.218>; state=16
Mar 23 10:33:43 [2337] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2337] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2337] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2337] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2337] DBG:core:forward_reply: found module tm, passing reply to it
Mar 23 10:33:43 [2337] DBG:tm:t_check: start=0xffffffffffffffff
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=22
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 235, <rport> = <4972>; state=6
Mar 23 10:33:43 [2337] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2337] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2337] DBG:core:parse_headers: via found, flags=22
Mar 23 10:33:43 [2337] DBG:core:parse_headers: parse_headers: this is the second via
Mar 23 10:33:43 [2337] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2337] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: <To> [42]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2337] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2337] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: hash 43958 label 630322071 branch 0
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2337] DBG:tm:t_reply_matching: reply matched (T=0x7f35bdf67498)!
Mar 23 10:33:43 [2337] DBG:tm:t_check: end=0x7f35bdf67498
Mar 23 10:33:43 [2337] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Mar 23 10:33:43 [2337] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Mar 23 10:33:43 [2337] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Mar 23 10:33:43 [2337] DBG:tm:set_timer: relative timeout is 120
Mar 23 10:33:43 [2337] DBG:tm:insert_timer_unsafe: [1]: 0x7f35bdf676e8 (3003)
Mar 23 10:33:43 [2337] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2337] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2337] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2335] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2335] DBG:core:parse_msg:  method:  <INVITE>
Mar 23 10:33:43 [2335] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5090>
Mar 23 10:33:43 [2335] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2335] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK00843d58>; state=6
Mar 23 10:33:43 [2335] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Mar 23 10:33:43 [2335] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2335] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2335] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2335] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2335] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2335] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2335] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5090}
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1000@172.16.16.218:5090] 
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5090>
]
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Mar 23 10:33:43 [2335] DBG:maxfwd:is_maxfwd_present: value = 70 



---- From SC/MS/IC  ----


Mar 23 10:33:43 [2335] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:1000@172.16.17.81:15099;transport=tls;user=phone'
Mar 23 10:33:43 [2335] DBG:core:mk_proxy: doing DNS lookup...
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=2000
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: content_length=580
Mar 23 10:33:43 [2335] DBG:core:forward_request: sending:
INVITE sip:1000@172.16.17.81:15099;transport=tls;user=phone SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK00843d58
Via: SIP/2.0/UDP 172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK00843d58;rport=5070
From: "1001" <sip:1001@172.16.16.218:5070>;tag=as60af855f
To: <sip:1000@172.16.16.218:5090>
Contact: <sip:1001@172.16.16.218:5070>
Call-ID: 15b634d06c6e5d2d63b71fe123c3c640@172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Tue, 23 Mar 2010 05:03:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 580

v=0
o=root 2126 2126 IN IP4 172.16.16.218
s=session
c=IN IP4 172.16.16.218
t=0 0
m=audio 11262 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:2FXsAoBFaNzqIwXcyo8EwI81slJDnNpoA6+PkJFY 
a=sendrecv
m=video 17638 RTP/SAVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:WNjW7f5hxaItleUZMNPv/Ni1ZNQ7A9i4AUhHBBxI 
a=sendrecv
.
Mar 23 10:33:43 [2335] DBG:core:forward_request: orig. len=1121, new_len=1352, proto=3
Mar 23 10:33:43 [2335] DBG:core:tcp_send: no open tcp connection found, opening new one
Mar 23 10:33:43 [2335] DBG:core:print_ip: tcpconn_new: new tcp connection to: 172.16.17.81
Mar 23 10:33:43 [2335] DBG:core:tcpconn_new: on port 15099, type 3
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: entered: Creating a whole new ssl connection
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: name based TLS client domains are disabled
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: no TLS client domain AVP set, looking for socket based TLS client domain
Mar 23 10:33:43 [2335] DBG:core:tls_find_client_domain: virtual TLS client domain not found, Using default TLS client domain settings
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: found socket based TLS client domain [0.0.0.0:0]
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: Setting in CONNECT mode (client)
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: TLS server extension is not activated
Mar 23 10:33:43 [2335] DBG:core:tls_tcpconn_init: TLS server name is not set, sending ClientHello without server_name
Mar 23 10:33:43 [2335] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdfad988, 2, fd 24 from 2 (2335)
Mar 23 10:33:43 [2344] DBG:core:tcpconn_add: hashes: 599, 41
Mar 23 10:33:43 [2335] DBG:core:tls_update_fd: New fd is 9
Mar 23 10:33:43 [2344] DBG:core:io_watch_add: io_watch_add(0x74ee80, 24, 2, 0x7f35bdfad988), fd_no=16
Mar 23 10:33:43 [2344] DBG:core:handle_tcpconn_ev: data available on 0x7f35bdfad988 24
Mar 23 10:33:43 [2344] DBG:core:io_watch_del: io_watch_del (0x74ee80, 24, -1, 0x0) fd_no=17 called
Mar 23 10:33:43 [2344] DBG:core:send2child: to tcp child 1 0(2341), 0x7f35bdfad988
Mar 23 10:33:43 [2341] DBG:core:handle_io: received n=8 con=0x7f35bdfad988, fd=19
Mar 23 10:33:43 [2341] DBG:core:io_watch_add: io_watch_add(0x74efe0, 19, 2, 0x7f35bdfad988), fd_no=1
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: depth = 0
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: subject = /C=US/ST=California/L=Los Angeles/O=Grandstream Networks, Inc./CN=HT500 ATA
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: verify error:num=20:unable to get local issuer certificate
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: error code is 20
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: something wrong with the cert ... error code is 20 (check x509_vfy.h)
Mar 23 10:33:43 [2335] NOTICE:core:verify_callback: verify return:0
Mar 23 10:33:43 [2335] ERROR:core:tls_connect: something wrong in SSL: 1 (ret=-1) err=Success(0)
Mar 23 10:33:43 [2335] ERROR:core:tls_print_errstack: error:14090086:SSL routines:SSL3_GET_SERVER_CERTIFICATE:certificate verify failed
Mar 23 10:33:43 [2335] DBG:core:tcp_send: after write: c= 0x7f35bdfad988 n=-1 fd=9
Mar 23 10:33:43 [2341] DBG:core:io_watch_del: io_watch_del (0x74efe0, 19, -1, 0x10) fd_no=2 called
Mar 23 10:33:43 [2335] DBG:core:tcp_send: buf=
INVITE sip:1000@172.16.17.81:15099;transport=tls;user=phone SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK00843d58
Via: SIP/2.0/UDP 172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK00843d58;rport=5070
From: "1001" <sip:1001@172.16.16.218:5070>;tag=as60af855f
To: <sip:1000@172.16.16.218:5090>
Contact: <sip:1001@172.16.16.218:5070>
Call-ID: 15b634d06c6e5d2d63b71fe123c3c640@172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Tue, 23 Mar 2010 05:03:43 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 580

v=0
o=root 2126 2126 IN IP4 172.16.16.218
s=session
c=IN IP4 172.16.16.218
t=0 0
m=audio 11262 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:2FXsAoBFaNzqIwXcyo8EwI81slJDnNpoA6+PkJFY 
a=sendrecv
m=video 17638 RTP/SAVP 99
a=rtpmap:99 H264/90000
a=fmtp:99 profile-level-id=42800d
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:WNjW7f5hxaItleUZMNPv/Ni1ZNQ7A9i4AUhHBBxI 
a=sendrecv

Mar 23 10:33:43 [2341] DBG:core:release_tcpconn:  releasing con 0x7f35bdfad988, state -2, fd=19, id=41
Mar 23 10:33:43 [2335] ERROR:core:tcp_send: failed to send
Mar 23 10:33:43 [2341] DBG:core:release_tcpconn:  extra_data 0x7f35bdf5d490
Mar 23 10:33:43 [2335] ERROR:core:msg_send: tcp_send failed
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdfad988, -2, fd -1 from 2 (2335)
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: delaying (0x7f35bdfad988, flags 0002) ...
Mar 23 10:33:43 [2335] DBG:sl:sl_reply_error: error text is Send failed (477/SL)
Mar 23 10:33:43 [2344] DBG:core:handle_tcp_child: reader response= 7f35bdfad988, -2 from 1 
Mar 23 10:33:43 [2344] DBG:core:tcpconn_destroy: destroying connection 0x7f35bdfad988, flags 0002
Mar 23 10:33:43 [2344] DBG:core:tls_close: closing SSL connection
Mar 23 10:33:43 [2335] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2335] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2344] DBG:core:tls_update_fd: New fd is 24
Mar 23 10:33:43 [2344] DBG:core:tls_shutdown: shutdown successful
Mar 23 10:33:43 [2335] DBG:core:check_via_address: params 172.16.16.218, 172.16.16.218, 0
Mar 23 10:33:43 [2344] DBG:core:tls_tcpconn_clean: Cleanup function entered
Mar 23 10:33:43 [2335] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2335] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2336] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2336] DBG:core:parse_msg:  method:  <ACK>
Mar 23 10:33:43 [2336] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5090>
Mar 23 10:33:43 [2336] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2336] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2336] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK00843d58>; state=6
Mar 23 10:33:43 [2336] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Mar 23 10:33:43 [2336] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2336] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2336] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2336] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2336] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2336] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2336] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.3da6
Mar 23 10:33:43 [2336] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2336] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5090}
Mar 23 10:33:43 [2336] DBG:core:get_hdr_field: <To> [73]; uri=[sip:1000@172.16.16.218:5090] 
Mar 23 10:33:43 [2336] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5090>]
Mar 23 10:33:43 [2336] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 23 10:33:43 [2336] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2336] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2338] DBG:tm:utimer_routine: timer routine:4,tl=0x7f35bdf676b8 next=(nil), timeout=2883200000
Mar 23 10:33:43 [2334] DBG:core:parse_msg: SIP Reply  (status):
Mar 23 10:33:43 [2334] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2334] DBG:core:parse_msg:  status:  <404>
Mar 23 10:33:43 [2334] DBG:core:parse_msg:  reason:  <Not Found>
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 236, <i> = <82>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.218>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2334] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2334] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2334] DBG:core:forward_reply: found module tm, passing reply to it
Mar 23 10:33:43 [2334] DBG:tm:t_check: start=0xffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=22
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 235, <rport> = <4972>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=22
Mar 23 10:33:43 [2334] DBG:core:parse_headers: parse_headers: this is the second via
Mar 23 10:33:43 [2334] DBG:core:parse_to_param: tag=as4b33da29
Mar 23 10:33:43 [2334] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2334] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: <To> [57]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: hash 43958 label 630322071 branch 0
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2334] DBG:tm:t_reply_matching: reply matched (T=0x7f35bdf67498)!
Mar 23 10:33:43 [2334] DBG:tm:t_check: end=0x7f35bdf67498
Mar 23 10:33:43 [2334] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2334] DBG:tm:build_local: using FROM=<From: "1001" <sip:1001@172.16.16.218:5091;user=phone>;tag=272384034
>, TO=<To: <sip:1000@172.16.16.218:5091;user=phone>;tag=as4b33da29
>, CSEQ_N=<CSeq: 61>
Mar 23 10:33:43 [2334] DBG:tm:extract_parsed_hdrs: ----parsing the buf req - first line
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6bba.793f1952.0>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 236, <i> = <82>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.206>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 235, <rport> = <4972>; state=6
Mar 23 10:33:43 [2334] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2334] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2334] DBG:core:parse_headers: via found, flags=ffffffffffffffff
Mar 23 10:33:43 [2334] DBG:core:parse_headers: parse_headers: this is the second via
Mar 23 10:33:43 [2334] DBG:core:parse_to: end of header reached, state=10
Mar 23 10:33:43 [2334] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: <To> [42]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>
]
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: cseq <CSeq>: <61> <INVITE>
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: content_length=815
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2334] DBG:tm:t_should_relay_response: T_code=100, new_code=404
Mar 23 10:33:43 [2334] DBG:tm:t_pick_branch: picked branch 0, code 404
Mar 23 10:33:43 [2334] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=404, flags=2
Mar 23 10:33:43 [2334] WARNING:core:run_actions: null action list (rec_level=1)
Mar 23 10:33:43 [2334] DBG:tm:relay_reply: branch=0, save=0, relay=0
Mar 23 10:33:43 [2334] DBG:core:parse_headers: flags=2000
Mar 23 10:33:43 [2334] DBG:core:get_hdr_field: content_length=0
Mar 23 10:33:43 [2334] DBG:core:build_res_buf_from_sip_res:  old size: 541, new size: 446
Mar 23 10:33:43 [2334] DBG:core:build_res_buf_from_sip_res: copied size: orig:118, new: 23, rest: 423 msg=
SIP/2.0 404 Not Found
Via: SIP/2.0/TLS 172.16.16.206:5060;received=172.16.16.206;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1001@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1000@172.16.16.218:5091;user=phone>;tag=as4b33da29
Call-ID: 875232337-5060-7@BHC.BG.BG.CAG
CSeq: 61 INVITE
User-Agent: PANTHER-SC
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


Mar 23 10:33:43 [2334] DBG:tm:set_timer: relative timeout is 30
Mar 23 10:33:43 [2334] DBG:tm:insert_timer_unsafe: [0]: 0x7f35bdf67610 (2913)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: tcp connection found (0x7f35bdf9d7f0), acquiring fd
Mar 23 10:33:43 [2334] DBG:core:tcp_send: c= 0x7f35bdf9d7f0, n=16
Mar 23 10:33:43 [2344] DBG:core:handle_ser_child: read response= 7f35bdf9d7f0, 1, fd -1 from 1 (2334)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: after receive_fd: c= 0x7f35bdf9d7f0 n=8 fd=8
Mar 23 10:33:43 [2334] DBG:core:tcp_send: sending...
Mar 23 10:33:43 [2334] DBG:core:tls_update_fd: New fd is 8
Mar 23 10:33:43 [2334] DBG:core:tls_write: write was successful (446 bytes)
Mar 23 10:33:43 [2334] DBG:core:tcp_send: after write: c= 0x7f35bdf9d7f0 n=446 fd=8
Mar 23 10:33:43 [2334] DBG:core:tcp_send: buf=
SIP/2.0 404 Not Found
Via: SIP/2.0/TLS 172.16.16.206:5060;received=172.16.16.206;branch=z9hG4bK687870189;rport=4972;alias
From: "1001" <sip:1001@172.16.16.218:5091;user=phone>;tag=272384034
To: <sip:1000@172.16.16.218:5091;user=phone>;tag=as4b33da29
Call-ID: 875232337-5060-7@BHC.BG.BG.CAG
CSeq: 61 INVITE
User-Agent: PANTHER-SC
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


Mar 23 10:33:43 [2334] DBG:tm:relay_reply: sent buf=0x7915a8: SIP/2.0 4..., shmem=0x7f35bdf5dbb0: SIP/2.0 4
Mar 23 10:33:43 [2334] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 23 10:33:43 [2334] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2334] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2334] DBG:core:receive_msg: cleaning up
Mar 23 10:33:43 [2340] DBG:core:tls_update_fd: New fd is 17
Mar 23 10:33:43 [2340] DBG:core:_tls_read: 331 bytes read
Mar 23 10:33:43 [2340] DBG:core:tcp_read_req: content-length= 0
Mar 23 10:33:43 [2340] DBG:core:parse_msg: SIP Request:
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  method:  <ACK>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  uri:     <sip:1000@172.16.16.218:5091;user=phone>
Mar 23 10:33:43 [2340] DBG:core:parse_msg:  version: <SIP/2.0>
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK687870189>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
Mar 23 10:33:43 [2340] DBG:core:parse_via_param: found param type 237, <alias> = <n/a>; state=16
Mar 23 10:33:43 [2340] DBG:core:parse_via: end of header reached, state=5
Mar 23 10:33:43 [2340] DBG:core:parse_headers: via found, flags=2
Mar 23 10:33:43 [2340] DBG:core:parse_headers: this is the first via
Mar 23 10:33:43 [2340] DBG:core:receive_msg: After parse_msg...
Mar 23 10:33:43 [2340] DBG:core:receive_msg: preparing to run routing scripts...
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=8
Mar 23 10:33:43 [2340] DBG:core:parse_to_param: tag=as4b33da29
Mar 23 10:33:43 [2340] DBG:core:parse_to: end of header reached, state=29
Mar 23 10:33:43 [2340] DBG:core:parse_to: display={}, ruri={sip:1000@172.16.16.218:5091;user=phone}
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: <To> [57]; uri=[sip:1000@172.16.16.218:5091;user=phone] 
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: to body [<sip:1000@172.16.16.218:5091;user=phone>]
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=100
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: cseq <CSeq>: <61> <ACK>
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: content_length=0
Mar 23 10:33:43 [2340] DBG:core:get_hdr_field: found end of header
Mar 23 10:33:43 [2340] DBG:maxfwd:is_maxfwd_present: max_forwards header not found!
Mar 23 10:33:43 [2340] DBG:siputils:has_totag: totag found
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=200
Mar 23 10:33:43 [2340] DBG:rr:find_first_route: No Route headers found
Mar 23 10:33:43 [2340] DBG:rr:loose_route: There is no Route HF
Mar 23 10:33:43 [2340] DBG:core:parse_headers: flags=78
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: start searching: hash=43958, isACK=1
Mar 23 10:33:43 [2340] DBG:tm:matching_3261: RFC3261 transaction matched, tid=687870189
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Mar 23 10:33:43 [2340] DBG:tm:t_lookup_request: transaction found (T=0x7f35bdf67498)
Mar 23 10:33:43 [2340] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Mar 23 10:33:43 [2340] DBG:tm:insert_timer_unsafe: [2]: 0x7f35bdf67518 (2888)
Mar 23 10:33:43 [2340] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 23 10:33:43 [2340] DBG:core:destroy_avp_list: destroying list (nil)
Mar 23 10:33:43 [2340] DBG:core:receive_msg: cleaning up
Mar 23 10:33:48 [2338] DBG:tm:timer_routine: timer routine:2,tl=0x7f35bdf67518 next=(nil), timeout=2888
Mar 23 10:33:48 [2338] DBG:tm:wait_handler: removing 0x7f35bdf67498 from table 
Mar 23 10:33:48 [2338] DBG:tm:delete_cell: delete transaction 0x7f35bdf67498
Mar 23 10:33:48 [2338] DBG:tm:wait_handler: done
Mar 23 10:33:49 [2340] DBG:core:tcp_receive_timeout: 0x7f35bdf9d7f0 expired (2888, 2889) lt=0
Mar 23 10:33:49 [2340] DBG:core:io_watch_del: io_watch_del (0x74efe0, 17, -1, 0x10) fd_no=2 called
Mar 23 10:33:49 [2340] DBG:core:release_tcpconn:  releasing con 0x7f35bdf9d7f0, state 0, fd=17, id=40
Mar 23 10:33:49 [2340] DBG:core:release_tcpconn:  extra_data 0x7f35bdf59cc0
Mar 23 10:33:49 [2344] DBG:core:handle_tcp_child: reader response= 7f35bdf9d7f0, 0 from 0 
Mar 23 10:33:49 [2344] DBG:core:io_watch_add: io_watch_add(0x74ee80, 23, 2, 0x7f35bdf9d7f0), fd_no=16
Mar 23 10:33:49 [2344] DBG:core:handle_tcp_child: cmd CONN_RELEASE  0x7f35bdf9d7f0 refcnt= 0