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

[sid-the-sloth]

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):

• OS: Debian 12 bookworm
• OpenVPN version: OpenVPN3/Linux v21 (openvpn3), OpenVPN core v3.8.2 linux x86_64 64-bit

[sid-the-sloth]

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]

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]

@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]

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]

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]

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]

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]

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]

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]

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

[schwabe]

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]

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 ff944ec. But it's probably not something which should be changed too hastily - to ensure we don't weaken already configured installs.