Opened 6 years ago

Closed 4 years ago

#385 closed Bug / Defect (worksforme)

Regression: 2.3.3 windows client fails with arm server 2.3.3

Reported by: tlhackque Owned by: Steffan Karger
Priority: major Milestone: release 2.3.9
Component: Generic / unclassified Version: OpenVPN 2.3.2 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords: cross-build arm
Cc:

Description

This reports a regression with 2.3.3 on the server side of a tunnel. Also, push-peer-info is not working with a build from git master.

I gave up on cross-building for RPI, put a disk on the system temporarily & native built 2.3.3. [It normally runs only from flash; logging is remote syslog.] Exact build procedure follows summary.

The linux machines got the openssl patch before the switch to 2.3.3 on the server. The server's openssl is 1.0.1e-2+rvt+deb7u6 (This has the heartbeat vulnerability patch.)

Prior to this, the RPI (server) ran 2.2.1-8+deb7u2 and successfully accepted connections from a remote linux system and a local windows system. After updating the windows system to 2.3.3, it continued to work with 2.2.1.

After updating the server to 2.3.3, it successfully accepts a connection from a remote Linux client (2.3.2, details below). The tunnel comes up, pings work both ways, data flows.

However, connections from the windows system fail. The failure is reported on the client side:

TLS_ERROR: BIO read tls_read_plaintext error: error:04066083:rsa routines:RSA_EAY_PRIVATE_ENCRYPT:invalid message length: error:14099006:SSL routines:SSL3_SEND_CLIENT_VERIFY:EVP lib
TLS Error: TLS object -> incoming plaintext read error
TLS Error: TLS handshake failed

It would be nice if this error was reported to the GUI, not just burried in the log.

The server side just has the usual:

TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)

I also built the server from git master (OpenVPN 2.3_git [git:master/60b40a58c4caaeb5] ) with no change in symptoms.

NB: With the git build, I expected to push-peer-info in the server connect script, but it does not appear in the environment. The push-peer-info directive is present in both the server and the (otherwise successful) linux client.

Let me know what I can do to help troubleshoot this. Details follow.

Thanks.

Server version:

openvpn --version

OpenVPN 2.3.3 arm-unknown-linux-gnueabihf [SSL (OpenSSL)] [LZO] [EPOLL] [MH] [IPv6] built on Apr 9 2014
Originally developed by James Yonan
Copyright (C) 2002-2010 OpenVPN Technologies, Inc. <sales@…>
Compile time defines: enable_crypto=yes enable_debug=yes enable_def_auth=yes enable_dependency_tracking=no enable_dlopen=unknown enable_dlopen_self=unknown enable_dlopen_self_static=unknown enable_fast_install=yes enable_fragment=yes enable_http_proxy=yes enable_iproute2=no enable_libtool_lock=yes enable_lzo=yes enable_lzo_stub=no enable_management=yes enable_multi=yes enable_multihome=yes enable_pam_dlopen=no enable_password_save=yes enable_pedantic=no enable_pf=yes enable_pkcs11=no enable_plugin_auth_pam=yes enable_plugin_down_root=yes enable_plugins=yes enable_port_share=yes enable_selinux=no enable_server=yes enable_shared=yes enable_shared_with_static_runtimes=no enable_small=no enable_socks=yes enable_ssl=yes enable_static=yes enable_strict=no enable_strict_options=no enable_systemd=no enable_win32_dll=yes enable_x509_alt_username=no with_crypto_library=openssl with_gnu_ld=yes with_mem_check=no with_plugindir='$(libdir)/openvpn/plugins' with_sysroot=no

Server built on RPI (debian raspbian wheezy) Started with an empty disk (but some tools on flash):

parted /dev/sda
mkfs -t ext4 -j -LBlackBox /dev/sda1
mount /dev/sda1 /mnt/hdd
mkdir /mnt/hdd/builds
cd /mnt/hdd/builds
wget http://swupdate.openvpn.org/community/releases/openvpn-2.3.3.zip
unzip openvpn-2.3.3.zip
cd openvpn-2.3.3/
apt-get install liblzo2-dev
apt-get install libpam-dev
apt-get install libssl-dev
apt-get install git

prefix=/usr ./configure --build=arm-linux-gnueabihf --prefix=/usr --includedir=${prefix}/include --mandir=${prefix}/share/man --infodir=${prefix}/share/info --sysconfdir=/etc --localstatedir=/var --libexecdir=${prefix}/lib/openvpn --disable-dependency-tracking CFLAGS="-g -O2" CPPFLAGS="" CXXFLAGS="-g -O2" FFLAGS=-"g -O2" LDFLAGS="" --enable-password-save --host=arm-linux-gnueabihf

make
make install

Client is today's windows release.

The client log - where things are XXX'd out, the length matches the live data:

