[Kamailio-Users] Problem with secure TLS call

Hemanshu Patel hemanshu.patel at saicare.com
Sat Mar 27 08:05:54 CET 2010


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 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 172.16.16.218:5091>;tag=2cf7f9a22b6374f465182a893bba7dec.5636
From: "1003"<sip:1003 at 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 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [73]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 172.16.16.218:5091>
From: "1003"<sip:1003 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 172.16.16.218:5090}
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002 at 172.16.16.218:5090] 
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 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 at 172.16.16.218:5070>;tag=as7351a581
To: <sip:1002 at 172.16.16.218:5090>
Contact: <sip:1003 at 172.16.16.218:5070>
Call-ID: 7c10eaf0305d3dff6dac07db404d5a60 at 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 at 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 at 172.16.16.218:5070>;tag=as7351a581
To: <sip:1002 at 172.16.16.218:5090>
Contact: <sip:1003 at 172.16.16.218:5070>
Call-ID: 7c10eaf0305d3dff6dac07db404d5a60 at 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 at 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 at 172.16.16.218:5090}
Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: <To> [73]; uri=[sip:1002 at 172.16.16.218:5090] 
Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: <To> [46]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 172.16.16.218:5091>;tag=9f574228
>, TO=<To: <sip:1002 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: <To> [31]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 172.16.16.218:5091>;tag=9f574228
To: <sip:1002 at 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 at 172.16.16.218:5091>;tag=9f574228
To: <sip:1002 at 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 at 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 at 172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [46]; uri=[sip:1002 at 172.16.16.218:5091] 
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body [<sip:1002 at 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 at 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 at 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 from
> > >> 172.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




More information about the sr-users mailing list