search

OpenVPN / openvpn3-linux

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

Fail to connect - crypto_alg: SHA*: bad digest for data channel use #220

Closed sid-the-sloth closed 9 months ago

sid-the-sloth commented 9 months ago

Describe the bug OpenVPN3 gets stuck in opening a session.

Running openvpn3, on Debian 12 bookworm, installed from the repo as described in https://community.openvpn.net/openvpn/wiki/OpenVPN3Linux.

$ openvpn3 version
OpenVPN3/Linux v21 (openvpn3)
OpenVPN core v3.8.2 linux x86_64 64-bit
Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.

To Reproduce

Imported connection with:

$ openvpn3 config-import --config /etc/openvpn/my-connection.ovpn --persistent

Trying to open session with:

$ openvpn3 session-start --config /etc/openvpn/my-connection.ovpn

The connection cannot be established, getting errors (in journalctl) such

g_object_unref: assertion 'G_IS_OBJECT (object)' failed

as seen below:

# journalctl --since today -u dbus | less +G

Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967556]: OpenVPN3/Linux v21 (openvpn3-service-backendstart)
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967556]: OpenVPN core v3.8.2 linux x86_64 64-bit
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967556]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Attached: {tag:1838831745448410381}  [:1.6809/net.openvpn.v3.backends], pid 3967556
Nov 15 12:28:18 machine-name dbus-daemon[1025]: [system] Successfully activated service 'net.openvpn.v3.backends'
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967560]: Re-initiated process from pid 3967560 to backend process pid 3967561
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967561]: OpenVPN3/Linux v21 (openvpn3-service-client)
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967561]: OpenVPN core v3.8.2 linux x86_64 64-bit
Nov 15 12:28:18 machine-name net.openvpn.v3.backends[3967561]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Attached: {tag:2898027044471729836}  [:1.6810/net.openvpn.v3.backends], pid 3967561
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Attached: {tag:16977099851477502325}  [:1.6810/net.openvpn.v3.sessions], pid 3967561
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Assigned session /net/openvpn/v3/sessions/feab0ea1scd88s4733s998cs0f06a0306ab2 to {tag:2898027044471729836}
Nov 15 12:28:18 machine-name dbus-daemon[1025]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.6810' (uid=125 pid=3967561 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien")
Nov 15 12:28:18 machine-name dbus-daemon[1025]: [system] Successfully activated service 'org.freedesktop.hostname1'
Nov 15 12:28:18 machine-name dbus-daemon[1025]: [system] Activating service name='net.openvpn.v3.netcfg' requested by ':1.6810' (uid=125 pid=3967561 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") (using servicehelper)
Nov 15 12:28:18 machine-name net.openvpn.v3.netcfg[3967573]: Loading configuration file: /var/lib/openvpn3/netcfg.json
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Attached: {tag:11965320258772559404}  [:1.6812/net.openvpn.v3.netcfg], pid 3967573
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: Attached: {tag:516827528801123380}  [:1.6812/net.openvpn.v3.netcfg.core], pid 3967573
Nov 15 12:28:18 machine-name net.openvpn.v3.netcfg[3967573]: OpenVPN3/Linux v21 (openvpn3-service-netcfg)
Nov 15 12:28:18 machine-name net.openvpn.v3.netcfg[3967573]: OpenVPN core v3.8.2 linux x86_64 64-bit
Nov 15 12:28:18 machine-name net.openvpn.v3.netcfg[3967573]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Nov 15 12:28:18 machine-name dbus-daemon[1025]: [system] Successfully activated service 'net.openvpn.v3.netcfg'
Nov 15 12:28:18 machine-name openvpn3-service-logger[3966148]: {tag:11965320258772559404} Redirect method: host-route

Nov 15 12:28:19 machine-name openvpn3-servic[3967561]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Nov 15 12:28:19 machine-name dbus-daemon[1025]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.6810" (uid=125 pid=3967561 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.6799" (uid=125 pid=3966164 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Nov 15 12:28:19 machine-name openvpn3-servic[3967561]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Nov 15 12:28:19 machine-name dbus-daemon[1025]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.6810" (uid=125 pid=3967561 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.6799" (uid=125 pid=3966164 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")

Expected behavior I expect it to connect. Same connection file works with OpenVPN2 client.

Version information (please complete the following information):

sid-the-sloth commented 9 months ago

Here's another extract from journalctl log, where the same error is visible:

g_object_unref: assertion 'G_IS_OBJECT (object)' failed

# journalctl --since today -u dbus | less +G

Nov 27 19:35:58 clio net.openvpn.v3.backends[810582]: OpenVPN3/Linux v21 (openvpn3-service-backendstart)
Nov 27 19:35:58 clio net.openvpn.v3.backends[810582]: OpenVPN core v3.8.2 linux x86_64 64-bit
Nov 27 19:35:58 clio net.openvpn.v3.backends[810582]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Nov 27 19:35:58 clio openvpn3-service-logger[805652]: Attached: {tag:12314003913594311452}  [:1.296/net.openvpn.v3.backends], pid 810582
Nov 27 19:35:58 clio dbus-daemon[952]: [system] Successfully activated service 'net.openvpn.v3.backends'
Nov 27 19:35:58 clio net.openvpn.v3.backends[810586]: Re-initiated process from pid 810586 to backend process pid 810587
Nov 27 19:35:58 clio net.openvpn.v3.backends[810587]: OpenVPN3/Linux v21 (openvpn3-service-client)
Nov 27 19:35:58 clio net.openvpn.v3.backends[810587]: OpenVPN core v3.8.2 linux x86_64 64-bit
Nov 27 19:35:58 clio net.openvpn.v3.backends[810587]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Nov 27 19:35:58 clio openvpn3-service-logger[805652]: Attached: {tag:13733231549266446319}  [:1.297/net.openvpn.v3.backends], pid 810587
Nov 27 19:35:58 clio openvpn3-service-logger[805652]: Attached: {tag:4341702196981159518}  [:1.297/net.openvpn.v3.sessions], pid 810587
Nov 27 19:35:58 clio openvpn3-service-logger[805652]: Assigned session /net/openvpn/v3/sessions/2481afe2sa5afs4168saddesb9af5ee23880 to {tag:13733231549266446319}
Nov 27 19:35:58 clio dbus-daemon[952]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.297' (uid=116 pid=810587 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien")
Nov 27 19:35:59 clio dbus-daemon[952]: [system] Successfully activated service 'org.freedesktop.hostname1'
Nov 27 19:36:03 clio openvpn3-servic[810587]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Nov 27 19:36:03 clio dbus-daemon[952]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.297" (uid=116 pid=810587 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.287" (uid=116 pid=805648 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Nov 27 19:36:04 clio openvpn3-service-logger[805652]: Detached: {tag:12314003913594311452}  [:1.296/net.openvpn.v3.backends], pid 810582
Nov 27 19:36:10 clio openvpn3-servic[810587]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Nov 27 19:36:10 clio dbus-daemon[952]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.297" (uid=116 pid=810587 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.287" (uid=116 pid=805648 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Nov 27 19:36:10 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Cleaning up resources for PID 810587.
Nov 27 19:36:10 clio openvpn3-service-logger[805652]: {tag:13733231549266446319} Starting connection
Nov 27 19:36:10 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Socket protect called for socket 8, remote: '99.99.99.99', tun: '', ipv6: no
Nov 27 19:36:10 clio openvpn3-service-logger[805652]: {tag:13733231549266446319} Connecting
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Virtual device '8ca9d391tf15dt4615ta07ct122b449b27c5' registered on /net/openvpn/v3/netcfg/810587_8ca9d391tf15dt4615ta07ct122b449b27c5 (owner uid 116, owner pid 810587)
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding IP Address 192.168.20.3/24 gw 192.168.20.1 ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Setting remote IP address to 99.99.99.99 ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '172.20.20.0/22' excl: no ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '10.0.6.0/24' excl: no ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '192.168.0.0/24' excl: no ipv6: no
Nov 27 19:36:14 clio dbus-daemon[952]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.11' (uid=0 pid=982 comm="/usr/sbin/NetworkManager --no-daemon")

Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding IP Address 192.168.20.3/24 gw 192.168.20.1 ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Setting remote IP address to 99.99.99.99 ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '172.20.20.0/22' excl: no ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '10.0.6.0/24' excl: no ipv6: no
Nov 27 19:36:13 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '192.168.0.0/24' excl: no ipv6: no
Nov 27 19:36:14 clio dbus-daemon[952]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.11' (uid=0 pid=982 comm="/usr/sbin/NetworkManager --no-daemon")
Nov 27 19:36:14 clio dbus-daemon[952]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Nov 27 19:36:15 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Socket protect called for socket 8, remote: '99.99.99.99', tun: 'tun0', ipv6: no
Nov 27 19:36:16 clio openvpn3-service-logger[805652]: {tag:13733231549266446319} Connecting
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Device 'tun0' was removed by openvpn
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Virtual device '8ca9d391tf15dt4615ta07ct122b449b27c5' registered on /net/openvpn/v3/netcfg/810587_8ca9d391tf15dt4615ta07ct122b449b27c5 (owner uid 116, owner pid 810587)
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding IP Address 192.168.20.6/24 gw 192.168.20.1 ipv6: no
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Setting remote IP address to 99.99.99.99 ipv6: no
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '172.20.20.0/22' excl: no ipv6: no
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '10.0.6.0/24' excl: no ipv6: no
Nov 27 19:36:19 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '192.168.0.0/24' excl: no ipv6: no
Nov 27 19:36:21 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Socket protect called for socket 8, remote: '99.99.99.99', tun: 'tun1', ipv6: no
Nov 27 19:36:21 clio openvpn3-service-logger[805652]: {tag:13733231549266446319} Connecting
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Device 'tun1' was removed by openvpn
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Virtual device '8ca9d391tf15dt4615ta07ct122b449b27c5' registered on /net/openvpn/v3/netcfg/810587_8ca9d391tf15dt4615ta07ct122b449b27c5 (owner uid 116, owner pid 810587)
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding IP Address 192.168.20.7/24 gw 192.168.20.1 ipv6: no
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Setting remote IP address to 99.99.99.99 ipv6: no
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '172.20.20.0/22' excl: no ipv6: no
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '10.0.6.0/24' excl: no ipv6: no
Nov 27 19:36:24 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Adding network '192.168.0.0/24' excl: no ipv6: no
Nov 27 19:36:26 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Socket protect called for socket 8, remote: '99.99.99.99', tun: 'tun0', ipv6: no
Nov 27 19:36:26 clio openvpn3-service-logger[805652]: {tag:13733231549266446319} Connecting
Nov 27 19:36:27 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Device 'tun0' was removed by openvpn
Nov 27 19:36:27 clio openvpn3-service-logger[805652]: {tag:10454780607822074100} Virtual device '8ca9d391tf15dt4615ta07ct122b449b27c5' registered on /net/openvpn/v3/netcfg/810587_8ca9d391tf15dt4615ta07ct122b449b27c5 (owner uid 116, owner pid 810587)
dsommers commented 9 months ago

Can you please increase the log levels to 6 (aka debug level) in both the logger service and the client config?

For the log service:

# openvpn3-admin log-service --log-level 6

The client config depends on how you start it. If you have used the openvpn3 config-import first, then you need to use this command:

$ openvpn3 config-manage --show --config MY_CONFIG_NAME --log-level 6

Otherwise you need to modify the .conf or .ovpn configuration file by replacing (or adding, if not present) the verb line to say:

verb 6

While the g_object_unref: assertion 'G_IS_OBJECT (object)' failed error is indeed a concern, it shouldn't be critical or fatal. For the v22_dev release, the whole D-Bus implementation is being refactored and improved. I hope to see all of these issues being resolved once that overhaul has completed.

Also, please use the openvpn3-admin journal command to extract the log data. This gives an easier and more precise log extraction from the systemd-journal for debugging connectivity issues. The line below should give you all log events from today:

# openvpn3-admin journal --since $(date +%F)
sid-the-sloth commented 9 months ago

@dsommers thanks for the instructions, i did exactly as advised.

here are the log lines obtained with openvpn3-admin journal:

Sat Dec  9 17:02:53 2023  Logger INFO: OpenVPN3/Linux v21 (openvpn3-service-logger)
               OpenVPN core v3.8.2 linux x86_64 64-bit
               Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Sat Dec  9 17:02:53 2023  Logger INFO: Log method: journald
Wed Jan 19 03:01:49 586524  OpenVPN3/Linux v21 (openvpn3-service-logger)
Wed Jan 19 03:01:49 586524  OpenVPN core v3.8.2 linux x86_64 64-bit
Wed Jan 19 03:01:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 03:01:49 586524  Log method: journald
Sat Dec  9 17:02:53 2023  Logger INFO: Idle exit set to 10 minutes
Sat Dec  9 17:02:53 2023  Logger VERB2: Attached: {tag:10461731494224564534}  [:1.156/net.openvpn.v3.configuration], pid 33745
Sat Dec  9 17:03:08 2023  {tag:10461731494224564534} Config Manager INFO: Parsed persistent configuration '/etc/openvpn/my-connection-name.ovpn', owner: my-linux-username
Sat Dec  9 17:03:08 2023  {tag:10461731494224564534} Config Manager INFO: Setting configuration override 'persist-tun' to 'true' by UID 1000
Sat Dec  9 17:03:41 2023  Logger VERB1: Log level changed to 6
Sat Dec  9 17:05:18 2023  {tag:10461731494224564534} Config Manager INFO: Setting configuration override 'log-level' to '6' by UID 1000
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:2190583007369179227}  [:1.172/net.openvpn.v3.sessions], pid 36216
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:9889426595076885858}  [:1.173/net.openvpn.v3.backends], pid 36221
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:8934332292885703780}  [:1.174/net.openvpn.v3.backends], pid 36226
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:17926422311906097132}  [:1.174/net.openvpn.v3.sessions], pid 36226
Sat Dec  9 17:06:56 2023  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/5ae2d83ds7981s4b01sbd24s76d72847e25e to {tag:8934332292885703780}
Sat Dec  9 17:06:56 2023  {tag:8934332292885703780} Client VERB1: Configuration override 'log-level' set to '6'
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:7651041941399916206}  [:1.176/net.openvpn.v3.netcfg], pid 36237
Sat Dec  9 17:06:56 2023  Logger VERB2: Attached: {tag:336107471703487772}  [:1.176/net.openvpn.v3.netcfg.core], pid 36237
Sat Dec  9 17:06:56 2023  {tag:336107471703487772} Network Configuration DEBUG: OpenVPN 3 Core library logging initialized
Sat Dec  9 17:06:56 2023  {tag:7651041941399916206} Network Configuration VERB1: Redirect method: host-route
Sat Dec  9 17:07:02 2023  Logger VERB2: Detached: {tag:9889426595076885858}  [:1.173/net.openvpn.v3.backends], pid 36221
Sat Dec  9 17:07:08 2023  {tag:7651041941399916206} Network Configuration INFO: Cleaning up resources for PID 36226.
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client INFO: Starting connection
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client VERB1: Username/password provided successfully for 'my-username'
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Using DNS resolver scope: global
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: [Connect] DCO flag: disabled
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: OpenVPN core v3.8.2 linux x86_64 64-bit OVPN-DCO
Sat Dec  9 17:07:08 2023  {tag:2190583007369179227} Session Manager VERB2: Starting connection
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Frame=512/2112/512 mssfix-ctrl=1250
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: NOTE: This configuration contains options that were not used:
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Unsupported option (ignored)
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: 8 [persist-key]
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: 9 [persist-tun]
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: 11 [mute] [20]
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: 20 [explicit-exit-notify] [2]
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client VERB2: Resolving
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Contacting 100.100.100.100:443 via UDP
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client VERB1: Waiting for server response
Sat Dec  9 17:07:08 2023  {tag:7651041941399916206} Network Configuration INFO: Socket protect called for socket 8, remote: '100.100.100.100', tun: '', ipv6: no
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Connecting to [100.100.100.100]:443 (100.100.100.100) via UDP
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client INFO: Connecting
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Tunnel Options:V4,dev-type tun,link-mtu 1569,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA256,keysize 256,key-method 2,tls-client
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Creds: Username/Password
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Sending Peer Info:
               IV_VER=v3.8.2
               IV_PLAT=linux
               IV_NCP=2
               IV_TCPNL=1
               IV_PROTO=990
               IV_MTU=1600
               IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
               IV_GUI_VER=OpenVPN3/Linux/v21
               IV_SSO=openurl,webauth,crtext
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: VERIFY OK: depth=1, /O=WatchGuard_Technologies/OU=Fireware/CN=Fireware SSLVPN (SN 80130872EEC3D 2021-06-07 15:42:10 UTC) CA, signature: RSA-SHA256
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: VERIFY OK: depth=0, /O=WatchGuard_Technologies/OU=Fireware/CN=Fireware SSLVPN Server, signature: RSA-SHA256
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: SSL Handshake: peer certificate: CN=Fireware SSLVPN Server, 2048 bit RSA, cipher: ECDHE-RSA-CHACHA20-POLY1305    TLSv1.2 Kx=ECDH     Au=RSA   Enc=CHACHA20/POLY1305(256) Mac=AEAD
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Session is ACTIVE
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client VERB2: Retrieving configuration from server
Sat Dec  9 17:07:08 2023  {tag:8934332292885703780} Client DEBUG: Sending PUSH_REQUEST to server...
Sat Dec  9 17:07:09 2023  {tag:8934332292885703780} Client DEBUG: Sending PUSH_REQUEST to server...
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: Sending PUSH_REQUEST to server...
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: OPTIONS:
               0 [route] [172.20.20.0] [255.255.252.0]
               1 [route] [10.0.6.0] [255.255.255.0]
               2 [route] [192.168.0.0] [255.255.255.0]
               3 [dhcp-option] [DOMAIN] [remote-domain.local]
               4 [dhcp-option] [DNS] [172.20.20.10]
               5 [dhcp-option] [DNS] [172.20.20.8]
               6 [route-gateway] [192.168.20.1]
               7 [topology] [subnet]
               8 [ping] [10]
               9 [ping-restart] [60]
               10 [ifconfig] [192.168.20.4] [255.255.255.0]
               11 [peer-id] [2]
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: PROTOCOL OPTIONS:
                 cipher: AES-256-CBC
                 digest: SHA256
                 key-derivation: OpenVPN PRF
                 compress: NONE
                 peer ID: 2
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Virtual device 'e9ccd27ctde2et4599tab90t7c0e8044e4f6' registered on /net/openvpn/v3/netcfg/36226_e9ccd27ctde2et4599tab90t7c0e8044e4f6 (owner uid 116, owner pid 36226)
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Adding IP Address 192.168.20.4/24 gw 192.168.20.1 ipv6: no
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Setting remote IP address to 100.100.100.100 ipv6: no
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client VERB2: Session name: '100.100.100.100'
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Adding network '172.20.20.0/22' excl: no ipv6: no
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Adding network '10.0.6.0/24' excl: no ipv6: no
Sat Dec  9 17:07:11 2023  {tag:7651041941399916206} Network Configuration INFO: Adding network '192.168.0.0/24' excl: no ipv6: no
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: TunPersist: saving tun context:
               Session Name: 100.100.100.100
               Layer: OSI_LAYER_3
               Remote Address: 100.100.100.100
               Tunnel Addresses:
                 192.168.20.4/24 -> 192.168.20.1
               Reroute Gateway: IPv4=0 IPv6=0 flags=[ IPv4 ]
               Block IPv4: no
               Block IPv6: no
               Add Routes:
                 172.20.20.0/22
                 10.0.6.0/24
                 192.168.0.0/24
               Exclude Routes:
               DNS Servers:
                 172.20.20.10
                 172.20.20.8
               Search Domains:
                 remote-domain.local
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: Connected via tun
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: Client exception in transport_recv: crypto_alg: SHA256: bad digest for data channel use
Sat Dec  9 17:07:11 2023  {tag:8934332292885703780} Client DEBUG: Client terminated, restarting in 2000 ms...

