search

OpenVPN / openvpn3-linux

OpenVPN 3 Linux client
GNU Affero General Public License v3.0
569 stars 152 forks source link

Version 17 beta2 focal cant connect on Ubuntu 20. Loop/Retrying connection with no failure. #103

Closed mattc321 closed 2 years ago

mattc321 commented 2 years ago

After upgrading, client attempts to connect over and over with no failure. Hangs and repeats connecting. Tried with dco feature, similar results. Tried with --enable-legacy-algorithms true, no change.

Related issues: #91 #94 #102

Workaround fix: downgrade to version 16

sudo apt remove --purge openvpn3
sudo apt install openvpn3=16~beta+focal
#remove and reimport configs if needed
openvpn3 config-remove --config CONFIG_NAME
openvpn3 config-import --config CONFIG_FILE --name CONFIG_NAME

Version and System Info

Ubuntu 20.04
17~beta2+focal
OpenVPN 3/Linux v17_beta (openvpn3)
OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit
Linux ubbi 5.15.11-76051511-generic #202112220937~1640185481~20.04~b3a2c21~dev-Ubuntu SMP Mon Jan 3  x86_64 x86_64 x86_64 GNU/Linux
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.3 LTS"
NAME="Ubuntu"
VERSION="20.04.3 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 20.04.3 LTS"
VERSION_ID="20.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal

Client Config

client
dev tun
proto tcp
remote ---- 443
tls-remote "----"
route remote_host 255.255.255.255 net_gateway
resolv-retry infinite
nobind
persist-key
persist-tun
ca ----.crt
cert ----.user.crt
key ----.user.key
auth-user-pass
cipher AES-128-CBC
auth SHA1
comp-lzo
route-delay 4
verb 3
reneg-sec 0
push "redirect-gateway def1"

Without dco or weak ciphers config

Name: fieldworks
Read only: No
Persistent config: Yes
Data Channel Offload: No

Overrides: 
persist-tun: true

log