Wed Apr 09 21:10:39 2014 us=68808 Current Parameter Settings:
Wed Apr 09 21:10:39 2014 us=68808 config = 'config.ovpn'
Wed Apr 09 21:10:39 2014 us=68808 mode = 0
Wed Apr 09 21:10:39 2014 us=68808 show_ciphers = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 show_digests = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 show_engines = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 genkey = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 key_pass_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 show_tls_ciphers = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 Connection profiles [default]:
Wed Apr 09 21:10:39 2014 us=68808 proto = udp
Wed Apr 09 21:10:39 2014 us=68808 local = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 local_port = 1194
Wed Apr 09 21:10:39 2014 us=68808 remote = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 remote_port = 1194
Wed Apr 09 21:10:39 2014 us=68808 remote_float = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 bind_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 bind_local = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 connect_retry_seconds = 5
Wed Apr 09 21:10:39 2014 us=68808 connect_timeout = 10
Wed Apr 09 21:10:39 2014 us=68808 connect_retry_max = 0
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_server = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_port = 0
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_retry = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu = 1500
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 link_mtu = 1500
Wed Apr 09 21:10:39 2014 us=68808 link_mtu_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_extra = 0
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_extra_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 mtu_discover_type = -1
Wed Apr 09 21:10:39 2014 us=68808 fragment = 0
Wed Apr 09 21:10:39 2014 us=68808 mssfix = 1450
Wed Apr 09 21:10:39 2014 us=68808 explicit_exit_notification = 0
Wed Apr 09 21:10:39 2014 us=68808 Connection profiles [0]:
Wed Apr 09 21:10:39 2014 us=68808 proto = udp
Wed Apr 09 21:10:39 2014 us=68808 local = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 local_port = 1194
Wed Apr 09 21:10:39 2014 us=68808 remote = 'xxxxxxxxxxxxx'
Wed Apr 09 21:10:39 2014 us=68808 remote_port = 1194
Wed Apr 09 21:10:39 2014 us=68808 remote_float = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 bind_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 bind_local = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 connect_retry_seconds = 5
Wed Apr 09 21:10:39 2014 us=68808 connect_timeout = 10
Wed Apr 09 21:10:39 2014 us=68808 connect_retry_max = 0
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_server = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_port = 0
Wed Apr 09 21:10:39 2014 us=68808 socks_proxy_retry = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu = 1500
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_defined = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 link_mtu = 1500
Wed Apr 09 21:10:39 2014 us=68808 link_mtu_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_extra = 0
Wed Apr 09 21:10:39 2014 us=68808 tun_mtu_extra_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 mtu_discover_type = -1
Wed Apr 09 21:10:39 2014 us=68808 fragment = 0
Wed Apr 09 21:10:39 2014 us=68808 mssfix = 1450
Wed Apr 09 21:10:39 2014 us=68808 explicit_exit_notification = 0
Wed Apr 09 21:10:39 2014 us=68808 Connection profiles END
Wed Apr 09 21:10:39 2014 us=68808 remote_random = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 ipchange = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 dev = 'tun'
Wed Apr 09 21:10:39 2014 us=68808 dev_type = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 dev_node = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 lladdr = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 topology = 1
Wed Apr 09 21:10:39 2014 us=68808 tun_ipv6 = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_local = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_remote_netmask = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_noexec = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_nowarn = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_ipv6_local = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_ipv6_netbits = 0
Wed Apr 09 21:10:39 2014 us=68808 ifconfig_ipv6_remote = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 shaper = 0
Wed Apr 09 21:10:39 2014 us=68808 mtu_test = 0
Wed Apr 09 21:10:39 2014 us=68808 mlock = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 keepalive_ping = 0
Wed Apr 09 21:10:39 2014 us=68808 keepalive_timeout = 0
Wed Apr 09 21:10:39 2014 us=68808 inactivity_timeout = 0
Wed Apr 09 21:10:39 2014 us=68808 ping_send_timeout = 0
Wed Apr 09 21:10:39 2014 us=68808 ping_rec_timeout = 0
Wed Apr 09 21:10:39 2014 us=68808 ping_rec_timeout_action = 0
Wed Apr 09 21:10:39 2014 us=68808 ping_timer_remote = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 remap_sigusr1 = 0
Wed Apr 09 21:10:39 2014 us=68808 persist_tun = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 persist_local_ip = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 persist_remote_ip = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 persist_key = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 passtos = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 resolve_retry_seconds = 1000000000
Wed Apr 09 21:10:39 2014 us=68808 username = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 groupname = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 chroot_dir = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 cd_dir = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 writepid = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 up_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 down_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 down_pre = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 up_restart = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 up_delay = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 daemon = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 inetd = 0
Wed Apr 09 21:10:39 2014 us=68808 log = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 suppress_timestamps = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 nice = 0
Wed Apr 09 21:10:39 2014 us=68808 verbosity = 5
Wed Apr 09 21:10:39 2014 us=68808 mute = 0
Wed Apr 09 21:10:39 2014 us=68808 status_file = 'status.txt'
Wed Apr 09 21:10:39 2014 us=68808 status_file_version = 3
Wed Apr 09 21:10:39 2014 us=68808 status_file_update_freq = 60
Wed Apr 09 21:10:39 2014 us=68808 occ = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 rcvbuf = 0
Wed Apr 09 21:10:39 2014 us=68808 sndbuf = 0
Wed Apr 09 21:10:39 2014 us=68808 sockflags = 0
Wed Apr 09 21:10:39 2014 us=68808 fast_io = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 lzo = 0
Wed Apr 09 21:10:39 2014 us=68808 route_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 route_default_gateway = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=68808 route_default_metric = 0
Wed Apr 09 21:10:39 2014 us=68808 route_noexec = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 route_delay = 5
Wed Apr 09 21:10:39 2014 us=68808 route_delay_window = 30
Wed Apr 09 21:10:39 2014 us=68808 route_delay_defined = ENABLED
Wed Apr 09 21:10:39 2014 us=68808 route_nopull = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 route_gateway_via_dhcp = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 max_routes = 100
Wed Apr 09 21:10:39 2014 us=68808 allow_pull_fqdn = DISABLED
Wed Apr 09 21:10:39 2014 us=68808 management_addr = '127.0.0.1'
Wed Apr 09 21:10:39 2014 us=68808 management_port = 25340
Wed Apr 09 21:10:39 2014 us=68808 management_user_pass = 'stdin'
Wed Apr 09 21:10:39 2014 us=78822 management_log_history_cache = 250
Wed Apr 09 21:10:39 2014 us=78822 management_echo_buffer_size = 100
Wed Apr 09 21:10:39 2014 us=78822 management_write_peer_info_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 management_client_user = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 management_client_group = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 management_flags = 6
Wed Apr 09 21:10:39 2014 us=78822 shared_secret_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 key_direction = 0
Wed Apr 09 21:10:39 2014 us=78822 ciphername_defined = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 ciphername = 'BF-CBC'
Wed Apr 09 21:10:39 2014 us=78822 authname_defined = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 authname = 'sha1'
Wed Apr 09 21:10:39 2014 us=78822 prng_hash = 'SHA1'
Wed Apr 09 21:10:39 2014 us=78822 prng_nonce_secret_len = 16
Wed Apr 09 21:10:39 2014 us=78822 keysize = 0
Wed Apr 09 21:10:39 2014 us=78822 engine = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 replay = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 mute_replay_warnings = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 replay_window = 64
Wed Apr 09 21:10:39 2014 us=78822 replay_time = 15
Wed Apr 09 21:10:39 2014 us=78822 packet_id_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 use_iv = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 test_crypto = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 tls_server = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 tls_client = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 key_method = 2
Wed Apr 09 21:10:39 2014 us=78822 ca_file = 'INLINE?'
Wed Apr 09 21:10:39 2014 us=78822 ca_path = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 dh_file = 'INLINE?'
Wed Apr 09 21:10:39 2014 us=78822 cert_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 priv_key_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 pkcs12_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 cryptoapi_cert = 'SUBJ:xxx'
Wed Apr 09 21:10:39 2014 us=78822 cipher_list = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 tls_verify = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 tls_export_cert = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 verify_x509_type = 0
Wed Apr 09 21:10:39 2014 us=78822 verify_x509_name = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 crl_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 ns_cert_type = 1
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_ku[i] = 0
Wed Apr 09 21:10:39 2014 us=78822 remote_cert_eku = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 ssl_flags = 0
Wed Apr 09 21:10:39 2014 us=78822 tls_timeout = 2
Wed Apr 09 21:10:39 2014 us=78822 renegotiate_bytes = 0
Wed Apr 09 21:10:39 2014 us=78822 renegotiate_packets = 0
Wed Apr 09 21:10:39 2014 us=78822 renegotiate_seconds = 3600
Wed Apr 09 21:10:39 2014 us=78822 handshake_window = 60
Wed Apr 09 21:10:39 2014 us=78822 transition_window = 3600
Wed Apr 09 21:10:39 2014 us=78822 single_session = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 push_peer_info = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 tls_exit = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 tls_auth_file = 'INLINE?'
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_protected_authentication = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_private_mode = 00000000
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_cert_private = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_pin_cache_period = -1
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_id = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 pkcs11_id_management = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 server_network = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 server_netmask = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 server_network_ipv6 = üó"
Wed Apr 09 21:10:39 2014 us=78822 server_netbits_ipv6 = 0
Wed Apr 09 21:10:39 2014 us=78822 server_bridge_ip = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 server_bridge_netmask = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 server_bridge_pool_start = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 server_bridge_pool_end = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_start = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_end = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_netmask = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_persist_filename = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_pool_persist_refresh_freq = 600
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_ipv6_pool_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_ipv6_pool_base = üó"
Wed Apr 09 21:10:39 2014 us=78822 ifconfig_ipv6_pool_netbits = 0
Wed Apr 09 21:10:39 2014 us=78822 n_bcast_buf = 256
Wed Apr 09 21:10:39 2014 us=78822 tcp_queue_limit = 64
Wed Apr 09 21:10:39 2014 us=78822 real_hash_size = 256
Wed Apr 09 21:10:39 2014 us=78822 virtual_hash_size = 256
Wed Apr 09 21:10:39 2014 us=78822 client_connect_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 learn_address_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 client_disconnect_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 client_config_dir = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 ccd_exclusive = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 tmp_dir = 'C:\DOCUME~1\Litt\LOCALS~1\Temp\'
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_local = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_remote_netmask = 0.0.0.0
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_ipv6_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_ipv6_local = üó"/0
Wed Apr 09 21:10:39 2014 us=78822 push_ifconfig_ipv6_remote = üó"
Wed Apr 09 21:10:39 2014 us=78822 enable_c2c = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 duplicate_cn = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 cf_max = 0
Wed Apr 09 21:10:39 2014 us=78822 cf_per = 0
Wed Apr 09 21:10:39 2014 us=78822 max_clients = 1024
Wed Apr 09 21:10:39 2014 us=78822 max_routes_per_client = 256
Wed Apr 09 21:10:39 2014 us=78822 auth_user_pass_verify_script = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 auth_user_pass_verify_script_via_file = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 client = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 pull = ENABLED
Wed Apr 09 21:10:39 2014 us=78822 auth_user_pass_file = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 show_net_up = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 route_method = 0
Wed Apr 09 21:10:39 2014 us=78822 ip_win32_defined = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 ip_win32_type = 3
Wed Apr 09 21:10:39 2014 us=78822 dhcp_masq_offset = 0
Wed Apr 09 21:10:39 2014 us=78822 dhcp_lease_time = 31536000
Wed Apr 09 21:10:39 2014 us=78822 tap_sleep = 0
Wed Apr 09 21:10:39 2014 us=78822 dhcp_options = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 dhcp_renew = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 dhcp_pre_release = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 dhcp_release = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 domain = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 netbios_scope = '[UNDEF]'
Wed Apr 09 21:10:39 2014 us=78822 netbios_node_type = 0
Wed Apr 09 21:10:39 2014 us=78822 disable_nbt = DISABLED
Wed Apr 09 21:10:39 2014 us=78822 OpenVPN 2.3.3 i686-w64-mingw32 [SSL (OpenSSL)] [LZO] [PKCS11] [IPv6] built on Apr 9 2014
Enter Management Password:
Wed Apr 09 21:10:50 2014 us=985944 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:25340
Wed Apr 09 21:10:50 2014 us=985944 Need hold release from management interface, waiting...
Wed Apr 09 21:10:51 2014 us=456620 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:25340
Wed Apr 09 21:10:51 2014 us=556764 MANAGEMENT: CMD 'state on'
Wed Apr 09 21:10:51 2014 us=556764 MANAGEMENT: CMD 'log all on'
Wed Apr 09 21:10:51 2014 us=987384 MANAGEMENT: CMD 'hold off'
Wed Apr 09 21:10:51 2014 us=997398 MANAGEMENT: CMD 'hold release'
Wed Apr 09 21:10:52 2014 us=177657 Control Channel Authentication: tls-auth using INLINE static key file
Wed Apr 09 21:10:52 2014 us=177657 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Apr 09 21:10:52 2014 us=177657 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Apr 09 21:10:52 2014 us=177657 Control Channel MTU parms [ L:1541 D:166 EF:66 EB:0 ET:0 EL:0 ]
Wed Apr 09 21:10:52 2014 us=177657 Socket Buffers: R=[8192->8192] S=[8192->8192]
Wed Apr 09 21:10:52 2014 us=187672 MANAGEMENT: >STATE:1397092252,RESOLVE,
Wed Apr 09 21:10:52 2014 us=397974 Data Channel MTU parms [ L:1541 D:1450 EF:41 EB:4 ET:0 EL:0 ]
Wed Apr 09 21:10:52 2014 us=397974 Local Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Wed Apr 09 21:10:52 2014 us=397974 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Wed Apr 09 21:10:52 2014 us=397974 Local Options hash (VER=V4): 'e1cabb67'
Wed Apr 09 21:10:52 2014 us=397974 Expected Remote Options hash (VER=V4): 'f78928cd'
Wed Apr 09 21:10:52 2014 us=397974 UDPv4 link local (bound): [undef]
Wed Apr 09 21:10:52 2014 us=397974 UDPv4 link remote: [AF_INET]192.168.134.1:1194
Wed Apr 09 21:10:52 2014 us=397974 MANAGEMENT: >STATE:1397092252,WAIT
,
Wed Apr 09 21:10:52 2014 us=508132 MANAGEMENT: >STATE:1397092252,AUTH,
Wed Apr 09 21:10:52 2014 us=508132 TLS: Initial packet from [AF_INET]192.168.148.43:1194, sid=6453fbcf a941847e
Wed Apr 09 21:10:52 2014 us=698406 VERIFY OK: depth=1, XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Wed Apr 09 21:10:52 2014 us=698406 VERIFY OK: nsCertType=SERVER
Wed Apr 09 21:10:52 2014 us=698406 VERIFY OK: depth=0, XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Wed Apr 09 21:10:52 2014 us=748478 TLS_ERROR: BIO read tls_read_plaintext error: error:04066083:rsa routines:RSA_EAY_PRIVATE_ENCRYPT:invalid message length: error:14099006:SSL routines:SSL3_SEND_CLIENT_VERIFY:EVP lib
Wed Apr 09 21:10:52 2014 us=748478 TLS Error: TLS object -> incoming plaintext read error
Wed Apr 09 21:10:52 2014 us=748478 TLS Error: TLS handshake failed
Wed Apr 09 21:10:52 2014 us=768507 TCP/UDP: Closing socket
Wed Apr 09 21:10:52 2014 us=778521 SIGUSR1[soft,tls-error] received, process restarting
Wed Apr 09 21:10:52 2014 us=778521 MANAGEMENT: >STATE:1397092252,RECONNECTING,tls-error