After this it just repeats all over, and hangs in the terminal, have to kill the process.

Thanks for the help!

dsommers commented 9 months ago

Alright, this gives much better hints. So the issue here is related to the SSL/TLS configuration.

 Client DEBUG: Client exception in transport_recv: crypto_alg: SHA256: bad digest for data channel use

This smells like an inconsistency between the OpenVPN server configuration and your local configuration profile. Can you try to comment out the auth SHA256 line in your config? If it's a recent enough OpenVPN server, the client and server should figure out the best settings here on their own. If it still fails; which OpenVPN server are you running?

sid-the-sloth commented 9 months ago

Well... this is the VPN for a company I work for... While it works fine with OpenVPN v2, I can't really tell them to change the config for me, when nobody else has issues with it. You can see from the log they are running a WatchGuard Fireware VPN server.

I will try to comment that line out in the client config and report back.

sid-the-sloth commented 9 months ago

Removed the line auth SHA256 from the *.ovpn config file, removed and re-added the config using openvpn3 config-remove and openvpn3 config-import, and the line with the error changed to this:

Client DEBUG: Client exception in transport_recv: crypto_alg: SHA1: bad digest for data channel use
dsommers commented 9 months ago

Hmmm ... alright, that begins to smell like a bug in the OpenVPN 3 Core library. Would you be willing to share (feel free to use mail) your configuration file? This would need some more testing of the configuration profile. Keying material and remote lines can be removed.