Jan 22 07:24:03 ubbi dbus-daemon[818]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.92' (uid=128 pid=4972 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-") (using servicehelper)
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10891]: OpenVPN 3/Linux v17_beta (openvpn3-service-backendstart)
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10891]: OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10891]: Copyright (C) 2012-2020 OpenVPN Inc. All rights reserved.
Jan 22 07:24:03 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:9889426595076885858}  [:1.173/net.openvpn.v3.backends]
Jan 22 07:24:03 ubbi dbus-daemon[818]: [system] Successfully activated service 'net.openvpn.v3.backends'
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10895]: Re-initiated process from pid 10895 to backend process pid 10896
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10896]: OpenVPN 3/Linux v17_beta (openvpn3-service-client)
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10896]: OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit
Jan 22 07:24:03 ubbi net.openvpn.v3.backends[10896]: Copyright (C) 2012-2020 OpenVPN Inc. All rights reserved.
Jan 22 07:24:03 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:8934332292885703780}  [:1.174/net.openvpn.v3.backends]
Jan 22 07:24:03 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:17926422311906097132}  [:1.174/net.openvpn.v3.sessions]
Jan 22 07:24:05 ubbi openvpn3-servic[10896]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jan 22 07:24:08 ubbi openvpn3-servic[10896]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jan 22 07:24:08 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Cleaning up resources for PID 10896.
Jan 22 07:24:08 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Starting connection
Jan 22 07:24:08 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: '', ipv6: no
Jan 22 07:24:09 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting
Jan 22 07:24:09 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Detached: {tag:9889426595076885858}  [:1.173/net.openvpn.v3.backends]
Jan 22 07:24:12 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Virtual device '1b19398ft4612t4a3bt937bt4ab1d4b55f7b' registered on /net/openvpn/v3/netcfg/10896_1b19398ft4612t4a3bt937bt4ab1d4b55f7b (owner uid 128, owner pid 10896)
Jan 22 07:24:12 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Adding IP Adress 10.242.0.4/24 gw 10.242.0.1 ipv6: no
Jan 22 07:24:12 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Setting remote IP address to '---- ipv6: no
Jan 22 07:24:12 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Adding network '10.50.0.0/16' excl: no ipv6: no
Jan 22 07:24:12 ubbi charon: 07[KNL] interface tun1 activated
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8002] manager: (tun1): new Tun device (/org/freedesktop/NetworkManager/Devices/26)
Jan 22 07:24:12 ubbi charon: 10[KNL] 10.242.0.4 appeared on tun1
Jan 22 07:24:12 ubbi charon: 01[KNL] fe80::a6e:4d92:2eaa:f795 appeared on tun1
Jan 22 07:24:12 ubbi systemd-udevd[10916]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8069] device (tun1): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8090] device (tun1): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8098] device (tun1): Activation: starting connection 'tun1' (9f6bd2a7-56bd-4051-b32d-cc5fd5891037)
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8099] device (tun1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8101] device (tun1): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8104] device (tun1): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8105] device (tun1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi dbus-daemon[818]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.14' (uid=0 pid=819 comm="/usr/sbin/NetworkManager --no-daemon ")
Jan 22 07:24:12 ubbi systemd[1]: Starting Network Manager Script Dispatcher Service...
Jan 22 07:24:12 ubbi dbus-daemon[818]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 22 07:24:12 ubbi systemd[1]: Started Network Manager Script Dispatcher Service.
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8233] device (tun1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8235] device (tun1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
Jan 22 07:24:12 ubbi NetworkManager[819]: <info>  [1642865052.8244] device (tun1): Activation: successful, device activated.
Jan 22 07:24:14 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: 'tun1', ipv6: no
Jan 22 07:24:14 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting
Jan 22 07:24:17 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: 'tun1', ipv6: no
Jan 22 07:24:17 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting
Jan 22 07:24:20 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: 'tun1', ipv6: no
Jan 22 07:24:20 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting
Jan 22 07:24:23 ubbi systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Jan 22 07:24:23 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: 'tun1', ipv6: no
Jan 22 07:24:23 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting
Jan 22 07:24:26 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 8, remote: '----', tun: 'tun1', ipv6: no
Jan 22 07:24:26 ubbi net.openvpn.v3.log[4956]: {tag:8934332292885703780} Client INFO: Connecting

With dco and weak ciphers enabled config

Name: fieldworks
Read only: No
Persistent config: No
Data Channel Offload: Yes

Overrides: 
persist-tun: true
enable-legacy-algorithms: true

log

Jan 22 07:31:29 ubbi dbus-daemon[818]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.92' (uid=128 pid=4972 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-") (using servicehelper)
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11367]: OpenVPN 3/Linux v17_beta (openvpn3-service-backendstart)
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11367]: OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11367]: Copyright (C) 2012-2020 OpenVPN Inc. All rights reserved.
Jan 22 07:31:29 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:16954776995141641054}  [:1.186/net.openvpn.v3.backends]
Jan 22 07:31:29 ubbi dbus-daemon[818]: [system] Successfully activated service 'net.openvpn.v3.backends'
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11371]: Re-initiated process from pid 11371 to backend process pid 11372
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11372]: OpenVPN 3/Linux v17_beta (openvpn3-service-client)
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11372]: OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit
Jan 22 07:31:29 ubbi net.openvpn.v3.backends[11372]: Copyright (C) 2012-2020 OpenVPN Inc. All rights reserved.
Jan 22 07:31:29 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:3408194204315350789}  [:1.187/net.openvpn.v3.backends]
Jan 22 07:31:29 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Attached: {tag:6091168827960353666}  [:1.187/net.openvpn.v3.sessions]
Jan 22 07:31:30 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: Ready, requester:  matt
Jan 22 07:31:30 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputQueueGetTypeGroup, requester:  matt
Jan 22 07:31:30 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputQueueCheck, requester:  matt
Jan 22 07:31:30 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputQueueFetch, requester:  matt
Jan 22 07:31:30 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputQueueFetch, requester:  matt
Jan 22 07:31:32 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputProvide, requester:  matt
Jan 22 07:31:32 ubbi openvpn3-servic[11372]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jan 22 07:31:34 ubbi slack.desktop[1988]: [01/22/22, 07:31:34:487] info: [RTM] (T0LE2M0N8) Processed 1 presence_change event(s) over 1.90ms
Jan 22 07:31:35 ubbi net.openvpn.v3.log[4956]: Logger VERB2: Detached: {tag:16954776995141641054}  [:1.186/net.openvpn.v3.backends]
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: UserInputProvide, requester:  matt
Jan 22 07:31:39 ubbi openvpn3-servic[11372]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: Ready, requester:  matt
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager DEBUG: Session operation: Connect, requester:  matt
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Cleaning up resources for PID 11372.
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:3408194204315350789} Client INFO: Starting connection
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Session Manager VERB2: Starting connection
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Client INFO: Starting connection
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Virtual device 'bd97fc8at0b19t4394t8a1bt9c773377aff3' registered on /net/openvpn/v3/netcfg/11372_bd97fc8at0b19t4394t8a1bt9c773377aff3 (owner uid 128, owner pid 11372)
Jan 22 07:31:39 ubbi net.openvpn.v3.netcfg[4987]: net_iface_new: add tun type ovpn-dco
Jan 22 07:31:39 ubbi NetworkManager[819]: <info>  [1642865499.2989] manager: (tun): new Generic device (/org/freedesktop/NetworkManager/Devices/28)
Jan 22 07:31:39 ubbi systemd-udevd[11386]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 22 07:31:39 ubbi systemd-udevd[11386]: Using default interface naming scheme 'v245'.
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 73, remote: '----', tun: 'tun', ipv6: no
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:3408194204315350789} Client INFO: Connecting
Jan 22 07:31:39 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Client INFO: Connecting
Jan 22 07:31:43 ubbi net.openvpn.v3.netcfg[4987]: net_iface_del: del tun
Jan 22 07:31:43 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration VERB1: Device 'tun' was removed by openvpn
Jan 22 07:31:43 ubbi charon: 13[KNL] interface tun deleted
Jan 22 07:31:43 ubbi gnome-shell[1752]: Removing a network device that was not added
Jan 22 07:31:45 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Virtual device 'bd97fc8at0b19t4394t8a1bt9c773377aff3' registered on /net/openvpn/v3/netcfg/11372_bd97fc8at0b19t4394t8a1bt9c773377aff3 (owner uid 128, owner pid 11372)
Jan 22 07:31:45 ubbi net.openvpn.v3.netcfg[4987]: net_iface_new: add tun type ovpn-dco
Jan 22 07:31:45 ubbi NetworkManager[819]: <info>  [1642865505.1451] manager: (tun): new Generic device (/org/freedesktop/NetworkManager/Devices/29)
Jan 22 07:31:45 ubbi systemd-udevd[11429]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 22 07:31:45 ubbi systemd-udevd[11429]: Using default interface naming scheme 'v245'.
Jan 22 07:31:45 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 76, remote: '----', tun: 'tun', ipv6: no
Jan 22 07:31:45 ubbi net.openvpn.v3.log[4956]: {tag:3408194204315350789} Client INFO: Connecting
Jan 22 07:31:45 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Client INFO: Connecting
Jan 22 07:31:46 ubbi net.openvpn.v3.netcfg[4987]: net_iface_del: del tun
Jan 22 07:31:46 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration VERB1: Device 'tun' was removed by openvpn
Jan 22 07:31:46 ubbi charon: 07[KNL] interface tun deleted
Jan 22 07:31:46 ubbi gnome-shell[1752]: Removing a network device that was not added
Jan 22 07:31:48 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Virtual device 'bd97fc8at0b19t4394t8a1bt9c773377aff3' registered on /net/openvpn/v3/netcfg/11372_bd97fc8at0b19t4394t8a1bt9c773377aff3 (owner uid 128, owner pid 11372)
Jan 22 07:31:48 ubbi net.openvpn.v3.netcfg[4987]: net_iface_new: add tun type ovpn-dco
Jan 22 07:31:48 ubbi systemd-udevd[11458]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Jan 22 07:31:48 ubbi NetworkManager[819]: <info>  [1642865508.0989] manager: (tun): new Generic device (/org/freedesktop/NetworkManager/Devices/30)
Jan 22 07:31:48 ubbi systemd-udevd[11458]: Using default interface naming scheme 'v245'.
Jan 22 07:31:48 ubbi net.openvpn.v3.log[4956]: {tag:17660655930566863473} Network Configuration INFO: Socket protect called for socket 76, remote: '----', tun: 'tun', ipv6: no
Jan 22 07:31:48 ubbi net.openvpn.v3.log[4956]: {tag:3408194204315350789} Client INFO: Connecting
Jan 22 07:31:48 ubbi net.openvpn.v3.log[4956]: {tag:2743665183901279581} Client INFO: Connecting

