[OpenSIPS-Users] Unable to call using Opensips via TLS

Wed Apr 13 16:36:07 CEST 2011

HI ,

I am using opensips with TLS enabled.Iam trying to establish a call via
TLS,both the clients are able to register,but when a message/call is sent I
get the following error

SIP/2.0 200 OK
Via: SIP/2.0/TLS 10.1.1.102:1268
;rport=1268;branch=z9hG4bKPj021189d9cdb2430998ee8f0d36cc173d
From: <sip:2000 at 20.1.1.2>;tag=3f23894087f04dc599171a376667a716
To: <sip:2000 at 20.1.1.2>;tag=e4628f3555f473813fff196cef35ce47.52fc
Call-ID: fc6971a239f14ed6942339b96e5e6985
CSeq: 47334 REGISTER
Contact: <sip:2000 at 10.1.1.102:4000;transport=TLS>;expires=300
Server: OpenSIPS (1.6.4-2-tls (i386/linux))
Content-Length: 0


Apr 17 08:32:38 [29262] DBG:core:destroy_avp_list: destroying list (nil)
Apr 17 08:32:38 [29262] DBG:core:receive_msg: cleaning up
Apr 17 08:32:44 [29262] DBG:core:tcp_receive_timeout: 0xb610c728 expired
(31, 32) lt=0
Apr 17 08:32:44 [29262] DBG:core:io_watch_del: io_watch_del (0x81a2ea0, 13,
-1, 0x10) fd_no=2 called
Apr 17 08:32:44 [29262] DBG:core:release_tcpconn:  releasing con 0xb610c728,
state 0, fd=13, id=2
Apr 17 08:32:44 [29262] DBG:core:release_tcpconn:  extra_data 0xb6109548
Apr 17 08:32:44 [29271] DBG:core:handle_tcp_child: reader response=
b610c728, 0 from 0
Apr 17 08:32:44 [29271] DBG:core:io_watch_add: io_watch_add(0x81a2d40, 19,
2, 0xb610c728), fd_no=13
Apr 17 08:32:44 [29271] DBG:core:handle_tcp_child: cmd CONN_RELEASE
0xb610c728 refcnt= 0
Apr 17 08:32:46 [29271] DBG:core:handle_tcpconn_ev: data available on
0xb60e26c4 18
Apr 17 08:32:46 [29271] DBG:core:io_watch_del: io_watch_del (0x81a2d40, 18,
-1, 0x0) fd_no=14 called
Apr 17 08:32:46 [29271] DBG:core:send2child: to tcp child 0 0(29262),
0xb60e26c4
Apr 17 08:32:46 [29262] DBG:core:handle_io: received n=4 con=0xb60e26c4,
fd=13
Apr 17 08:32:46 [29262] DBG:core:io_watch_add: io_watch_add(0x81a2ea0, 13,
2, 0xb60e26c4), fd_no=1
Apr 17 08:32:46 [29262] DBG:core:tls_update_fd: New fd is 13
Apr 17 08:32:46 [29262] DBG:core:_tls_read: 4 bytes read
Apr 17 08:32:46 [29262] DBG:core:tcp_read_req: content-length= 0
Apr 17 08:32:46 [29262] DBG:core:tcp_send: tcp connection found
(0xb60e26c4), acquiring fd
Apr 17 08:32:46 [29262] DBG:core:tcp_send: c= 0xb60e26c4, n=8
Apr 17 08:32:46 [29271] DBG:core:handle_ser_child: read response= b60e26c4,
1, fd -1 from 4 (29262)
Apr 17 08:32:46 [29262] DBG:core:tcp_send: after receive_fd: c= 0xb60e26c4
n=4 fd=14
Apr 17 08:32:46 [29262] DBG:core:tcp_send: sending...
Apr 17 08:32:46 [29262] DBG:core:tls_update_fd: New fd is 14
Apr 17 08:32:46 [29262] DBG:core:tls_write: write was successful (2 bytes)
Apr 17 08:32:46 [29262] DBG:core:tcp_send: after write: c= 0xb60e26c4 n=2
fd=14
Apr 17 08:32:46 [29262] DBG:core:tcp_send: buf=