sid-the-sloth commented 9 months ago

Here's one clue that I think will help you: the last Debian package of openvpn3 client that worked for me with this connection and server was version 16~beta+bullseye -- you search the commits right after and you should be able to find the bug introduced before the next version (17~beta) was released.

Until then, here is my .ovpn file, stripped of some specifics:

dev tun
client
proto udp
<ca>
-----BEGIN CERTIFICATE-----
...
-----END CERTIFICATE-----
</ca>
<cert>
-----BEGIN CERTIFICATE-----
...
-----END CERTIFICATE-----
</cert>
<key>
-----BEGIN PRIVATE KEY-----
...
-----END PRIVATE KEY-----
</key>
remote-cert-eku "TLS Web Server Authentication"
remote 100.100.100.100 443
persist-key
persist-tun
verb 3
mute 20
keepalive 10 60
cipher AES-256-CBC
auth SHA256
float
reneg-sec 28800
nobind
mute-replay-warnings
auth-user-pass
explicit-exit-notify 2
tls-version-min 1.2
;remember_connection 1
;auto_reconnect 1

Appreciate your work and the help!

schwabe commented 9 months ago

You probably do not have the enableNonPreferredDCAlgorithms (not sure how openvpn3-linux exactly calls it) option enabled. Without that option openvpn3 will refuse CBC and SHA as data channel ciphers.