Not looking for an update on this issue - just posting this in case it will help.

dsommers commented 2 years ago

Can you please provide the log output of openvpn2 --config $CONFIG_FILE --verb 6 ?

mattc321 commented 2 years ago

openvpn2 --config $CONFIG_FILE --verb 6

2022-01-24 06:05:44.703561 [STATUS] (StatusMajor.CONNECTION, StatusMinor.CFG_OK) config_path=/net/openvpn/v3/configuration/69592c61x7aa8x41c1x8343x6de28437c2ee
2022-01-24 06:05:44.703664 [LOG] Starting connection
2022-01-24 06:05:44.703722 [LOG] Username/password provided successfully for 'matt'
2022-01-24 06:05:44.703784 [LOG] Using DNS resolver scope: global
2022-01-24 06:05:44.703941 [LOG] [Connect] DCO flag: disabled
2022-01-24 06:05:44.703995 [STATUS] (StatusMajor.CONNECTION, StatusMinor.CONN_CONNECTING)
2022-01-24 06:05:44.704035 [LOG] OpenVPN core 3.git:HEAD:7765540e linux x86_64 64-bit OVPN-DCO
2022-01-24 06:05:44.704058 [LOG] Frame=512/2048/512 mssfix-ctrl=1250
2022-01-24 06:05:44.704091 [LOG] UNUSED OPTIONS
                                 9 [persist-tun]
                                 14 [verb] [6]
