Re: [Kamailio-Users] Problem with secure TLS call

Here is the complete call log for One call from two clients eyebream and bria running on single PC. Mar 27 12:36:36 [5492] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:36 [5492] DBG:core:receive_msg: cleaning up Mar 27 12:36:42 [5492] DBG:core:tcp_receive_timeout: 0x7fd335f04798 expired (50, 51) lt=0 Mar 27 12:36:42 [5492] DBG:core:io_watch_del: io_watch_del (0x74efe0, 18, -1, 0x10) fd_no=2 called Mar 27 12:36:42 [5492] DBG:core:release_tcpconn: releasing con 0x7fd335f04798, state 0, fd=18, id=3 Mar 27 12:36:42 [5492] DBG:core:release_tcpconn: extra_data 0x7fd335f017b8 Mar 27 12:36:42 [5499] DBG:core:handle_tcp_child: reader response= 7fd335f04798, 0 from 0 Mar 27 12:36:42 [5499] DBG:core:io_watch_add: io_watch_add(0x74ee80, 24, 2, 0x7fd335f04798), fd_no=17 Mar 27 12:36:42 [5499] DBG:core:handle_tcp_child: cmd CONN_RELEASE 0x7fd335f04798 refcnt= 0 Mar 27 12:36:45 [5499] DBG:core:handle_tcpconn_ev: data available on 0x7fd335eddc18 23 Mar 27 12:36:45 [5499] DBG:core:io_watch_del: io_watch_del (0x74ee80, 23, -1, 0x0) fd_no=18 called Mar 27 12:36:45 [5499] DBG:core:send2child: to tcp child 0 0(5492), 0x7fd335eddc18 Mar 27 12:36:45 [5492] DBG:core:handle_io: received n=8 con=0x7fd335eddc18, fd=18 Mar 27 12:36:45 [5492] DBG:core:io_watch_add: io_watch_add(0x74efe0, 18, 2, 0x7fd335eddc18), fd_no=1 Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18 Mar 27 12:36:45 [5492] DBG:core:_tls_read: 1109 bytes read Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 512 Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <INVITE> Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5091;transport=tls> Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-e333132001727d6d-1---d8754z->; state=6 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=100 Mar 27 12:36:45 [5492] DBG:maxfwd:is_maxfwd_present: value = 70 Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=10 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091> ] Mar 27 12:36:45 [5492] DBG:siputils:has_totag: no totag Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE> Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44320, isACK=0 Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=9f574228 Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={"1003"}, ruri={sip:1003@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5090 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5092 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5091 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:check_self: host == me Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=10000 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: content_length=512 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: found end of header Mar 27 12:36:45 [5492] DBG:auth:pre_auth: credentials with given realm not found Mar 27 12:36:45 [5492] DBG:auth:reserve_nonce_index: second= 22, sec_monit= -1, index= 3 Mar 27 12:36:45 [5492] DBG:auth:build_auth_hf: nonce index= 3 Mar 27 12:36:45 [5492] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest realm="172.16.16.218", nonce="4badaea30000000316e854bb0194116d66618a39dcd9340c" ' Mar 27 12:36:45 [5492] DBG:sl:send_reply: reply in stateless mode (sl) Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff Mar 27 12:36:45 [5492] DBG:core:check_via_address: params 172.16.17.85, 172.16.17.85, 0 Mar 27 12:36:45 [5492] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring fd Mar 27 12:36:45 [5492] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16 Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1 from 7 (5492) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: sending... Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 19 Mar 27 12:36:45 [5492] DBG:core:tls_write: write was successful (519 bytes) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=519 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: buf= SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/TLS 172.16.17.85:4403;branch=z9hG4bK-d8754z-e333132001727d6d-1---d8754z-;rport=1301 To: <sip:1002@172.16.16.218:5091>;tag=2cf7f9a22b6374f465182a893bba7dec.5636 From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228 Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU. CSeq: 1 INVITE Proxy-Authenticate: Digest realm="172.16.16.218", nonce="4badaea30000000316e854bb0194116d66618a39dcd9340c" Server: Kamailio (1.5.4-tls (x86_64/linux)) Content-Length: 0 Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18 Mar 27 12:36:45 [5492] DBG:core:_tls_read: 370 bytes read Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 0 Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <ACK> Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5091;transport=tls> Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-e333132001727d6d-1---d8754z->; state=6 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.5636 Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [73]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091>] Mar 27 12:36:45 [5492] DBG:sl:sl_filter_ACK: local ACK found -> dropping it! Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18 Mar 27 12:36:45 [5492] DBG:core:_tls_read: 1339 bytes read Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 512 Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <INVITE> Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5091;transport=tls> Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=100 Mar 27 12:36:45 [5492] DBG:maxfwd:is_maxfwd_present: value = 70 Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=10 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091> ] Mar 27 12:36:45 [5492] DBG:siputils:has_totag: no totag Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44317, isACK=0 Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=9f574228 Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={"1003"}, ruri={sip:1003@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5090 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5092 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 && [172.16.16.218] == [172.16.16.218] Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5091 matches port 5091 Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:check_self: host == me Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=10000 Mar 27 12:36:45 [5492] DBG:auth:check_nonce: comparing [4badaea30000000316e854bb0194116d66618a39dcd9340c] and [4badaea30000000316e854bb0194116d66618a39dcd9340c] Mar 27 12:36:45 [5492] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78d6c8 Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query Mar 27 12:36:45 [5492] DBG:core:db_allocate_columns: allocate 8 bytes for result names at 0x78aab8 Mar 27 12:36:45 [5492] DBG:core:db_allocate_columns: allocate 4 bytes for result types at 0x79ea58 Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: allocate 16 bytes for RES_NAMES[0] at 0x78d010 Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78d010)[0]=[password] Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type Mar 27 12:36:45 [5492] DBG:core:db_allocate_rows: allocate 16 bytes for rows at 0x79ea38 Mar 27 12:36:45 [5492] DBG:core:db_allocate_row: allocate 32 bytes for row values at 0x79ea78 Mar 27 12:36:45 [5492] DBG:core:db_str2val: converting STRING [1234] Mar 27 12:36:45 [5492] DBG:auth_db:get_ha1: HA1 string calculated: 6650a5aab1d658b465ee304e21b8db36 Mar 27 12:36:45 [5492] DBG:auth:check_response: our result = '19406efa15546eb60e105c164a1feb3d' Mar 27 12:36:45 [5492] DBG:auth:check_response: authorization is OK Mar 27 12:36:45 [5492] DBG:auth:post_auth: nonce index= 3 Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing 1 columns Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x78d010 Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing result names at 0x78aab8 Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing result types at 0x79ea58 Mar 27 12:36:45 [5492] DBG:core:db_free_rows: freeing 1 rows Mar 27 12:36:45 [5492] DBG:core:db_free_row: freeing row values at 0x79ea78 Mar 27 12:36:45 [5492] DBG:core:db_free_rows: freeing rows at 0x79ea38 Mar 27 12:36:45 [5492] DBG:core:db_free_result: freeing result set at 0x78d6c8 Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=14000 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: content_length=512 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: found end of header Mar 27 12:36:45 [5492] DBG:core:comp_scriptvar: str 29 : 1003 ---- Invite ---- Mar 27 12:36:45 [5492] DBG:core:comp_scriptvar: str 29 : 1003 Mar 27 12:36:45 [5492] ERROR:rr:w_record_route: Double attempt to record-route Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: set [1] Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: alg hash [789753065] Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: selected [0-1/0] <sip:172.16.16.218:5070> Mar 27 12:36:45 [5492] DBG:tm:t_newtran: transaction on entrance=(nil) Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78 Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44317, isACK=0 Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found Mar 27 12:36:45 [5492] DBG:tm:run_reqin_callbacks: trans=0x7fd335eee6b0, callback type 1, id 0 entered Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff Mar 27 12:36:45 [5492] DBG:core:check_via_address: params 172.16.17.85, 172.16.17.85, 0 Mar 27 12:36:45 [5492] DBG:core:_shm_resize: resize(0) called Mar 27 12:36:45 [5492] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring fd Mar 27 12:36:45 [5492] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16 Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1 from 7 (5492) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: sending... Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 19 Mar 27 12:36:45 [5492] DBG:core:tls_write: write was successful (352 bytes) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=352 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: buf= SIP/2.0 100 Giving a try Via: SIP/2.0/TLS 172.16.17.85:4403;branch=z9hG4bK-d8754z-863b295f961d253f-1---d8754z-;rport=1301 To: <sip:1002@172.16.16.218:5091> From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228 Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU. CSeq: 2 INVITE Server: Kamailio (1.5.4-tls (x86_64/linux)) Content-Length: 0 Mar 27 12:36:45 [5492] DBG:tm:_reply_light: reply sent out. buf=0x79f5e8: SIP/2.0 1..., shmem=0x7fd335f007a8: SIP/2.0 1 Mar 27 12:36:45 [5492] DBG:tm:_reply_light: finished Mar 27 12:36:45 [5492] DBG:core:mk_proxy: doing DNS lookup... Mar 27 12:36:45 [5492] DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv proto=3 Mar 27 12:36:45 [5492] DBG:tm:set_timer: relative timeout is 500000 Mar 27 12:36:45 [5492] DBG:tm:insert_timer_unsafe: [4]: 0x7fd335eee8d0 (54200000) Mar 27 12:36:45 [5492] DBG:tm:set_timer: relative timeout is 30 Mar 27 12:36:45 [5492] DBG:tm:insert_timer_unsafe: [0]: 0x7fd335eee900 (83) Mar 27 12:36:45 [5492] DBG:tm:t_relay_to: new transaction fwd'ed Mar 27 12:36:45 [5492] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5487] DBG:core:parse_msg: SIP Reply (status): Mar 27 12:36:45 [5487] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5487] DBG:core:parse_msg: status: <100> Mar 27 12:36:45 [5487] DBG:core:parse_msg: reason: <Trying> Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKd1da.1a6f9b73.0>; state=6 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=6 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.218>; state=16 Mar 27 12:36:45 [5487] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5487] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5487] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5487] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5487] DBG:core:forward_reply: found module tm, passing reply to it Mar 27 12:36:45 [5487] DBG:tm:t_check: start=0xffffffffffffffff Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=22 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 234, <received> = <172.16.17.85>; state=6 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6 Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 235, <rport> = <1301>; state=16 Mar 27 12:36:45 [5487] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5487] DBG:core:parse_headers: via found, flags=22 Mar 27 12:36:45 [5487] DBG:core:parse_headers: parse_headers: this is the second via Mar 27 12:36:45 [5487] DBG:core:parse_to: end of header reached, state=10 Mar 27 12:36:45 [5487] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091> ] Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: hash 44317 label 934934177 branch 0 Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: reply matched (T=0x7fd335eee6b0)! Mar 27 12:36:45 [5487] DBG:tm:t_check: end=0x7fd335eee6b0 Mar 27 12:36:45 [5487] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1) Mar 27 12:36:45 [5487] DBG:tm:t_should_relay_response: T_code=100, new_code=100 Mar 27 12:36:45 [5487] DBG:tm:relay_reply: branch=0, save=0, relay=-1 Mar 27 12:36:45 [5487] DBG:tm:set_timer: relative timeout is 120 Mar 27 12:36:45 [5487] DBG:tm:insert_timer_unsafe: [1]: 0x7fd335eee900 (173) Mar 27 12:36:45 [5487] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 27 12:36:45 [5487] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5487] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5489] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5489] DBG:core:parse_msg: method: <INVITE> Mar 27 12:36:45 [5489] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5090> Mar 27 12:36:45 [5489] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5489] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7f71d414>; state=6 Mar 27 12:36:45 [5489] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5489] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5489] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5489] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5489] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5489] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=100 Mar 27 12:36:45 [5489] DBG:core:parse_to: end of header reached, state=10 Mar 27 12:36:45 [5489] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5090} Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002@172.16.16.218:5090] Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5090> ] Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE> Mar 27 12:36:45 [5489] DBG:maxfwd:is_maxfwd_present: value = 70 ---- From SC/MS/IC ---- Mar 27 12:36:45 [5489] DBG:core:rewrite_uri: rewriting Request-URI with 'sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS' Mar 27 12:36:45 [5489] DBG:core:mk_proxy: doing DNS lookup... Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=2000 Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: content_length=394 Mar 27 12:36:45 [5489] DBG:core:forward_request: sending: INVITE sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS 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=z9hG4bK7f71d414 Via: SIP/2.0/UDP 172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK7f71d414;rport=5070 From: "1003" <sip:1003@172.16.16.218:5070>;tag=as7351a581 To: <sip:1002@172.16.16.218:5090> Contact: <sip:1003@172.16.16.218:5070> Call-ID: 7c10eaf0305d3dff6dac07db404d5a60(a)172.16.16.218 CSeq: 102 INVITE User-Agent: PANTHER-SC Max-Forwards: 69 Date: Sat, 27 Mar 2010 07:06:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 394 v=0 o=root 2434 2434 IN IP4 172.16.17.85 s=session c=IN IP4 172.16.17.85 t=0 0 m=audio 54168 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=sendrecv AES_CM_128_HMAC_SHA1_80 inline:qGi2zArgAgHDiUoqc0wbBofpBISpZINZxrqDoa7W . Mar 27 12:36:45 [5489] DBG:core:forward_request: orig. len=935, new_len=1182, proto=3 Mar 27 12:36:45 [5489] DBG:core:tcp_send: no open tcp connection found, opening new one Mar 27 12:36:45 [5489] DBG:core:print_ip: tcpconn_new: new tcp connection to: 172.16.17.85 Mar 27 12:36:45 [5489] DBG:core:tcpconn_new: on port 25923, type 3 Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: entered: Creating a whole new ssl connection Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: name based TLS client domains are disabled Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: no TLS client domain AVP set, looking for socket based TLS client domain Mar 27 12:36:45 [5489] DBG:core:tls_find_client_domain: virtual TLS client domain not found, Using default TLS client domain settings Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: found socket based TLS client domain [0.0.0.0:0] Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: Setting in CONNECT mode (client) Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: TLS server extension is not activated Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: TLS server name is not set, sending ClientHello without server_name Mar 27 12:36:45 [5489] DBG:core:tcp_send: sending... Mar 27 12:36:45 [5489] DBG:core:tls_update_fd: New fd is 12 Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335f23098, 2, fd 25 from 4 (5489) Mar 27 12:36:45 [5499] DBG:core:tcpconn_add: hashes: 495, 4 Mar 27 12:36:45 [5499] DBG:core:io_watch_add: io_watch_add(0x74ee80, 25, 2, 0x7fd335f23098), fd_no=17 Mar 27 12:36:45 [5499] DBG:core:handle_tcpconn_ev: data available on 0x7fd335f23098 25 Mar 27 12:36:45 [5489] ERROR:core:tls_connect: SSL_ERROR_SYSCALL err=Connection reset by peer(104) Mar 27 12:36:45 [5499] DBG:core:io_watch_del: io_watch_del (0x74ee80, 25, -1, 0x0) fd_no=18 called Mar 27 12:36:45 [5489] ERROR:core:tls_connect: something wrong in SSL: 5 (ret=-1) err=Connection reset by peer(104) Mar 27 12:36:45 [5499] DBG:core:send2child: to tcp child 1 0(5494), 0x7fd335f23098 Mar 27 12:36:45 [5489] DBG:core:tcp_send: after write: c= 0x7fd335f23098 n=-1 fd=12 Mar 27 12:36:45 [5489] DBG:core:tcp_send: buf= INVITE sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS 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=z9hG4bK7f71d414 Via: SIP/2.0/UDP 172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK7f71d414;rport=5070 From: "1003" <sip:1003@172.16.16.218:5070>;tag=as7351a581 To: <sip:1002@172.16.16.218:5090> Contact: <sip:1003@172.16.16.218:5070> Call-ID: 7c10eaf0305d3dff6dac07db404d5a60(a)172.16.16.218 CSeq: 102 INVITE User-Agent: PANTHER-SC Max-Forwards: 69 Date: Sat, 27 Mar 2010 07:06:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 394 v=0 o=root 2434 2434 IN IP4 172.16.17.85 s=session c=IN IP4 172.16.17.85 t=0 0 m=audio 54168 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=sendrecv AES_CM_128_HMAC_SHA1_80 inline:qGi2zArgAgHDiUoqc0wbBofpBISpZINZxrqDoa7W Mar 27 12:36:45 [5494] DBG:core:handle_io: received n=8 con=0x7fd335f23098, fd=20 Mar 27 12:36:45 [5489] ERROR:core:tcp_send: failed to send Mar 27 12:36:45 [5494] DBG:core:io_watch_add: io_watch_add(0x74efe0, 20, 2, 0x7fd335f23098), fd_no=1 Mar 27 12:36:45 [5489] ERROR:core:msg_send: tcp_send failed Mar 27 12:36:45 [5494] DBG:core:io_watch_del: io_watch_del (0x74efe0, 20, -1, 0x10) fd_no=2 called Mar 27 12:36:45 [5494] DBG:core:release_tcpconn: releasing con 0x7fd335f23098, state -2, fd=20, id=4 Mar 27 12:36:45 [5494] DBG:core:release_tcpconn: extra_data 0x7fd335f00ef8 Mar 27 12:36:45 [5489] DBG:sl:sl_reply_error: error text is Send failed (477/SL) Mar 27 12:36:45 [5499] DBG:core:handle_tcp_child: reader response= 7fd335f23098, -2 from 1 Mar 27 12:36:45 [5499] DBG:core:tcpconn_destroy: delaying (0x7fd335f23098, flags 0002) ... Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=ffffffffffffffff Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: found end of header Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335f23098, -2, fd -1 from 4 (5489) Mar 27 12:36:45 [5499] DBG:core:tcpconn_destroy: destroying connection 0x7fd335f23098, flags 0002 Mar 27 12:36:45 [5489] DBG:core:check_via_address: params 172.16.16.218, 172.16.16.218, 0 Mar 27 12:36:45 [5499] DBG:core:tls_close: closing SSL connection Mar 27 12:36:45 [5499] DBG:core:tls_update_fd: New fd is 25 Mar 27 12:36:45 [5499] DBG:core:tls_shutdown: shutdown successful Mar 27 12:36:45 [5499] DBG:core:tls_tcpconn_clean: Cleanup function entered Mar 27 12:36:45 [5486] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5486] DBG:core:parse_msg: method: <ACK> Mar 27 12:36:45 [5486] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5090> Mar 27 12:36:45 [5486] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5486] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5486] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK7f71d414>; state=6 Mar 27 12:36:45 [5486] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5486] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5486] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5486] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5486] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5486] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5486] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5486] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.adb6 Mar 27 12:36:45 [5486] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5486] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5090} Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: <To> [73]; uri=[sip:1002@172.16.16.218:5090] Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5090>] Mar 27 12:36:45 [5486] DBG:sl:sl_filter_ACK: local ACK found -> dropping it! Mar 27 12:36:45 [5486] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5486] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5489] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5489] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5485] DBG:core:parse_msg: SIP Reply (status): Mar 27 12:36:45 [5485] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5485] DBG:core:parse_msg: status: <404> Mar 27 12:36:45 [5485] DBG:core:parse_msg: reason: <Not Found> Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKd1da.1a6f9b73.0>; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 234, <received> = <172.16.16.218>; state=16 Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5485] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5485] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5485] DBG:core:forward_reply: found module tm, passing reply to it Mar 27 12:36:45 [5485] DBG:tm:t_check: start=0xffffffffffffffff Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=22 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 234, <received> = <172.16.17.85>; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 235, <rport> = <1301>; state=16 Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=22 Mar 27 12:36:45 [5485] DBG:core:parse_headers: parse_headers: this is the second via Mar 27 12:36:45 [5485] DBG:core:parse_to_param: tag=as06cb485b Mar 27 12:36:45 [5485] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5485] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: <To> [46]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091>] Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: hash 44317 label 934934177 branch 0 Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1 Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: reply matched (T=0x7fd335eee6b0)! Mar 27 12:36:45 [5485] DBG:tm:t_check: end=0x7fd335eee6b0 Mar 27 12:36:45 [5485] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1) Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5485] DBG:tm:build_local: using FROM=<From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228 Mar 27 12:36:45 [5485] DBG:tm:extract_parsed_hdrs: ----parsing the buf req - first line Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=ffffffffffffffff Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKd1da.1a6f9b73.0>; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 236, <i> = <1>; state=16 Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=ffffffffffffffff Mar 27 12:36:45 [5485] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 234, <received> = <172.16.17.85>; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6 Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 235, <rport> = <1301>; state=16 Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=ffffffffffffffff Mar 27 12:36:45 [5485] DBG:core:parse_headers: parse_headers: this is the second via Mar 27 12:36:45 [5485] DBG:core:parse_to: end of header reached, state=10 Mar 27 12:36:45 [5485] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091> ] Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: cseq <CSeq>: <2> <INVITE> Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: content_length=512 Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: found end of header Mar 27 12:36:45 [5485] DBG:tm:t_should_relay_response: T_code=100, new_code=404 Mar 27 12:36:45 [5485] DBG:tm:t_pick_branch: picked branch 0, code 404 Mar 27 12:36:45 [5485] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=404, flags=2 Mar 27 12:36:45 [5485] WARNING:core:run_actions: null action list (rec_level=1) Mar 27 12:36:45 [5485] DBG:tm:relay_reply: branch=0, save=0, relay=0 Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=2000 Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: content_length=0 Mar 27 12:36:45 [5485] DBG:core:build_res_buf_from_sip_res: old size: 548, new size: 454 Mar 27 12:36:45 [5485] DBG:core:build_res_buf_from_sip_res: copied size: orig:117, new: 23, rest: 431 msg= SIP/2.0 404 Not Found Via: SIP/2.0/TLS 172.16.17.85:4403;received=172.16.17.85;branch=z9hG4bK-d8754z-863b295f961d253f-1---d8754z-;rport=1301 From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228 To: <sip:1002@172.16.16.218:5091>;tag=as06cb485b Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU. CSeq: 2 INVITE User-Agent: PANTHER-SC Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 Mar 27 12:36:45 [5485] DBG:tm:set_timer: relative timeout is 30 Mar 27 12:36:45 [5485] DBG:tm:insert_timer_unsafe: [0]: 0x7fd335eee828 (83) Mar 27 12:36:45 [5485] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring fd Mar 27 12:36:45 [5485] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16 Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1 from 1 (5485) Mar 27 12:36:45 [5485] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=9 Mar 27 12:36:45 [5485] DBG:core:tcp_send: sending... Mar 27 12:36:45 [5485] DBG:core:tls_update_fd: New fd is 9 Mar 27 12:36:45 [5485] DBG:core:tls_write: write was successful (454 bytes) Mar 27 12:36:45 [5485] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=454 fd=9 Mar 27 12:36:45 [5485] DBG:core:tcp_send: buf= SIP/2.0 404 Not Found Via: SIP/2.0/TLS 172.16.17.85:4403;received=172.16.17.85;branch=z9hG4bK-d8754z-863b295f961d253f-1---d8754z-;rport=1301 From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228 To: <sip:1002@172.16.16.218:5091>;tag=as06cb485b Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU. CSeq: 2 INVITE User-Agent: PANTHER-SC Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 Mar 27 12:36:45 [5485] DBG:tm:relay_reply: sent buf=0x7916f0: SIP/2.0 4..., shmem=0x7fd335f007a8: SIP/2.0 4 Mar 27 12:36:45 [5485] DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 27 12:36:45 [5485] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 27 12:36:45 [5485] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5485] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18 Mar 27 12:36:45 [5492] DBG:core:_tls_read: 343 bytes read Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 0 Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request: Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <ACK> Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5091;transport=tls> Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0> Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6 Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17 Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5 Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2 Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg... Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts... Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8 Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=as06cb485b Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29 Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091} Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [46]; uri=[sip:1002@172.16.16.218:5091] Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002@172.16.16.218:5091>] Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=100 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: cseq <CSeq>: <2> <ACK> Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: content_length=0 Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: found end of header Mar 27 12:36:45 [5492] DBG:maxfwd:is_maxfwd_present: max_forwards header not found! Mar 27 12:36:45 [5492] DBG:siputils:has_totag: totag found Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=200 Mar 27 12:36:45 [5492] DBG:rr:find_first_route: No Route headers found Mar 27 12:36:45 [5492] DBG:rr:loose_route: There is no Route HF Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78 Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44317, isACK=1 Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matched, tid=-d8754z-863b295f961d253f-1---d8754z- Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1 Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: transaction found (T=0x7fd335eee6b0) Mar 27 12:36:45 [5492] DBG:tm:cleanup_uac_timers: RETR/FR timers reset Mar 27 12:36:45 [5492] DBG:tm:insert_timer_unsafe: [2]: 0x7fd335eee730 (58) Mar 27 12:36:45 [5492] DBG:tm:t_unref: UNREF_UNSAFE: after is 0 Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil) Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18 Mar 27 12:36:45 [5492] DBG:core:_tls_read: 4 bytes read Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 0 Mar 27 12:36:45 [5492] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring fd Mar 27 12:36:45 [5492] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16 Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1 from 7 (5492) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: sending... Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 19 Mar 27 12:36:45 [5492] DBG:core:tls_write: write was successful (2 bytes) Mar 27 12:36:45 [5492] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=2 fd=19 Mar 27 12:36:45 [5492] DBG:core:tcp_send: buf= one more thing, i have got two clients from one PC, still look at netstat result hemanshu@localhost user]$ netstat -antp | grep kamailio (Not all processes could be identified, non-owned process info will not be shown, you would have to be root to see it all.) tcp 0 0 172.16.16.218:5091 0.0.0.0:* LISTEN 4947/kamailio tcp 0 0 172.16.16.218:5092 0.0.0.0:* LISTEN 4947/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1295 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1296 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1289 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1293 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1291 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1286 ESTABLISHED 4964/kamailio tcp 0 0 172.16.16.218:5091 172.16.17.85:1285 ESTABLISHED 4964/kamailio Both clients keep creating new connection, and not reusing the already connected connection. i this this si the problem ---- Regards, Hemanshu Patel Sr. Software Engg Mo:09601295238 On Sat 27/03/10 11:37 AM , Hemanshu Patel &lt;hemanshu.patel(a)saicare.com&gt; wrote: ---- SIS Blade Server, Desktop & Thin Client is now available on DGS & D rate contract. For more detail kindly visit our website http://www.saicare.com