Apr 17 08:32:52 [29262] DBG:core:tls_update_fd: New fd is 13
Apr 17 08:32:52 [29262] DBG:core:_tls_read: 543 bytes read
Apr 17 08:32:52 [29262] DBG:core:tcp_read_req: content-length= 2
Apr 17 08:32:52 [29262] DBG:core:parse_msg: SIP Request:
Apr 17 08:32:52 [29262] DBG:core:parse_msg:  method:  <MESSAGE>
Apr 17 08:32:52 [29262] DBG:core:parse_msg:  uri:     <sip:1000 at 20.1.1.2>
Apr 17 08:32:52 [29262] DBG:core:parse_msg:  version: <SIP/2.0>
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=2
Apr 17 08:32:52 [29262] DBG:core:parse_via_param: found param type 235,
<rport> = <n/a>; state=6
Apr 17 08:32:52 [29262] DBG:core:parse_via_param: found param type 232,
<branch> = <z9hG4bKPja09ec884d91f4b0faea630f9fbc156bf>; state=16
Apr 17 08:32:52 [29262] DBG:core:parse_via: end of header reached, state=5
Apr 17 08:32:52 [29262] DBG:core:parse_headers: via found, flags=2
Apr 17 08:32:52 [29262] DBG:core:parse_headers: this is the first via
Apr 17 08:32:52 [29262] DBG:core:receive_msg: After parse_msg...
Apr 17 08:32:52 [29262] DBG:core:receive_msg: preparing to run routing
scripts...
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=100
Apr 17 08:32:52 [29262] DBG:maxfwd:is_maxfwd_present: value = 70
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=8
Apr 17 08:32:52 [29262] DBG:core:parse_to: end of header reached, state=10
Apr 17 08:32:52 [29262] DBG:core:parse_to: display={}, ruri={
sip:1000 at 20.1.1.2}
Apr 17 08:32:52 [29262] DBG:core:get_hdr_field: <To> [21]; uri=[
sip:1000 at 20.1.1.2]
Apr 17 08:32:52 [29262] DBG:core:get_hdr_field: to body [<sip:1000 at 20.1.1.2>
]
Apr 17 08:32:52 [29262] DBG:uri:has_totag: no totag
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=78
Apr 17 08:32:52 [29262] DBG:core:get_hdr_field: cseq <CSeq>: <15905>
<MESSAGE>
Apr 17 08:32:52 [29262] DBG:tm:t_lookup_request: start searching:
hash=15450, isACK=0
Apr 17 08:32:52 [29262] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Apr 17 08:32:52 [29262] DBG:tm:t_lookup_request: no transaction found
Apr 17 08:32:52 [29262] DBG:core:parse_to_param:
tag=d5b6699b53424475b7588a272b462a3f
Apr 17 08:32:52 [29262] DBG:core:parse_to: end of header reached, state=29
Apr 17 08:32:52 [29262] DBG:core:parse_to: display={}, ruri={
sip:1000 at 20.1.1.2}
Apr 17 08:32:52 [29262] DBG:core:grep_sock_info: checking if host==us: 8==8
&&  [20.1.1.2] == [20.1.1.2]
Apr 17 08:32:52 [29262] DBG:core:grep_sock_info: checking if port 5061
matches port 5060
Apr 17 08:32:52 [29262] DBG:core:check_self: host != me
Apr 17 08:32:52 [29262] DBG:core:grep_sock_info: checking if host==us: 8==8
&&  [20.1.1.2] == [20.1.1.2]
Apr 17 08:32:52 [29262] DBG:core:grep_sock_info: checking if port 5061
matches port 5060
Apr 17 08:32:52 [29262] DBG:core:check_self: host != me
Apr 17 08:32:52 [29262] DBG:registrar:lookup: setting as ruri
<sip:1000 at 10.1.1.203:3000;transport=TLS>
Apr 17 08:32:52 [29262] DBG:registrar:lookup: looking for branches
Apr 17 08:32:52 [29262] DBG:tm:t_newtran: transaction on entrance=(nil)
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=ffffffffffffffff
Apr 17 08:32:52 [29262] DBG:core:get_hdr_field: content_length=2
Apr 17 08:32:52 [29262] DBG:core:get_hdr_field: found end of header
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=78
Apr 17 08:32:52 [29262] DBG:tm:t_lookup_request: start searching:
hash=15450, isACK=0
Apr 17 08:32:52 [29262] DBG:tm:matching_3261: RFC3261 transaction matching
failed
Apr 17 08:32:52 [29262] DBG:tm:t_lookup_request: no transaction found
Apr 17 08:32:52 [29262] DBG:tm:run_reqin_callbacks: trans=0xb61056f8,
callback type 1, id 0 entered
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=78
Apr 17 08:32:52 [29262] DBG:core:mk_proxy: doing DNS lookup...
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=2000
Apr 17 08:32:52 [29262] DBG:core:build_req_buf_from_sip_req: id added:
<;i=1>, rcv proto=3
Apr 17 08:32:52 [29262] DBG:core:tcp_send: no open tcp connection found,
opening new one
Apr 17 08:32:52 [29262] DBG:core:print_ip: tcpconn_new: new tcp connection
to: 10.1.1.203
Apr 17 08:32:52 [29262] DBG:core:tcpconn_new: on port 3000, type 3
Apr 17 08:32:52 [29262] DBG:core:tls_tcpconn_init: entered: Creating a whole
new ssl connection
Apr 17 08:32:52 [29262] DBG:core:tls_tcpconn_init: name based TLS client
domains are disabled
Apr 17 08:32:52 [29262] DBG:core:tls_tcpconn_init: no TLS client doman AVP
set, looking for socket based TLS client domain
Apr 17 08:32:52 [29262] DBG:core:tls_find_client_domain: virtual TLS client
domain not found, Using default TLS client domain settings
Apr 17 08:32:52 [29262] DBG:core:tls_tcpconn_init: found socket based TLS
client domain [0.0.0.0:0]
Apr 17 08:32:52 [29262] DBG:core:tls_tcpconn_init: Setting in CONNECT mode
(client)
Apr 17 08:32:52 [29262] DBG:core:tcp_send: sending...
Apr 17 08:32:52 [29262] DBG:core:tls_update_fd: New fd is 14
Apr 17 08:32:52 [29271] DBG:core:handle_ser_child: read response= b612b9c0,
2, fd 20 from 4 (29262)
Apr 17 08:32:52 [29271] DBG:core:tcpconn_add: hashes: 690, 3
Apr 17 08:32:52 [29271] DBG:core:io_watch_add: io_watch_add(0x81a2d40, 20,
2, 0xb612b9c0), fd_no=13
Apr 17 08:32:52 [29271] DBG:core:handle_tcpconn_ev: data available on
0xb612b9c0 20
Apr 17 08:32:52 [29271] DBG:core:io_watch_del: io_watch_del (0x81a2d40, 20,
-1, 0x0) fd_no=14 called
Apr 17 08:32:52 [29271] DBG:core:send2child: to tcp child 1 0(29263),
0xb612b9c0
Apr 17 08:32:52 [29262] ERROR:core:tls_connect: SSL_ERROR_SYSCALL
err=Success(0)
Apr 17 08:32:52 [29262] ERROR:core:tls_connect: something wrong in SSL: 5
(ret=0) err=Success(0)
Apr 17 08:32:52 [29262] DBG:core:tcp_send: after write: c= 0xb612b9c0 n=-1
fd=14
Apr 17 08:32:52 [29262] DBG:core:tcp_send: buf=
MESSAGE sip:1000 at 10.1.1.203:3000;transport=TLS SIP/2.0
Via: SIP/2.0/TLS 20.1.1.2:5061;branch=z9hG4bKa5c3.13a1e574.0;i=1
Via: SIP/2.0/TLS 10.1.1.203:1788
;received=10.1.1.203;rport=1788;branch=z9hG4bKPja09ec884d91f4b0faea630f9fbc156bf
Max-Forwards: 69
From: <sip:1000 at 20.1.1.2>;tag=d5b6699b53424475b7588a272b462a3f
To: <sip:1000 at 20.1.1.2>
Call-ID: 51c2a37a3a914ccb9189f2b9b2e4870a
CSeq: 15905 MESSAGE
Accept: text/plain, application/im-iscomposing+xml
Contact: <sip:1000 at 10.1.1.203:3000;transport=TLS>
User-Agent: QjSimple 0.6.5 (pjproject 1.5.5/win32)
Route: <sip:20.1.1.2;transport=tls;lr>
Content-Type: text/plain
Content-Length:     2