2022-01-24 06:05:44.704124 [LOG] Resolving
2022-01-24 06:05:44.704150 [LOG] Contacting ----:443 via TCPv4
2022-01-24 06:05:44.704165 [LOG] Waiting for server response
2022-01-24 06:05:44.787373 [LOG] Connecting to [----]:443 (----) via TCPv4
2022-01-24 06:05:44.865541 [LOG] Connecting
2022-01-24 06:05:44.865703 [STATUS] (StatusMajor.CONNECTION, StatusMinor.CONN_CONNECTING)
2022-01-24 06:05:44.865802 [LOG] Tunnel Options:V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client
2022-01-24 06:05:44.865913 [LOG] Creds: Username/Password
2022-01-24 06:05:44.866212 [LOG] Peer Info:
                                 IV_VER=3.git:HEAD:7765540e
                                 IV_PLAT=linux
                                 IV_NCP=2
                                 IV_TCPNL=1
                                 IV_PROTO=30
                                 IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
                                 IV_LZO_STUB=1
                                 IV_COMP_STUB=1
                                 IV_COMP_STUBv2=1
                                 IV_GUI_VER=OpenVPN 3/Linux v17_beta/3.git:HEAD:7765540e linux x86_64 64-bit
                                 IV_SSO=openurl,webauth