Wed Apr 09 21:10:52 2014 us=778521 Restart pause, 2 second(s)
Wed Apr 09 21:10:54 2014 us=801430 Control Channel Authentication: tls-auth using INLINE static key file
Wed Apr 09 21:10:54 2014 us=821459 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Apr 09 21:10:54 2014 us=841488 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Wed Apr 09 21:10:54 2014 us=841488 Control Channel MTU parms [ L:1541 D:166 EF:66 EB:0 ET:0 EL:0 ]
Wed Apr 09 21:10:54 2014 us=851502 Socket Buffers: R=[8192->8192] S=[8192->8192]
Wed Apr 09 21:10:54 2014 us=851502 MANAGEMENT: >STATE:1397092254,RESOLVE,
Wed Apr 09 21:10:54 2014 us=861516 Data Channel MTU parms [ L:1541 D:1450 EF:41 EB:4 ET:0 EL:0 ]
Wed Apr 09 21:10:54 2014 us=881545 Local Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Wed Apr 09 21:10:54 2014 us=891560 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Wed Apr 09 21:10:54 2014 us=891560 Local Options hash (VER=V4): 'e1cabb67'
Wed Apr 09 21:10:54 2014 us=901574 Expected Remote Options hash (VER=V4): 'f78928cd'
Wed Apr 09 21:10:54 2014 us=901574 UDPv4 link local (bound): [undef]
Wed Apr 09 21:10:54 2014 us=911588 UDPv4 link remote: [AF_INET]192.168.134.1:1194
Wed Apr 09 21:10:54 2014 us=911588 MANAGEMENT: >STATE:1397092254,WAIT
,
Wed Apr 09 21:10:54 2014 us=921603 MANAGEMENT: >STATE:1397092254,AUTH,
Wed Apr 09 21:10:54 2014 us=921603 TLS: Initial packet from [AF_INET]192.168.148.43:1194, sid=769c88e9 d986fb31
Wed Apr 09 21:10:55 2014 us=91848 TLS Error: Unroutable control packet received from [AF_INET]192.168.148.43:1194 (si=3 op=P_CONTROL_V1)
Wed Apr 09 21:10:55 2014 us=161948 VERIFY OK: <The sequence continues>