ds
Apr 17 08:32:52 [29262] ERROR:core:tcp_send: failed to send
Apr 17 08:32:52 [29262] ERROR:tm:msg_send: tcp_send failed
Apr 17 08:32:52 [29262] ERROR:tm:t_forward_nonack: sending request failed
Apr 17 08:32:52 [29262] DBG:tm:t_relay_to: t_forward_nonack returned error
Apr 17 08:32:52 [29262] DBG:core:parse_headers: flags=ffffffffffffffff
Apr 17 08:32:52 [29262] DBG:core:check_ip_address: params 10.1.1.203,
10.1.1.203, 0
Apr 17 08:32:52 [29262] DBG:core:_shm_resize: resize(0) called
Apr 17 08:32:52 [29262] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Apr 17 08:32:52 [29262] DBG:tm:insert_timer_unsafe: [2]: 0xb6105740 (45)
Apr 17 08:32:52 [29262] DBG:core:tcp_send: tcp connection found
(0xb60e26c4), acquiring fd
Apr 17 08:32:52 [29262] DBG:core:tcp_send: c= 0xb60e26c4, n=8
Apr 17 08:32:52 [29271] DBG:core:handle_ser_child: read response= b612b9c0,
-2, fd -1 from 4 (29262)
Apr 17 08:32:52 [29271] DBG:core:tcpconn_destroy: delaying (0xb612b9c0,
flags 0002) ...
Apr 17 08:32:52 [29271] DBG:core:handle_ser_child: read response= b60e26c4,
1, fd -1 from 4 (29262)
Apr 17 08:32:52 [29262] DBG:core:tcp_send: after receive_fd: c= 0xb60e26c4
n=4 fd=14
Apr 17 08:32:52 [29262] DBG:core:tcp_send: sending...
Apr 17 08:32:52 [29262] DBG:core:tls_update_fd: New fd is 14
Apr 17 08:32:52 [29262] DBG:core:tls_write: write was successful (389 bytes)
Apr 17 08:32:52 [29262] DBG:core:tcp_send: after write: c= 0xb60e26c4 n=389
fd=14
Apr 17 08:32:52 [29262] DBG:core:tcp_send: buf=
SIP/2.0 477 Send failed (477/TM)
Via: SIP/2.0/TLS 10.1.1.203:1788
;rport=1788;branch=z9hG4bKPja09ec884d91f4b0faea630f9fbc156bf
From: <sip:1000 at 20.1.1.2>;tag=d5b6699b53424475b7588a272b462a3f
To: <sip:1000 at 20.1.1.2>;tag=a8259f3b076366b731c5bbc891fa8843-4ced
Call-ID: 51c2a37a3a914ccb9189f2b9b2e4870a
CSeq: 15905 MESSAGE
Server: OpenSIPS (1.6.4-2-tls (i386/linux))
Content-Length: 0


both the clients are directly connected to the server and there is no
NAT.This is the first time I am trying opensips with TLS(I am using version
1.6) any help would be  appreciated.I am also attaching my config file

Regards
Chandra Shekar S
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20110413/487a9624/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: opensips.cfg
Type: application/octet-stream
Size: 11194 bytes
Desc: not available
URL: <http://lists.opensips.org/pipermail/users/attachments/20110413/487a9624/attachment-0001.obj>