27 Mar
2010
27 Mar
'10
9:05 a.m.
Here is the complete call log for One call from two clients eyebream and bria running on
single PC.
Mar 27 12:36:36 [5492] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:36 [5492] DBG:core:receive_msg: cleaning up
Mar 27 12:36:42 [5492] DBG:core:tcp_receive_timeout: 0x7fd335f04798 expired (50, 51) lt=0
Mar 27 12:36:42 [5492] DBG:core:io_watch_del: io_watch_del (0x74efe0, 18, -1, 0x10)
fd_no=2 called
Mar 27 12:36:42 [5492] DBG:core:release_tcpconn: releasing con 0x7fd335f04798, state 0,
fd=18, id=3
Mar 27 12:36:42 [5492] DBG:core:release_tcpconn: extra_data 0x7fd335f017b8
Mar 27 12:36:42 [5499] DBG:core:handle_tcp_child: reader response= 7fd335f04798, 0 from 0
Mar 27 12:36:42 [5499] DBG:core:io_watch_add: io_watch_add(0x74ee80, 24, 2,
0x7fd335f04798), fd_no=17
Mar 27 12:36:42 [5499] DBG:core:handle_tcp_child: cmd CONN_RELEASE 0x7fd335f04798 refcnt=
0
Mar 27 12:36:45 [5499] DBG:core:handle_tcpconn_ev: data available on 0x7fd335eddc18 23
Mar 27 12:36:45 [5499] DBG:core:io_watch_del: io_watch_del (0x74ee80, 23, -1, 0x0)
fd_no=18 called
Mar 27 12:36:45 [5499] DBG:core:send2child: to tcp child 0 0(5492), 0x7fd335eddc18
Mar 27 12:36:45 [5492] DBG:core:handle_io: received n=8 con=0x7fd335eddc18, fd=18
Mar 27 12:36:45 [5492] DBG:core:io_watch_add: io_watch_add(0x74efe0, 18, 2,
0x7fd335eddc18), fd_no=1
Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18
Mar 27 12:36:45 [5492] DBG:core:_tls_read: 1109 bytes read
Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 512
Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request:
Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <INVITE>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri:
<sip:1002@172.16.16.218:5091;transport=tls>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK-d8754z-e333132001727d6d-1---d8754z->; state=6
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=17
Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts...
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=100
Mar 27 12:36:45 [5492] DBG:maxfwd:is_maxfwd_present: value = 70
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=10
Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31];
uri=[sip:1002@172.16.16.218:5091]
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5091>
]
Mar 27 12:36:45 [5492] DBG:siputils:has_totag: no totag
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: cseq <CSeq>: <1>
<INVITE>
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44320, isACK=0
Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found
Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=9f574228
Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29
Mar 27 12:36:45 [5492] DBG:core:parse_to: display={"1003"},
ruri={sip:1003@172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5090 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5092 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5091 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091]
Mar 27 12:36:45 [5492] DBG:core:check_self: host == me
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=10000
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: content_length=512
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: found end of header
Mar 27 12:36:45 [5492] DBG:auth:pre_auth: credentials with given realm not found
Mar 27 12:36:45 [5492] DBG:auth:reserve_nonce_index: second= 22, sec_monit= -1, index= 3
Mar 27 12:36:45 [5492] DBG:auth:build_auth_hf: nonce index= 3
Mar 27 12:36:45 [5492] DBG:auth:build_auth_hf: 'Proxy-Authenticate: Digest
realm="172.16.16.218",
nonce="4badaea30000000316e854bb0194116d66618a39dcd9340c"
'
Mar 27 12:36:45 [5492] DBG:sl:send_reply: reply in stateless mode (sl)
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 27 12:36:45 [5492] DBG:core:check_via_address: params 172.16.17.85, 172.16.17.85, 0
Mar 27 12:36:45 [5492] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring
fd
Mar 27 12:36:45 [5492] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16
Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1
from 7 (5492)
Mar 27 12:36:45 [5492] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=19
Mar 27 12:36:45 [5492] DBG:core:tcp_send: sending...
Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 19
Mar 27 12:36:45 [5492] DBG:core:tls_write: write was successful (519 bytes)
Mar 27 12:36:45 [5492] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=519 fd=19
Mar 27 12:36:45 [5492] DBG:core:tcp_send: buf=
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TLS
172.16.17.85:4403;branch=z9hG4bK-d8754z-e333132001727d6d-1---d8754z-;rport=1301
To: <sip:1002@172.16.16.218:5091>;tag=2cf7f9a22b6374f465182a893bba7dec.5636
From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228
Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU.
CSeq: 1 INVITE
Proxy-Authenticate: Digest realm="172.16.16.218",
nonce="4badaea30000000316e854bb0194116d66618a39dcd9340c"
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0
Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18
Mar 27 12:36:45 [5492] DBG:core:_tls_read: 370 bytes read
Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 0
Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request:
Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <ACK>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri:
<sip:1002@172.16.16.218:5091;transport=tls>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK-d8754z-e333132001727d6d-1---d8754z->; state=6
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=17
Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts...
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.5636
Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29
Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [73];
uri=[sip:1002@172.16.16.218:5091]
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5091>]
Mar 27 12:36:45 [5492] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 18
Mar 27 12:36:45 [5492] DBG:core:_tls_read: 1339 bytes read
Mar 27 12:36:45 [5492] DBG:core:tcp_read_req: content-length= 512
Mar 27 12:36:45 [5492] DBG:core:parse_msg: SIP Request:
Mar 27 12:36:45 [5492] DBG:core:parse_msg: method: <INVITE>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: uri:
<sip:1002@172.16.16.218:5091;transport=tls>
Mar 27 12:36:45 [5492] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6
Mar 27 12:36:45 [5492] DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=17
Mar 27 12:36:45 [5492] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5492] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5492] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5492] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5492] DBG:core:receive_msg: preparing to run routing scripts...
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=100
Mar 27 12:36:45 [5492] DBG:maxfwd:is_maxfwd_present: value = 70
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=10
Mar 27 12:36:45 [5492] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: <To> [31];
uri=[sip:1002@172.16.16.218:5091]
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5091>
]
Mar 27 12:36:45 [5492] DBG:siputils:has_totag: no totag
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: cseq <CSeq>: <2>
<INVITE>
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44317, isACK=0
Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found
Mar 27 12:36:45 [5492] DBG:core:parse_to_param: tag=9f574228
Mar 27 12:36:45 [5492] DBG:core:parse_to: end of header reached, state=29
Mar 27 12:36:45 [5492] DBG:core:parse_to: display={"1003"},
ruri={sip:1003@172.16.16.218:5091}
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5090 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5092 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if host==us: 13==13 &&
[172.16.16.218] == [172.16.16.218]
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: checking if port 5091 matches port 5091
Mar 27 12:36:45 [5492] DBG:core:grep_sock_info: match found for: [172.16.16.218:5091]
Mar 27 12:36:45 [5492] DBG:core:check_self: host == me
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=10000
Mar 27 12:36:45 [5492] DBG:auth:check_nonce: comparing
[4badaea30000000316e854bb0194116d66618a39dcd9340c] and
[4badaea30000000316e854bb0194116d66618a39dcd9340c]
Mar 27 12:36:45 [5492] DBG:core:db_new_result: allocate 48 bytes for result set at
0x78d6c8
Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the
query
Mar 27 12:36:45 [5492] DBG:core:db_allocate_columns: allocate 8 bytes for result names at
0x78aab8
Mar 27 12:36:45 [5492] DBG:core:db_allocate_columns: allocate 4 bytes for result types at
0x79ea58
Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: allocate 16 bytes for
RES_NAMES[0] at 0x78d010
Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns:
RES_NAMES(0x78d010)[0]=[password]
Mar 27 12:36:45 [5492] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Mar 27 12:36:45 [5492] DBG:core:db_allocate_rows: allocate 16 bytes for rows at 0x79ea38
Mar 27 12:36:45 [5492] DBG:core:db_allocate_row: allocate 32 bytes for row values at
0x79ea78
Mar 27 12:36:45 [5492] DBG:core:db_str2val: converting STRING [1234]
Mar 27 12:36:45 [5492] DBG:auth_db:get_ha1: HA1 string calculated:
6650a5aab1d658b465ee304e21b8db36
Mar 27 12:36:45 [5492] DBG:auth:check_response: our result =
'19406efa15546eb60e105c164a1feb3d'
Mar 27 12:36:45 [5492] DBG:auth:check_response: authorization is OK
Mar 27 12:36:45 [5492] DBG:auth:post_auth: nonce index= 3
Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing 1 columns
Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing RES_NAMES[0] at 0x78d010
Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing result names at 0x78aab8
Mar 27 12:36:45 [5492] DBG:core:db_free_columns: freeing result types at 0x79ea58
Mar 27 12:36:45 [5492] DBG:core:db_free_rows: freeing 1 rows
Mar 27 12:36:45 [5492] DBG:core:db_free_row: freeing row values at 0x79ea78
Mar 27 12:36:45 [5492] DBG:core:db_free_rows: freeing rows at 0x79ea38
Mar 27 12:36:45 [5492] DBG:core:db_free_result: freeing result set at 0x78d6c8
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=14000
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: content_length=512
Mar 27 12:36:45 [5492] DBG:core:get_hdr_field: found end of header
Mar 27 12:36:45 [5492] DBG:core:comp_scriptvar: str 29 : 1003
---- Invite ----
Mar 27 12:36:45 [5492] DBG:core:comp_scriptvar: str 29 : 1003
Mar 27 12:36:45 [5492] ERROR:rr:w_record_route: Double attempt to record-route
Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: set [1]
Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: alg hash [789753065]
Mar 27 12:36:45 [5492] DBG:dispatcher:ds_select_dst: selected [0-1/0]
<sip:172.16.16.218:5070>
Mar 27 12:36:45 [5492] DBG:tm:t_newtran: transaction on entrance=(nil)
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=78
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: start searching: hash=44317, isACK=0
Mar 27 12:36:45 [5492] DBG:tm:matching_3261: RFC3261 transaction matching failed
Mar 27 12:36:45 [5492] DBG:tm:t_lookup_request: no transaction found
Mar 27 12:36:45 [5492] DBG:tm:run_reqin_callbacks: trans=0x7fd335eee6b0, callback type 1,
id 0 entered
Mar 27 12:36:45 [5492] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 27 12:36:45 [5492] DBG:core:check_via_address: params 172.16.17.85, 172.16.17.85, 0
Mar 27 12:36:45 [5492] DBG:core:_shm_resize: resize(0) called
Mar 27 12:36:45 [5492] DBG:core:tcp_send: tcp connection found (0x7fd335eddc18), acquiring
fd
Mar 27 12:36:45 [5492] DBG:core:tcp_send: c= 0x7fd335eddc18, n=16
Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335eddc18, 1, fd -1
from 7 (5492)
Mar 27 12:36:45 [5492] DBG:core:tcp_send: after receive_fd: c= 0x7fd335eddc18 n=8 fd=19
Mar 27 12:36:45 [5492] DBG:core:tcp_send: sending...
Mar 27 12:36:45 [5492] DBG:core:tls_update_fd: New fd is 19
Mar 27 12:36:45 [5492] DBG:core:tls_write: write was successful (352 bytes)
Mar 27 12:36:45 [5492] DBG:core:tcp_send: after write: c= 0x7fd335eddc18 n=352 fd=19
Mar 27 12:36:45 [5492] DBG:core:tcp_send: buf=
SIP/2.0 100 Giving a try
Via: SIP/2.0/TLS
172.16.17.85:4403;branch=z9hG4bK-d8754z-863b295f961d253f-1---d8754z-;rport=1301
To: <sip:1002@172.16.16.218:5091>
From: "1003"<sip:1003@172.16.16.218:5091>;tag=9f574228
Call-ID: M2Y2OThmYmYwZjM4ODhhYzk4Mjc0MGFhMDQyNDUzZWU.
CSeq: 2 INVITE
Server: Kamailio (1.5.4-tls (x86_64/linux))
Content-Length: 0
Mar 27 12:36:45 [5492] DBG:tm:_reply_light: reply sent out. buf=0x79f5e8: SIP/2.0 1...,
shmem=0x7fd335f007a8: SIP/2.0 1
Mar 27 12:36:45 [5492] DBG:tm:_reply_light: finished
Mar 27 12:36:45 [5492] DBG:core:mk_proxy: doing DNS lookup...
Mar 27 12:36:45 [5492] DBG:core:build_req_buf_from_sip_req: id added: <;i=1>, rcv
proto=3
Mar 27 12:36:45 [5492] DBG:tm:set_timer: relative timeout is 500000
Mar 27 12:36:45 [5492] DBG:tm:insert_timer_unsafe: [4]: 0x7fd335eee8d0 (54200000)
Mar 27 12:36:45 [5492] DBG:tm:set_timer: relative timeout is 30
Mar 27 12:36:45 [5492] DBG:tm:insert_timer_unsafe: [0]: 0x7fd335eee900 (83)
Mar 27 12:36:45 [5492] DBG:tm:t_relay_to: new transaction fwd'ed
Mar 27 12:36:45 [5492] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 27 12:36:45 [5492] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5492] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5487] DBG:core:parse_msg: SIP Reply (status):
Mar 27 12:36:45 [5487] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5487] DBG:core:parse_msg: status: <100>
Mar 27 12:36:45 [5487] DBG:core:parse_msg: reason: <Trying>
Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKd1da.1a6f9b73.0>; state=6
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 236, <i> =
<1>; state=6
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 234, <received> =
<172.16.16.218>; state=16
Mar 27 12:36:45 [5487] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5487] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5487] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5487] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5487] DBG:core:forward_reply: found module tm, passing reply to it
Mar 27 12:36:45 [5487] DBG:tm:t_check: start=0xffffffffffffffff
Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=22
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 234, <received> =
<172.16.17.85>; state=6
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6
Mar 27 12:36:45 [5487] DBG:core:parse_via_param: found param type 235, <rport> =
<1301>; state=16
Mar 27 12:36:45 [5487] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5487] DBG:core:parse_headers: via found, flags=22
Mar 27 12:36:45 [5487] DBG:core:parse_headers: parse_headers: this is the second via
Mar 27 12:36:45 [5487] DBG:core:parse_to: end of header reached, state=10
Mar 27 12:36:45 [5487] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091}
Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: <To> [31];
uri=[sip:1002@172.16.16.218:5091]
Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5091>
]
Mar 27 12:36:45 [5487] DBG:core:get_hdr_field: cseq <CSeq>: <2>
<INVITE>
Mar 27 12:36:45 [5487] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: hash 44317 label 934934177 branch 0
Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 27 12:36:45 [5487] DBG:tm:t_reply_matching: reply matched (T=0x7fd335eee6b0)!
Mar 27 12:36:45 [5487] DBG:tm:t_check: end=0x7fd335eee6b0
Mar 27 12:36:45 [5487] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0
is_invite=1)
Mar 27 12:36:45 [5487] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Mar 27 12:36:45 [5487] DBG:tm:relay_reply: branch=0, save=0, relay=-1
Mar 27 12:36:45 [5487] DBG:tm:set_timer: relative timeout is 120
Mar 27 12:36:45 [5487] DBG:tm:insert_timer_unsafe: [1]: 0x7fd335eee900 (173)
Mar 27 12:36:45 [5487] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Mar 27 12:36:45 [5487] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5487] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5489] DBG:core:parse_msg: SIP Request:
Mar 27 12:36:45 [5489] DBG:core:parse_msg: method: <INVITE>
Mar 27 12:36:45 [5489] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5090>
Mar 27 12:36:45 [5489] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5489] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK7f71d414>; state=6
Mar 27 12:36:45 [5489] DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=17
Mar 27 12:36:45 [5489] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5489] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5489] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5489] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5489] DBG:core:receive_msg: preparing to run routing scripts...
Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=100
Mar 27 12:36:45 [5489] DBG:core:parse_to: end of header reached, state=10
Mar 27 12:36:45 [5489] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5090}
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: <To> [31];
uri=[sip:1002@172.16.16.218:5090]
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5090>
]
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: cseq <CSeq>: <102>
<INVITE>
Mar 27 12:36:45 [5489] DBG:maxfwd:is_maxfwd_present: value = 70
---- From SC/MS/IC ----
Mar 27 12:36:45 [5489] DBG:core:rewrite_uri: rewriting Request-URI with
'sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS'
Mar 27 12:36:45 [5489] DBG:core:mk_proxy: doing DNS lookup...
Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=2000
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: content_length=394
Mar 27 12:36:45 [5489] DBG:core:forward_request: sending:
INVITE sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK7f71d414
Via: SIP/2.0/UDP
172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK7f71d414;rport=5070
From: "1003" <sip:1003@172.16.16.218:5070>;tag=as7351a581
To: <sip:1002@172.16.16.218:5090>
Contact: <sip:1003@172.16.16.218:5070>
Call-ID: 7c10eaf0305d3dff6dac07db404d5a60(a)172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Sat, 27 Mar 2010 07:06:45 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 394
v=0
o=root 2434 2434 IN IP4 172.16.17.85
s=session
c=IN IP4 172.16.17.85
t=0 0
m=audio 54168 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv AES_CM_128_HMAC_SHA1_80 inline:qGi2zArgAgHDiUoqc0wbBofpBISpZINZxrqDoa7W
.
Mar 27 12:36:45 [5489] DBG:core:forward_request: orig. len=935, new_len=1182, proto=3
Mar 27 12:36:45 [5489] DBG:core:tcp_send: no open tcp connection found, opening new one
Mar 27 12:36:45 [5489] DBG:core:print_ip: tcpconn_new: new tcp connection to:
172.16.17.85
Mar 27 12:36:45 [5489] DBG:core:tcpconn_new: on port 25923, type 3
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: entered: Creating a whole new ssl
connection
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: name based TLS client domains are
disabled
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: no TLS client domain AVP set, looking
for socket based TLS client domain
Mar 27 12:36:45 [5489] DBG:core:tls_find_client_domain: virtual TLS client domain not
found, Using default TLS client domain settings
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: found socket based TLS client domain
[0.0.0.0:0]
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: Setting in CONNECT mode (client)
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: TLS server extension is not activated
Mar 27 12:36:45 [5489] DBG:core:tls_tcpconn_init: TLS server name is not set, sending
ClientHello without server_name
Mar 27 12:36:45 [5489] DBG:core:tcp_send: sending...
Mar 27 12:36:45 [5489] DBG:core:tls_update_fd: New fd is 12
Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335f23098, 2, fd 25
from 4 (5489)
Mar 27 12:36:45 [5499] DBG:core:tcpconn_add: hashes: 495, 4
Mar 27 12:36:45 [5499] DBG:core:io_watch_add: io_watch_add(0x74ee80, 25, 2,
0x7fd335f23098), fd_no=17
Mar 27 12:36:45 [5499] DBG:core:handle_tcpconn_ev: data available on 0x7fd335f23098 25
Mar 27 12:36:45 [5489] ERROR:core:tls_connect: SSL_ERROR_SYSCALL err=Connection reset by
peer(104)
Mar 27 12:36:45 [5499] DBG:core:io_watch_del: io_watch_del (0x74ee80, 25, -1, 0x0)
fd_no=18 called
Mar 27 12:36:45 [5489] ERROR:core:tls_connect: something wrong in SSL: 5 (ret=-1)
err=Connection reset by peer(104)
Mar 27 12:36:45 [5499] DBG:core:send2child: to tcp child 1 0(5494), 0x7fd335f23098
Mar 27 12:36:45 [5489] DBG:core:tcp_send: after write: c= 0x7fd335f23098 n=-1 fd=12
Mar 27 12:36:45 [5489] DBG:core:tcp_send: buf=
INVITE sip:1002@172.16.17.85:25923;rinstance=133b23266b1f2e83;transport=TLS SIP/2.0
Record-Route: <sip:172.16.16.218:5091;transport=tls;r2=on;lr=on>
Record-Route: <sip:172.16.16.218:5090;r2=on;lr=on>
Via: SIP/2.0/TLS 172.16.16.218:5091;branch=z9hG4bK7f71d414
Via: SIP/2.0/UDP
172.16.16.218:5070;received=172.16.16.218;branch=z9hG4bK7f71d414;rport=5070
From: "1003" <sip:1003@172.16.16.218:5070>;tag=as7351a581
To: <sip:1002@172.16.16.218:5090>
Contact: <sip:1003@172.16.16.218:5070>
Call-ID: 7c10eaf0305d3dff6dac07db404d5a60(a)172.16.16.218
CSeq: 102 INVITE
User-Agent: PANTHER-SC
Max-Forwards: 69
Date: Sat, 27 Mar 2010 07:06:45 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 394
v=0
o=root 2434 2434 IN IP4 172.16.17.85
s=session
c=IN IP4 172.16.17.85
t=0 0
m=audio 54168 RTP/SAVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv AES_CM_128_HMAC_SHA1_80 inline:qGi2zArgAgHDiUoqc0wbBofpBISpZINZxrqDoa7W
Mar 27 12:36:45 [5494] DBG:core:handle_io: received n=8 con=0x7fd335f23098, fd=20
Mar 27 12:36:45 [5489] ERROR:core:tcp_send: failed to send
Mar 27 12:36:45 [5494] DBG:core:io_watch_add: io_watch_add(0x74efe0, 20, 2,
0x7fd335f23098), fd_no=1
Mar 27 12:36:45 [5489] ERROR:core:msg_send: tcp_send failed
Mar 27 12:36:45 [5494] DBG:core:io_watch_del: io_watch_del (0x74efe0, 20, -1, 0x10)
fd_no=2 called
Mar 27 12:36:45 [5494] DBG:core:release_tcpconn: releasing con 0x7fd335f23098, state -2,
fd=20, id=4
Mar 27 12:36:45 [5494] DBG:core:release_tcpconn: extra_data 0x7fd335f00ef8
Mar 27 12:36:45 [5489] DBG:sl:sl_reply_error: error text is Send failed (477/SL)
Mar 27 12:36:45 [5499] DBG:core:handle_tcp_child: reader response= 7fd335f23098, -2 from 1
Mar 27 12:36:45 [5499] DBG:core:tcpconn_destroy: delaying (0x7fd335f23098, flags 0002)
...
Mar 27 12:36:45 [5489] DBG:core:parse_headers: flags=ffffffffffffffff
Mar 27 12:36:45 [5489] DBG:core:get_hdr_field: found end of header
Mar 27 12:36:45 [5499] DBG:core:handle_ser_child: read response= 7fd335f23098, -2, fd -1
from 4 (5489)
Mar 27 12:36:45 [5499] DBG:core:tcpconn_destroy: destroying connection 0x7fd335f23098,
flags 0002
Mar 27 12:36:45 [5489] DBG:core:check_via_address: params 172.16.16.218, 172.16.16.218, 0
Mar 27 12:36:45 [5499] DBG:core:tls_close: closing SSL connection
Mar 27 12:36:45 [5499] DBG:core:tls_update_fd: New fd is 25
Mar 27 12:36:45 [5499] DBG:core:tls_shutdown: shutdown successful
Mar 27 12:36:45 [5499] DBG:core:tls_tcpconn_clean: Cleanup function entered
Mar 27 12:36:45 [5486] DBG:core:parse_msg: SIP Request:
Mar 27 12:36:45 [5486] DBG:core:parse_msg: method: <ACK>
Mar 27 12:36:45 [5486] DBG:core:parse_msg: uri: <sip:1002@172.16.16.218:5090>
Mar 27 12:36:45 [5486] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5486] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5486] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK7f71d414>; state=6
Mar 27 12:36:45 [5486] DBG:core:parse_via_param: found param type 235, <rport> =
<n/a>; state=17
Mar 27 12:36:45 [5486] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5486] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5486] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5486] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5486] DBG:core:receive_msg: preparing to run routing scripts...
Mar 27 12:36:45 [5486] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5486] DBG:core:parse_to_param: tag=2cf7f9a22b6374f465182a893bba7dec.adb6
Mar 27 12:36:45 [5486] DBG:core:parse_to: end of header reached, state=29
Mar 27 12:36:45 [5486] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5090}
Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: <To> [73];
uri=[sip:1002@172.16.16.218:5090]
Mar 27 12:36:45 [5486] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5090>]
Mar 27 12:36:45 [5486] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Mar 27 12:36:45 [5486] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5486] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5489] DBG:core:destroy_avp_list: destroying list (nil)
Mar 27 12:36:45 [5489] DBG:core:receive_msg: cleaning up
Mar 27 12:36:45 [5485] DBG:core:parse_msg: SIP Reply (status):
Mar 27 12:36:45 [5485] DBG:core:parse_msg: version: <SIP/2.0>
Mar 27 12:36:45 [5485] DBG:core:parse_msg: status: <404>
Mar 27 12:36:45 [5485] DBG:core:parse_msg: reason: <Not Found>
Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=2
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKd1da.1a6f9b73.0>; state=6
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 236, <i> =
<1>; state=6
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 234, <received> =
<172.16.16.218>; state=16
Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=2
Mar 27 12:36:45 [5485] DBG:core:parse_headers: this is the first via
Mar 27 12:36:45 [5485] DBG:core:receive_msg: After parse_msg...
Mar 27 12:36:45 [5485] DBG:core:forward_reply: found module tm, passing reply to it
Mar 27 12:36:45 [5485] DBG:tm:t_check: start=0xffffffffffffffff
Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=22
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 234, <received> =
<172.16.17.85>; state=6
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bK-d8754z-863b295f961d253f-1---d8754z->; state=6
Mar 27 12:36:45 [5485] DBG:core:parse_via_param: found param type 235, <rport> =
<1301>; state=16
Mar 27 12:36:45 [5485] DBG:core:parse_via: end of header reached, state=5
Mar 27 12:36:45 [5485] DBG:core:parse_headers: via found, flags=22
Mar 27 12:36:45 [5485] DBG:core:parse_headers: parse_headers: this is the second via
Mar 27 12:36:45 [5485] DBG:core:parse_to_param: tag=as06cb485b
Mar 27 12:36:45 [5485] DBG:core:parse_to: end of header reached, state=29
Mar 27 12:36:45 [5485] DBG:core:parse_to: display={}, ruri={sip:1002@172.16.16.218:5091}
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: <To> [46];
uri=[sip:1002@172.16.16.218:5091]
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: to body
[<sip:1002@172.16.16.218:5091>]
Mar 27 12:36:45 [5485] DBG:core:get_hdr_field: cseq <CSeq>: <2>
<INVITE>
Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: hash 44317 label 934934177 branch 0
Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Mar 27 12:36:45 [5485] DBG:tm:t_reply_matching: reply matched (T=0x7fd335eee6b0)!
Mar 27 12:36:45 [5485] DBG:tm:t_check: end=0x7fd335eee6b0
Mar 27 12:36:45 [5485] DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0
is_invite=1)
Mar 27 12:36:45 [5485] DBG:core:parse_headers: flags=8
Mar 27 12:36:45 [5485] DBG:tm:build_local: using FROM=<From:
"1003"<sip:1003@172.16.16.218:5091>;tag=9f574228
, 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(a)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:
on
_______________________________________________
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
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
list
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 >
(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 >> '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?
29 Mar
29 Mar
11:56 a.m.
New subject: [Kamailio-Users] Problem with secure TLS call
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_…
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
5355
days inactive
5357
days old
1 comments
2 participants
participants (2)
-
Hemanshu Patel -
Klaus Darilion