Server log for this connection:

[24014]: MULTI: multi_create_instance called
[24014]: 192.168.148.191:1194 Re-using SSL/TLS context
[24014]: 192.168.148.191:1194 Control Channel MTU parms [ L:1541 D:166 EF:66 EB:0 ET:0 EL:0 ]
[24014]: 192.168.148.191:1194 Data Channel MTU parms [ L:1541 D:1450 EF:41 EB:4 ET:0 EL:0 ]
[24014]: 192.168.148.191:1194 Local Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
[24014]: 192.168.148.191:1194 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
[24014]: 192.168.148.191:1194 Local Options hash (VER=V4): 'f78928cd'
[24014]: 192.168.148.191:1194 Expected Remote Options hash (VER=V4): 'e1cabb67'
[24014]: 192.168.148.191:1194 TLS: Initial packet from [AF_INET]192.168.148.191:1194, sid=d6ccd910 e3e6a2f4
[24014]: 192.168.148.191:1194 TLS: new session incoming connection from [AF_INET]192.168.148.191:1194
[24014]: 192.168.148.191:1194 TLS: new session incoming connection from [AF_INET]192.168.148.191:1194
[24014]: 192.168.148.191:1194 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
[24014]: 192.168.148.191:1194 TLS Error: TLS handshake failed
[24014]: 192.168.148.191:1194 SIGUSR1[soft,tls-error] received, client-instance restarting


