[OpenSIPS-Users] TLS handshake failing

Wed Jan 21 17:07:50 CET 2015

Hi all, I'm trying to set up opensips with TLS enabled. I followed the webnair to install opensips and the advanced tutorial about TLS. Everything seems to be configured correctly but when I try to register using TLS it fails. I tried both latest LTS version and the master version of opensips, Bria and Linphone softphones and the default and customized TLS certificates. For all tests I got this log:

Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:probe_max_sock_buff: getsockopt: snd is initially 262142
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: INFO:core:probe_max_sock_buff: using snd buffer of 255 kb
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: INFO:core:init_sock_keepalive: -- TCP keepalive enabled on socket
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:print_ip: tcpconn_new: new tcp connection to: 192.168.14.26
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tcpconn_new: on port 50853, type 3
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_tcpconn_init: entered: Creating a whole new ssl connection
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_tcpconn_init: looking up socket based TLS server domain [192.168.14.23:5061]
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_find_server_domain: virtual TLS server domain not found, Using default TLS server domain settings
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_tcpconn_init: found socket based TLS server domain [0.0.0.0:0]
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_tcpconn_init: Setting in ACCEPT mode (server)
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tcpconn_add: hashes: 613, 3
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:handle_new_connect: new connection: 0x7f3aeafa9eb8 25 flags: 0002
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:send2child: to tcp child 0 0(3314), 0x7f3aeafa9eb8 rw 1
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:handle_io: We have received conn 0x7f3aeafa9eb8 with rw 1
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:io_watch_add: io_watch_add op on 20 (0x84d120, 20, 2, 0x7f3aeafa9eb8,1), fd_no=1
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_update_fd: New fd is 20
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: Using the global ( per process ) buff
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_update_fd: New fd is 20
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:tls_accept: New TLS connection from 192.168.14.26:50853 accepted
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_accept: new TLS connection from 192.168.14.26:50853 using TLSv1/SSLv3 AES256-SHA 256
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_accept: local socket: 192.168.14.23:5061
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:tls_accept: Client did not present a TLS certificate
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:tls_dump_cert_info: tls_accept: local TLS server certificate subject: /C=XY/ST=Some State/O=My Large Organization Name/OU=My Subunit of Large Organization/CN=somename.somewhere.com/emailAddress=root at somename.somewhere.com, issuer: /CN=Your_NAME/ST=Your_STATE/C=CO/emailAddress=YOUR_EMAIL/O=YOUR_ORG_NAME
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_update_fd: New fd is 20
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: read= 0 bytes, parsed=0, state=0, error=1
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: last char=0x00, parsed msg=#012
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: We didn't manage to read a full request. Back to child poll
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: tcp_read_req end
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: Using the per connection buff
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_update_fd: New fd is 20
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:_tls_read: TLS connection to 192.168.14.26:50853 closed cleanly
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: read= 0 bytes, parsed=0, state=0, error=1
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: last char=0x00, parsed msg=#012
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: EOF
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:io_watch_del: io_watch_del op on index -1 20 (0x84d120, 20, -1, 0x10,0x3) fd_no=2 called
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:release_tcpconn:  releasing con 0x7f3aeafa9eb8, state -1, fd=20, id=3
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:release_tcpconn:  extra_data 0x7f3aeafaa038
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:handle_tcp_child: reader response= 7f3aeafa9eb8, -1 from 0
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tcpconn_destroy: destroying connection 0x7f3aeafa9eb8, flags 0002
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_close: closing TLS connection
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_update_fd: New fd is 25
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_shutdown: shutdown successful
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3318]: DBG:core:tls_tcpconn_clean: entered

So it seems the TLS connection was accepted:

Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:tls_accept: New TLS connection from 192.168.14.26:50853 accepted
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_accept: new TLS connection from 192.168.14.26:50853 using TLSv1/SSLv3 AES256-SHA 256

But then some error occurs and the connection is closed:

Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: We didn't manage to read a full request. Back to child poll
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: tcp_read_req end
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tcp_read_req: Using the per connection buff
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: DBG:core:tls_update_fd: New fd is 20
Jan 20 15:41:27 devmachine /usr/local/opensips/sbin/opensips[3314]: INFO:core:_tls_read: TLS connection to 192.168.14.26:50853 closed cleanly

Any help is appreciated. Thanks.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20150121/fc81aa79/attachment-0001.htm>