2022-01-24 06:05:45.021026 [LOG] VERIFY OK: depth=1, /C=us/L=Philadelphia/O=Fieldworks LLC/CN=Fieldworks LLC VPN CA/emailAddress=aws_fieldworks@cloudnexa.com, signature: RSA-SHA256
2022-01-24 06:05:45.021532 [LOG] VERIFY OK: depth=0, /C=us/L=Philadelphia/O=Fieldworks LLC/CN=prd-vpn-a01/emailAddress=aws_fieldworks@cloudnexa.com, signature: RSA-SHA256
2022-01-24 06:05:45.399243 [LOG] SSL Handshake: peer certificate: CN=prd-vpn-a01, 2048 bit RSA, cipher: DHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=DH       Au=RSA  Enc=AESGCM(256) Mac=AEAD
2022-01-24 06:05:45.399664 [LOG] Session is ACTIVE
2022-01-24 06:05:45.400066 [LOG] Retrieving configuration from server
2022-01-24 06:05:45.400255 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:46.399302 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:48.398816 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:48.564080 [LOG] OPTIONS:
                                 0 [route] [remote_host] [255.255.255.255] [net_gateway]
                                 1 [route-gateway] [10.242.0.1]
                                 2 [route-gateway] [10.242.0.1]
                                 3 [topology] [subnet]
                                 4 [ping] [10]
                                 5 [ping-restart] [120]
                                 6 [route] [10.50.0.0] [255.255.0.0]
                                 7 [ifconfig] [10.242.0.3] [255.255.255.0]
2022-01-24 06:05:48.564469 [LOG] PROTOCOL OPTIONS:
                                   cipher: AES-128-CBC
                                   digest: SHA1
                                   key-derivation: OpenVPN PRF
                                   compress: LZO_STUB
                                   peer ID: -1
2022-01-24 06:05:48.577730 [LOG] exception parsing IPv4 route: [route] [remote_host] [255.255.255.255] [net_gateway] : addr_pair_mask_parse_error: AddrMaskPair parse error 'route': remote_host/255.255.255.255 : ip_exception: error parsing route IP address 'remote_host' : Invalid argument
2022-01-24 06:05:48.579696 [LOG] Session name: '----'
2022-01-24 06:05:48.585909 [LOG] TunPersist: saving tun context:
                                 Session Name: ----
                                 Layer: OSI_LAYER_3
                                 Remote Address: ----
                                 Tunnel Addresses:
                                   10.242.0.3/24 -> 10.242.0.1
                                 Reroute Gateway: IPv4=0 IPv6=0 flags=[ IPv4 ]
                                 Block IPv4: no
                                 Block IPv6: no
                                 Add Routes:
                                   10.50.0.0/16
                                 Exclude Routes:
                                 DNS Servers:
                                 Search Domains:
2022-01-24 06:05:48.585997 [LOG] Connected via tun
2022-01-24 06:05:48.586013 [LOG] Client exception in transport_recv: crypto_alg: AES-128-CBC: bad cipher for data channel use
2022-01-24 06:05:48.586026 [LOG] Client terminated, restarting in 2000 ms...
2022-01-24 06:05:50.583694 [LOG] Contacting ----:443 via TCPv4
2022-01-24 06:05:50.583950 [LOG] Waiting for server response
2022-01-24 06:05:50.666671 [LOG] Connecting to [----]:443 (----) via TCPv4
2022-01-24 06:05:50.743938 [LOG] Connecting
2022-01-24 06:05:50.744106 [STATUS] (StatusMajor.CONNECTION, StatusMinor.CONN_CONNECTING)
2022-01-24 06:05:50.745295 [LOG] Tunnel Options:V4,dev-type tun,link-mtu 1560,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client
2022-01-24 06:05:50.745476 [LOG] Creds: Username/Password
2022-01-24 06:05:50.745588 [LOG] Peer Info:
                                 IV_VER=3.git:HEAD:7765540e
                                 IV_PLAT=linux
                                 IV_NCP=2
                                 IV_TCPNL=1
                                 IV_PROTO=30
                                 IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
                                 IV_LZO_STUB=1
                                 IV_COMP_STUB=1
                                 IV_COMP_STUBv2=1
                                 IV_GUI_VER=OpenVPN 3/Linux v17_beta/3.git:HEAD:7765540e linux x86_64 64-bit
                                 IV_SSO=openurl,webauth