Client config:


verb 1
verb 5
cryptoapicert "SUBJ:XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"
dev tun
proto udp
ns-cert-type server
pull
tls-client
cipher BF-CBC
reneg-sec 3600
push-peer-info
status status.txt
status-version 3
ping-timer-rem
auth sha1
float
<connection>
# Only the first one is reachable in the test
remote xxx 1194 udp
remote yyy 1194 udp
</connection>
<dh>
xx
</dh>
<tls-auth>
# 2048 bit OpenVPN static key
</tls-auth>
# Can CA come from the crypto API?
<ca>
xxx
</ca>


server config


verb 1
cd /etc/openvpn
script-security 2
dev tun
proto udp
float
port 1194
topology subnet
keepalive 300 600
ping-timer-rem
management 127.0.0.1 1195
mode server
tls-server
ca ca-cert.pem
dh dh1024.pem
cert server.0.pem
key private.pem
cipher BF-CBC
reneg-sec 3600
tls-auth tls-auth.key
#push tun-ipv6
push-peer-info
push "topology subnet"
push "persist-key"
push "persist-tun"
ifconfig 192.168.134.1 255.255.255.0
ifconfig-pool 192.168.134.50 192.168.134.254 255.255.255.0
push "route-gateway 192.168.134.1"
push "route 192.168.0.0 255.255.0.0"
push "route 172.16.0.0 255.240.0.0"
push "route 10.0.0.0 255.0.0.0"
push "dhcp-option DOMAIN xxxxxxxxxxxxxxxx."
push "dhcp-option DNS 192.168.148.6"
push "dhcp-option DNS 192.168.148.4"
push "dhcp-option DNS 192.168.134.6"
push "dhcp-option WINS 192.168.148.21"
push "dhcp-option NBT 2"
push "dhcp-option NTP 192.168.148.43"
push "dhcp-option NTP 192.168.148.10"
push "dhcp-option NTP 192.168.148.136"
client-to-client
client-config-dir clients
ccd-exclusive
client-connect client-connect
opt-verify
auth sha1


