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@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@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
, TO=<To: sip:1002@172.16.16.218:5091;tag=as06cb485b , CSEQ_N=<CSeq: 2>
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 hemanshu.patel@saicare.com wrote:
With TLS it still is not working Mar 27 11:39:16 [4421] INFO:core:probe_max_receive_buffer: using a UDP receive buffer of 255 kb Mar 27 11:39:16 [4425] WARNING:usrloc:dbrow2info: non-local socket ...ignoring Mar 27 11:39:18 [4431] INFO:core:tls_accept: client did not present a certificate Mar 27 11:39:55 [4432] INFO:core:tls_accept: client did not present a certificate Mar 27 11:40:01 [4431] ERROR:rr:w_record_route: Double attempt to record-route Mar 27 11:40:01 [4426] ERROR:core:tls_connect: SSL_ERROR_SYSCALL err=Connection reset by peer(104) Mar 27 11:40:01 [4426] ERROR:core:tls_connect: something wrong in SSL: 5 (ret=-1) err=Connection reset by peer(104) Mar 27 11:40:01 [4426] ERROR:core:tcp_send: failed to send Mar 27 11:40:01 [4426] ERROR:core:msg_send: tcp_send failed Mar 27 11:40:01 [4425] WARNING:core:run_actions: null action list (rec_level=1) my doubt is that if somethings wrong with SSL certificates that i created myself (i.e my own root CA, and self signed certificates), then how come registration is working like charm? if there is some problem with Certificates then registration should also not work. am i right?
Regards, Hemanshu Patel Sr. Software Engg SIS,Ahmedabad Mo:09601295238 On Sat 27/03/10 9:50 AM , "Hemanshu Patel" wrote:
I havent tested over TCP, let me check it but hardphone, i mean hardware based phones from grandstream
gvx3140
works fine with same implementation on TLS. -- Regards, Hemanshu Patel M: 09601295238
Does eyebeam with SIP over TCP is working?
Am 26.03.2010 13:43, schrieb Hemanshu Patel:
i am still having this problem. when i use two grandstream phone everything works fine, i can make calls on TLS and users can talk to each other.
But when i use two eyebream phone, it doesnt work, gives
following error
:33 [2875] WARNING:core:init_ssl_ctx_behavior: server
verification NOT
activated. Weaker security. [ panreg-tls]$ [ panreg-tls]$ [ panreg-tls]$ Mar 26 18:11:59 [2889] ERROR:rr:w_record_route: Double attempt to record-route Mar 26 18:12:09 [2884] ERROR:core:tcp_blocking_connect: timeout
10 s
elapsed from 10 s Mar 26 18:12:09 [2884] ERROR:core:tcpconn_connect:
tcp_blocking_connect
failed Mar 26 18:12:09 [2884] ERROR:core:tcp_send: connect failed Mar 26 18:12:09 [2884] ERROR:core:msg_send: tcp_send failed Mar 26 18:12:10 [2883] ERROR:core:tcp_blocking_connect: timeout
10 s
elapsed from 10 s Mar 26 18:12:10 [2883] ERROR:core:tcpconn_connect:
tcp_blocking_connect
failed Mar 26 18:12:10 [2883] ERROR:core:tcp_send: connect failed Mar 26 18:12:10 [2883] ERROR:core:msg_send: tcp_send failed Mar 26 18:12:10 [2883] WARNING:core:run_actions: null action
list
(rec_level=1) Mar 26 18:12:11 [2881] ERROR:core:tcp_blocking_connect: timeout
10 s
elapsed from 10 s Mar 26 18:12:11 [2881] ERROR:core:tcpconn_connect:
tcp_blocking_connect
failed Mar 26 18:12:11 [2881] ERROR:core:tcp_send: connect failed Mar 26 18:12:11 [2881] ERROR:core:msg_send: tcp_send failed Mar 26 18:12:13 [2882] ERROR:core:tcp_blocking_connect: timeout
10 s
elapsed from 10 s Mar 26 18:12:13 [2882] ERROR:core:tcpconn_connect:
tcp_blocking_connect
failed Mar 26 18:12:13 [2882] ERROR:core:tcp_send: connect failed Mar 26 18:12:13 [2882] ERROR:core:msg_send: tcp_send failed Mar 26 18:12:19 [2884] ERROR:core:tcp_blocking_connect: timeout
10 s
elapsed from 10 s Mar 26 18:12:19 [2884] ERROR:core:tcpconn_connect:
tcp_blocking_connect
failed Mar 26 18:12:19 [2884] ERROR:core:tcp_send: connect failed Mar 26 18:12:19 [2884] ERROR:core:msg_send: tcp_send failed
Any idea? Same configuration works with grandstream, while they
cant in
softphone? and gives 477 errot code.
my asterisk log is as below:
26 18:08:09] WARNING[2833]: chan_sip.c:1648 setup_crypto:
Hemanshu:
local_key641 jhbAJ7jFE1p/Ngn4kVxy7qTTmkJpeBiN6W98+gmM len 40 -- Called kamailio/1003 -- Got SIP response 477 "Send failed (477/SL)" back from 172.16.16.218 -- No one is available to answer at this time (1:0/0/0) -- Executing [_default:4] Hangup("SIP/5091-8c001430", "") in new stack == Spawn extension (hemu_default, 1003, 4) exited non-zero
on
'SIP/5091-8c001430' > ::Disconnected form Oracle, trying to connect
again..
> ::Tried a lot, not getting connected.. -- Got SIP response 477 "Send failed (477/SL)" back from172.16.16.218
Any idea what could be the problem?
Kamailio (OpenSER) - Users mailing list http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
---- 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
---- 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
A SIP trace would be much more useful. You can make them for example with Wireshark and configure Wireshark with the private kay of the certificate - then Wireshark can decode TLS. http://www.routerzone.eu/wiki/index.php/Using_Wireshark_to_Decrypt_SSL/TLS_P...
regards klaus
Am 27.03.2010 08:05, schrieb Hemanshu Patel:
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(549
-
Hemanshu Patel -
Klaus Darilion