2022-01-24 06:05:50.928049 [LOG] VERIFY OK: depth=1, /C=us/L=Philadelphia/O=Fieldworks LLC/CN=Fieldworks LLC VPN CA/emailAddress=aws_fieldworks@cloudnexa.com, signature: RSA-SHA256
2022-01-24 06:05:50.928181 [LOG] VERIFY OK: depth=0, /C=us/L=Philadelphia/O=Fieldworks LLC/CN=prd-vpn-a01/emailAddress=aws_fieldworks@cloudnexa.com, signature: RSA-SHA256
2022-01-24 06:05:51.296520 [LOG] SSL Handshake: peer certificate: CN=prd-vpn-a01, 2048 bit RSA, cipher: DHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=DH       Au=RSA  Enc=AESGCM(256) Mac=AEAD
2022-01-24 06:05:51.296695 [LOG] Session is ACTIVE
2022-01-24 06:05:51.296798 [LOG] Retrieving configuration from server
2022-01-24 06:05:51.296964 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:51.471833 [LOG] OPTIONS:
                                 0 [route] [remote_host] [255.255.255.255] [net_gateway]
                                 1 [route-gateway] [10.242.0.1]
                                 2 [route-gateway] [10.242.0.1]
                                 3 [topology] [subnet]
                                 4 [ping] [10]
                                 5 [ping-restart] [120]
                                 6 [route] [10.50.0.0] [255.255.0.0]
                                 7 [ifconfig] [10.242.0.3] [255.255.255.0]
2022-01-24 06:05:51.472008 [LOG] PROTOCOL OPTIONS:
                                   cipher: AES-128-CBC
                                   digest: SHA1
                                   key-derivation: OpenVPN PRF
                                   compress: LZO_STUB
                                   peer ID: -1
2022-01-24 06:05:51.472288 [LOG] TunPersist: reused tun context
2022-01-24 06:05:51.472378 [LOG] Connected via tun
2022-01-24 06:05:51.472458 [LOG] Client exception in transport_recv: crypto_alg: AES-128-CBC: bad cipher for data channel use
2022-01-24 06:05:51.472667 [LOG] Client terminated, restarting in 2000 ms...

retries...
dsommers commented 2 years ago

There are multiple issues here.

First of all, with DCO you cannot enable legacy algorithms. The ovpn-dco kernel module only supports AEAD ciphers (AES-GCM and ChaCha20-Poly1305). There are no exception here.

The log file you provide at the end has a single line which is the key issue:

Client exception in transport_recv: crypto_alg: AES-128-CBC: bad cipher for data channel use

The openpn2 front-end doesn't support changing the enable-legacy-algorithms override. But as you have done the openvpn3 config-import step, it's possible to increase the log level there and extract that without too much extra work.

  1. Increase the default log-level and enable legacy algorithms for the config profile: openvpn3 config-manage --config CONFIG_NAME --log-level 6 --enable-legacy-algorithms true --show
  2. In terminal A, start a log capture process: openvpn3 log --config CONFIG_NAME
  3. In terminal B, start the VPN session: openvpn3 session-start --config CONFIG_NAME
alexandre-lelain commented 2 years ago

Hello,

After upgrading, I had the same issue here, with the 17~beta2 version. I had to rollback to 15~beta on my Ubuntu 20.04.3 to make openvpn3 command work again:

sudo apt-get install openvpn3=15~beta+focal
dsommers commented 2 years ago

After upgrading, I had the same issue here, with the 17~beta2 version. I had to rollback to 15~beta on my Ubuntu 20.04.3 to make openvpn3 command work again:

Hi @alexandre-lelain,

It would help tremendously if you would bother enough to do the same debugging steps already discussed here in prior comments and provide log details. Rolling back two releases shouldn't be needed unless there are some real issues. And we need to understand those issues better, which requires logs.

alexandre-lelain commented 2 years ago

Hello @dsommers ,

After some investigations, it seems that enabling --enable-legacy-algorithms true in my config resolved my problem with version 17~beta2+focal.

So I guess the ssh server I'm trying to connect to does not support AEAD cipher, and that was probably a default support in versions prior to this one. Which may explain why upgrading to v17 broke my connection as the legacy algorithms were not enabled.

dsommers commented 2 years ago

@alexandre-lelain Which OS/distro is your VPN server running? And which version of OpenVPN? As of OpenVPN 2.4 on most Linux distributions, AEAD ciphers should not be a problem (you need OpenSSL 1.0.1 or newer). In addition, OpenVPN 2.4 and newer should automatically negotiate an AEAD cipher unless this mechanism has been disabled.

AEAD ciphers supported in OpenVPN today are AES-GCM and ChaCha20-Poly1305, but it requires support from the OpenSSL library as well.

If you are running an OS or Linux distribution with an OpenSSL library older than version 1.0.1 or have an OpenVPN version older than 2.4, you should upgrade.

dsommers commented 2 years ago

There are multiple issues here.

First of all, with DCO you cannot enable legacy algorithms. The ovpn-dco kernel module only supports AEAD ciphers (AES-GCM and ChaCha20-Poly1305). There are no exception here.

The log file you provide at the end has a single line which is the key issue:

Client exception in transport_recv: crypto_alg: AES-128-CBC: bad cipher for data channel use

The openpn2 front-end doesn't support changing the enable-legacy-algorithms override. But as you have done the openvpn3 config-import step, it's possible to increase the log level there and extract that without too much extra work.

1. Increase the default log-level and enable legacy algorithms for the config profile:  `openvpn3 config-manage --config CONFIG_NAME --log-level 6 --enable-legacy-algorithms true --show`

2. In terminal A, start a log capture process: `openvpn3 log --config CONFIG_NAME`

3. In terminal B, start the VPN session: `openvpn3 session-start --config CONFIG_NAME`

Hi @mattc321,

Have you had a chance to look into this?

dsommers commented 2 years ago

Closing this as it looks quite similar to #91.

Further, the server does not seem to support NCP, which would normally upgrade the tunnel to an AEAD cipher (usually AES-256-GCM). This is seen in the log snipped below; the server does not push any cipher options.

2022-01-24 06:05:45.400066 [LOG] Retrieving configuration from server
2022-01-24 06:05:45.400255 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:46.399302 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:48.398816 [LOG] Sending PUSH_REQUEST to server...
2022-01-24 06:05:48.564080 [LOG] OPTIONS:
                                 0 [route] [remote_host] [255.255.255.255] [net_gateway]
                                 1 [route-gateway] [10.242.0.1]
                                 2 [route-gateway] [10.242.0.1]
                                 3 [topology] [subnet]
                                 4 [ping] [10]
                                 5 [ping-restart] [120]
                                 6 [route] [10.50.0.0] [255.255.0.0]
                                 7 [ifconfig] [10.242.0.3] [255.255.255.0]
2022-01-24 06:05:48.564469 [LOG] PROTOCOL OPTIONS:
                                   cipher: AES-128-CBC
                                   digest: SHA1
                                   key-derivation: OpenVPN PRF
                                   compress: LZO_STUB
                                   peer ID: -1

This indicates that the AES-128-CBC cipher is kept, but the OpenSSL library does not allow this cipher as legacy ciphers are not enabled.