Server CCD for this client:


push "register-dns"


The server build from git:
apt-get install autoconf autoconf-doc libtool automake m4 gettext libsnappy-dev

git clone git://openvpn.git.sourceforge.net/gitroot/openvpn/openvpn.git --depth 1

autoreconf -vi

(same configure, make, make install)

Change History (13)

comment:1 Changed 6 years ago by Gert Döring

Keywords: cross-build arm added

Well, I'm a bit confused now. Is the server running 2.3.3 or git master?

2.3.3 will not print the push-peer-info values in the log, that's something added in git master *only* (because the change was fairly intrusive and that stuff doesn't go into 2.3.x right in the middle of a "maintenance" branch).

We're not regularily testing OpenVPN on ARM, so it might be possible that something sneaked in (but it could as well be something in your build environment, etc. - so to be sure it's a regression in 2.3.3, you'd need to build a 2.2.1 version on the PI, and see if that works - if that doesn't work either, it's something in the build). I'll see whether I can find time to test this on one of my boxes.

comment:2 Changed 6 years ago by tlhackque

Sorry for the confusion; I tried to provide all relevant data.

Let me try to summarize:

Server Client Client
RPI Fedora Windows Result
2.2.1-8+deb7u2 - 2.3.2 OK
2.2.1-8+deb7u2 2.3.2 - OK
2.2.1-8+deb7u2 - 2.3.3 OK
OpenSSL patch - no change
2.3.3 2.3.2 - OK
2.3.3 - 2.3.3 FAILS
master 2.3.2 - OK
master - 2.3.3 FAILS

The Fedora and Windows machines don't connect to each-other (but when the tunnels came up, they could talk).

Summary: Windows 2.3.3 client fails with ARM 2.3.3 and ARM git master server.

Windows 2.3.3 client works with ARM 2.2.1 server.

The 2.2.1 version on the Pi came from the debian repo (as indicated by the version.)

The 2.3.3 and git masters were built by me - as shown above. I suppose the packager may have patched something; I did not.

Since then, I have downloaded the 2.2.1 repo patches from "http://mirrordirector.raspbian.org/raspbian/ wheezy/main openvpn 2.2.1-8+deb7u2". The ones that looked as though they might bear on this are already in master.

I will try to build from the unmodified (2.2.1 from your downloads page) sources and see if anything changes. It will take a while; I'll report back either way.

The push-peer-info is something that I wanted on the servers client-connect script, which is the main reason I built the server from git. Specifically, I need to push --register-dns to windows clients, but not others. No other way to tell clients apart (same cert for dual-boot machines.)

With respect to the keyword - 'cross-build' - I did not cross-build. I tried, but failed. Too many dependency hassles.

All results are from native build on the Pi.q

comment:3 Changed 6 years ago by Gert Döring

Mmmh. There is something new in 2.3.3 as compared to 2.3.2, and that is the TLS version negotiation change - which could explain why 2.3.2 -> PI works, and 2.3.3 -> PI fails.

In general, we know that 2.3.3 -> git master works (using that on a number of production systems), but we haven't tested on ARM. Could be an issue in the OpenSSL build (-> new TLS stuff -> break with 2.3.3 or git master), could be something not properly architecture-clean.

You could test if it's that by checking out git master and reverting 4b67f9849ab3efe89268e01afddc7795f38d0f64

comment:4 Changed 6 years ago by tlhackque

Portability is always fun. OpenSSL is used by a lot of other code (webservers, etc). I didn't build it; just used what's in the repo (=openssl_1.0.1e-2+rvt+deb7u6). So while I don't rule an openssl issue out, it wouldn't be my build. And I expect that the owner ran the regression tests. (Among the patches in the distro is something for heartbleed; I have not investigated.)

Progress:

I tried to revert that commit, but won a revert conflict in src/openvpn/ssl_openssl.c, shown below. I resolved as shown below.

Now the server validates the client certificate. New failure:

Mon Apr 14 14:41:12 2014 us=169594 192.168.148.191:1194 TLS Auth Error: --client-config-dir authentication failed for common name 'First Last' file='clients/First Last' # < **** Note space in file name
WWWWRRRRMon Apr 14 14:41:12 2014 us=230230 192.168.148.191:1194 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Mon Apr 14 14:41:12 2014 us=231839 192.168.148.191:1194 [First Last] Peer Connection Initiated with [AF_INET]192.168.148.191:1194
RMon Apr 14 14:41:14 2014 us=301006 192.168.148.191:1194 PUSH: Received control message: 'PUSH_REQUEST'
Mon Apr 14 14:41:14 2014 us=302520 192.168.148.191:1194 Delayed exit in 5 seconds
Mon Apr 14 14:41:14 2014 us=304771 192.168.148.191:1194 SENT CONTROL [First Last]: 'AUTH_FAILED' (status=1)
WWWRMon Apr 14 14:41:16 2014 us=497846 192.168.148.191:1194 TLS Error: Cannot accept new session request from [AF_INET]192.168.148.191:1194 due to session context expire or --single-session [2]
RMon Apr 14 14:41:18 2014 us=981485 192.168.148.191:1194 TLS Error: Cannot accept new session request from [AF_INET]192.168.148.191:1194 due to session context expire or --single-session [2]
Mon Apr 14 14:41:20 2014 us=46461 192.168.148.191:1194 SIGTERM[soft,delayed-exit] received, client-instance exiting


The name in the certificate has a space. The client config filename should (and does with prior OpenVPN) have the space replaced by "_". With git.master it does not. See first line of log extract above.

I added a softlink from "First Last" to "First_Last".

The tunnel comes up.

Summary:
Old issue: Something in the TLS negotiation causes the server to send a bad packet. Reverting the version negotiation 'solves' that issue. Still need to get to root cause.

New issue: Server's translation from Client CN to config file name is different.

Also, note that in the log (that I posted above) the error is "Invalid message length". We can see that the client gets and validates the server certificate. The error seems to be an async read while sending the client verify (cert). The server reports the initial packet only. So the server is unhappy, and probably is spitting out some objection that's not logged.

If there's a way to get the TLS stream into something wireshark can decode, we'd probably see where things are going wrong pretty easily.