Looks like the option is called --enable-legacy-algorithms

dsommers commented 9 months ago

@schwabe I'm a bit puzzled here ... when did auth SHA256 with CBC ciphers (in particular AES-CBC) become a legacy algorithm?

schwabe commented 9 months ago

OpenVPN 3 Linux is the only OpenVPN software that calls them legacy algorithms. The other software and internally we just call them non-preferred (enableNonPreferredDCAlgorithms internally) algorithms as we only supports the newer AEAD algorithms by default in 2.6.x and DCO implementation also only supports the AEAD algorithms.

We also have "true" legacy algorithms that include MD5, DES, 3DES and BF-CBC that are enabled by enableLegacyAlgorithms internally.

dsommers commented 9 months ago

Duh! Right, I see the error here now. Alright, yeah, I see that OpenVPN 3 Linux classifies all non-AEAD as legacy. In hindsight, that might not have been the right decisions in commit ff944ec0678951. But it's probably not something which should be changed too hastily - to ensure we don't weaken already configured installs.

schwabe commented 9 months ago

You could rename the option and keep the --enable-legacy-algorithms as hidden compat option.

sid-the-sloth commented 9 months ago

Okay, this knowledge is gold, but it is hidden for the user because the error message says nothing that helps the user.

I've removed and re-added the connection, then enabled the "legacy" algorithms:

$ openvpn3 config-manage --show --config /etc/openvpn/my-connection.ovpn --enable-legacy-algorithms true

As a user and a developer, I would like to suggest two things, you do what you think is best of course:

  1. do a better job at setting the defaults (in this case, if "legacy" works with OpenVPN v2, it should have stayed enabled);
  2. describe the error with a proper message so the user knows what is going on -- in this case, there is no indication that user might want to enable so-called "legacy" algorithms.

Thank you for your time, my issue is now resolved, but there might be other (Linux) users out there missing out on this fine software.

schwabe commented 9 months ago

Unless you are using very old OpenVPN 2 version older than 2.4.0, you do not need that option. All 2.4.0+ OpenVPN 2.x versions will try to negotiate to AES-GCM by default.

But yeah we can probably extend the error message that this algorithm might be disabled.

sid-the-sloth commented 9 months ago

@schwabe On Debian 12 bookworm -- openvpn v2 is at version 2.6.3 and it works just fine with my config and remote server.

schwabe commented 9 months ago

@sid-the-sloth unless you manually fiddle with data-ciphers on OpenPVN 2.6.x will also not support AES-CBC on the data channel as well. You might wnat to post your openvpn 2.x log to double check that.

Also the log you have in https://github.com/OpenVPN/openvpn3-linux/issues/220#issuecomment-1848765578 does not show the server pushing a --cipher option but a --peer-id so that looks like either some wacky implementation or disabling cipher negotiation with --ncp-disable