void
tls_ctx_set_options (struct tls_root_ctx *ctx, unsigned int ssl_flags)
{
  ASSERT(NULL != ctx);

#if 0
<<<<<<< HEAD
  /* process SSL options including minimum TLS version we will accept from peer */
  {
    long sslopt = SSL_OP_SINGLE_DH_USE | SSL_OP_NO_TICKET | SSL_OP_NO_SSLv2 | SSL_OP_NO_SSLv3;
    const int tls_version_min = (ssl_flags >> SSLF_TLS_VERSION_SHIFT) & SSLF_TLS_VERSION_MASK;
    if (tls_version_min > TLS_VER_1_0)
      sslopt |= SSL_OP_NO_TLSv1;
#ifdef SSL_OP_NO_TLSv1_1
    if (tls_version_min > TLS_VER_1_1)
      sslopt |= SSL_OP_NO_TLSv1_1;
#endif
#ifdef SSL_OP_NO_TLSv1_2
    if (tls_version_min > TLS_VER_1_2)
      sslopt |= SSL_OP_NO_TLSv1_2;
#endif
    SSL_CTX_set_options (ctx->ctx, sslopt);
  }

=======
>>>>>>> parent of 4b67f98... TLS version negotiation
#endif
  SSL_CTX_set_session_cache_mode (ctx->ctx, SSL_SESS_CACHE_OFF);
#if 0
  SSL_CTX_set_options (ctx->ctx, SSL_OP_SINGLE_DH_USE);
#else
  SSL_CTX_set_options (ctx->ctx, SSL_OP_SINGLE_DH_USE | SSL_OP_NO_TICKET | SSL_OP_NO_SSLv2 | SSL_OP_NO_SSLv3);
#endif
  SSL_CTX_set_default_passwd_cb (ctx->ctx, pem_password_callback);

  /* Require peer certificate verification */
#if P2MP_SERVER

comment:5 Changed 6 years ago by tlhackque

One bug found:

The version negotiation problem is caused by what looks like a partial reversed patch in the commit that you referenced: the ssl context was being setup for v23 rather than TLS1.

Here is a patch that corrects the problem for me:

diff --git a/src/openvpn/ssl_openssl.c b/src/openvpn/ssl_openssl.c
index 0b63e26..0785ce4 100644
--- a/src/openvpn/ssl_openssl.c
+++ b/src/openvpn/ssl_openssl.c
@@ -98,10 +98,10 @@ tls_ctx_server_new(struct tls_root_ctx *ctx)
 {
   ASSERT(NULL != ctx);

-  ctx->ctx = SSL_CTX_new (SSLv23_server_method ());
+  ctx->ctx = SSL_CTX_new (TLSv1_server_method ());

   if (ctx->ctx == NULL)
-    msg (M_SSLERR, "SSL_CTX_new SSLv23_server_method");
+    msg (M_SSLERR, "SSL_CTX_new TLSv1_server_method");
 }

 void
@@ -109,10 +109,10 @@ tls_ctx_client_new(struct tls_root_ctx *ctx)
 {
   ASSERT(NULL != ctx);

-  ctx->ctx = SSL_CTX_new (SSLv23_client_method ());
+  ctx->ctx = SSL_CTX_new (TLSv1_client_method ());

   if (ctx->ctx == NULL)
-    msg (M_SSLERR, "SSL_CTX_new SSLv23_client_method");
+    msg (M_SSLERR, "SSL_CTX_new TLSv1_client_method");
 }

 void

Don't know why the commit's change works in other environments but not here; since both SSL_CTX and the *_*_method functions belong to OpenSSL, it's probably their code.

Since we always reject v2 & v3 (using the options value), I don't see any harm in initializing for TLS - 'why' is of academic interest. Initializing for V23 should advertise V2 & V3 for compatibility and accept V2 and V3 client hellos, but then the options we select cause v2 and v3 to be rejected. So setting up to accept the V2/V3 hellos doesn't buy us anything - we know it has to be OpenVPN on the other end. So we might as well work-around the issue on the OpenVPN side.

I've looked at the cert name issue - see the next comment.

(Updated to make the error message match the initialization method and clarify the explanation.)

Last edited 6 years ago by tlhackque (previous) (diff)

comment:6 Changed 6 years ago by tlhackque

Client config filename changes:

The change that breaks finding clients with spaces (and other stuff) in their CNs appears to be in commit https://community.openvpn.net/openvpn/changeset/9885f57e3ac8d2e32ba20ca84f6bdd0a1a995eac/, which decided to allow more characters (for Unix, all but '/') in a 'safe' filename. (openvpn/misc.c gen_path()).

This is probably a good thing - though perhaps the Unix restrictions are a bit loose. Names of '.', '..', my.host.example.net: might be problematic, if valid corner cases.

In any case, anyone with client config files that contain special characters is going to have to rename their files. And if they have to drop back a server version for any reason, rename them again. Or use my trick of soft linking.

This is rather a pain; note that reversing the mapping doesn't work, as any underscore in a filename could be: (a) just an underscore or (b) a translation of any of the previously disallowed characters.

It would have been better for there to be a compatibility option that looks first for the new mapping, then falls back to the old filename with a warning. multi.c:1653 would seem to be the place.

Up to you to decide if it's too late for that - but at least a warning in the release notes is in order. 'client config' does not appear anywhere in the release notes...

As I'm a new user, I'll just go with the flow; I'm not motivated to create a patch for this.

comment:7 Changed 6 years ago by Steffan Karger

This issue is still under investigation and discussed on the mailinglist. For other people ending up here: changing the SSLv23_{client,server}_method () calls back to TLSv1_{client,server}_method () will resolve the issue, but remove support for TLSv1.1 and TLSv1.2 (yes, in OpenSSL-lingo SSLv23 actually means 'autonegotiate', and TLSv1 means 'force TLSv1.0').

A less restrictive patch would be to add the SSL_OP_NO_TLSv1_2 flag to sslopt, that would still allow you to use TLSv1.1.

In the mean time, we'll have to keep digging to find the real culprit.

comment:8 Changed 6 years ago by Gert Döring

Milestone: release 2.4

2.3.4 will have the "do not do tls version negotiation by default" fix (one version or the other). The real milestone to fix this "for good" is 2.4 -> setting trac milestone so it's easier to see what is still open for 2.3.x

Thanks for the analysis so far!

comment:9 Changed 5 years ago by Steffan Karger

Owner: set to Steffan Karger
Status: newaccepted

I suspect the negotiation issues have been fixed by now. I'll accept the ticket to get it on my to-do list for testing.

The remapping stuff I'm not very familiar with, but its going on my list for testing too.

comment:10 Changed 5 years ago by Steffan Karger

Milestone: release 2.4release 2.3.8

2.3 *did* get default tls negotiation after all, so moving this back to a 2.3 milestone.

comment:11 Changed 5 years ago by Gert Döring

Milestone: release 2.3.8release 2.3.9

comment:12 Changed 4 years ago by Gert Döring

2.3.9 or new milestone? I assume your testing list is long, so "2.3.11" it is...?

comment:13 Changed 4 years ago by Steffan Karger

Resolution: worksforme
Status: acceptedclosed

Ok, let's just get this over with. I just tested OpenVPN 2.3.8 on Windows 7 and git-master on Linux against git-master, 2.3.8 and 2.3.3 on Debian jessie on a raspberry pi 2. Everything plays together nicely. So not sure if this was some specific OpenSSL bug, some too-strict firewall in between, or what. Either case, seems to work just fine. Closing this ticket now. If you still experience problems, just reopen the ticket.

Note: See TracTickets for help on using tickets.