dsommers commented 9 months ago

Yeah, I agree that this is not a good user experience. And we need to look into how to improve that. However, if an OpenVPN 2.4 or 2.5 server is deployed with --ncp-disable - that disables all the negotiations expected to happen ... which is there to avoid such situations as here. The server would see a client supporting AES-GCM (which is better, especially in regards to performance) and then upgrade the cipher from AES-CBC. And then this wouldn't be seen as an issue.

When the OpenVPN Data Channel Offload (DCO, ovpn-dco) kernel module is in use, only AEAD ciphers will be in use. And since that has potential to give much higher throughput speed than the traditional tun interface (which stagnates around 2-3Gbit/s), that's where we're moving towards. And since OpenVPN 3 Linux is newer with a very different configuration setup, it is in a position where it can require some updates on the defaults. It's way too long since commit ff944ec067 got pulled in to remember all the reasons. The option itself is not really well named, but the intension was exactly as described - to move the "defaults" to higher standards (AEAD, disabling compression support, etc) which would then make it work smoothly out-of-the-box with DCO.

The option should have been called something like --enable-non-aead-algos or something along those lines, instead of --enable-legacy-algorithms; as @schwabe points out, BF-CBC and that class of ciphers and MD5 hashing are the true legacy algorithms. But enabling non-AEAD ciphers by default by default is not the best move forward to achieve an upgrade of defaults. What can be considered is to provide some warnings when importing a configuration profile and warn about options needing additional settings to work. A very simple foilware illustration:

$ openvpn3 config-import --config my-config.ovpn
WARNING: This configuration file includes settings which is known to cause issues
WARNING:  --cipher AES-256-CBC    <--  This is not an AEAD cipher, DCO will not work
WARNING:  --auth SHA256           <--  DCO will not work
WARNING:  --comp-lzo              <--  Compression is deprecated; DCO will not work
WARNING:  See the openvpn3-config-manage man page for enabling support for these options.
[....]
$

This is not something which will come too soon, but something to consider for a future release.

JFTR, since this turned out to not be a bug - but a configuration issue; I'll convert this discussion into a GH discussion instead of GH issue.