Installed linux client via APT per the documentation. Client continues to error out

[TheGorf]

In case anyone cares, there are several threads on the forum that are literally 2 years old full of people asking for account help. it's what brought me here, because no mods or anything are responding.

Ok, so I followed the documentation here for setting up the client on my Debian bookworm workstation. After getting the repo setup and the client installed, I have yet to be able to successfully start a session. There is a lot of similarities over in this thread but it closed without any resolution.

My commands:

$ openvpn3 config-import --config roose_vpn.ovpn
$ openvpn3 session-start --config roose_vpn.ovpn 
Using pre-loaded configuration profile 'roose_vpn.ovpn'
Session path: /net/openvpn/v3/sessions/04df3dc6sabc1s4f1fsabd8sf830d4ecc071
Auth User name: geoff
Auth Password: 
openvpn3/session-start: ** ERROR ** Failed to start the connection

So after that, I can see some logs in my user.log (I have rsyslog running):

2024-12-15T01:23:39.701438-08:00 geoff-lappy net.openvpn.v3.backends[61999]: Re-initiated process from pid 61999 to backend process pid 62000
2024-12-15T01:23:39.701993-08:00 geoff-lappy net.openvpn.v3.backends[62000]: OpenVPN3/Linux v24 (openvpn3-service-client)
2024-12-15T01:23:39.702053-08:00 geoff-lappy net.openvpn.v3.backends[62000]: OpenVPN core v3.10.4 linux x86_64 64-bit
2024-12-15T01:23:39.702107-08:00 geoff-lappy net.openvpn.v3.backends[62000]: Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
2024-12-15T01:23:39.727400-08:00 geoff-lappy openvpn3-service-log[58231]: Attached: {tag:12273027263049481468}  [:1.321/net.openvpn.v3.backends], pid 62000
2024-12-15T01:23:39.737089-08:00 geoff-lappy openvpn3-service-log[58231]: Attached: {tag:10405469118638653531}  [:1.321/net.openvpn.v3.sessions], pid 62000
2024-12-15T01:23:39.801110-08:00 geoff-lappy openvpn3-service-log[58231]: Assigned session /net/openvpn/v3/sessions/cf0fce9bs2b82s4553sb9e0s687a69208c03, interface=net.openvpn.v3.backends to {tag:12273027263049481468}
2024-12-15T01:23:47.617204-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:11691715401130759224} Cleaning up resources for PID 62000.
2024-12-15T01:23:47.623246-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:12273027263049481468} Starting connection
2024-12-15T01:23:47.643742-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:11691715401130759224} Socket protect called for socket 8, remote: 'w.x.y.z', tun: '', ipv6: no, device_path=/, device-object: missing
2024-12-15T01:23:47.677925-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:12273027263049481468} Connecting
2024-12-15T01:23:48.438398-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:11691715401130759224} Virtual device '88a89cbbte3b3t4681tb8b2tb6e29b7c3508' registered on /net/openvpn/v3/netcfg/62000_88a89cbbte3b3t4681tb8b2tb6e29b7c3508 (owner uid 117, owner pid 62000)
2024-12-15T01:23:48.452562-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:12273027263049481468} Failed configuring TUN device (TUN_SETUP_FAILED)
2024-12-15T01:23:49.256708-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:11691715401130759224} Device '88a89cbbte3b3t4681tb8b2tb6e29b7c3508' was removed by openvpn
2024-12-15T01:23:49.270697-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:11691715401130759224} Cleaning up resources for PID 62000.
2024-12-15T01:23:49.296985-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:12273027263049481468} Stopping VPN client
2024-12-15T01:23:49.317715-08:00 geoff-lappy openvpn3-service-log[58231]: Removing AttachedService object for {tag:12273027263049481468}
2024-12-15T01:23:49.317813-08:00 geoff-lappy openvpn3-service-log[58231]: Detached: {tag:12273027263049481468}  [:1.321/net.openvpn.v3.backends], pid 62000
2024-12-15T01:23:49.339084-08:00 geoff-lappy openvpn3-service-log[58231]: Removing AttachedService object for {tag:10405469118638653531}
2024-12-15T01:23:49.339285-08:00 geoff-lappy openvpn3-service-log[58231]: Detached: {tag:10405469118638653531}  [:1.321/net.openvpn.v3.sessions], pid 62000

And that's pretty much it. This is my config:

$ cat roose_vpn.ovpn 
client
dev tun
proto udp
float
nobind
cipher AES-128-CBC
comp-lzo yes
allow-compression yes
resolv-retry infinite
persist-key
auth-user-pass
remote w.x.y.z 1194
<ca>
~key stuff pruned~

Output of the admin init-config

$ sudo /usr/sbin/openvpn3-admin init-config
- Detected settings will be saved to disk? No

* Checking for OpenVPN user and group accounts
    Found:  openvpn user - uid 117
    Found:  openvpn group - gid 126

* Checking OpenVPN 3 Linux state/configuration directory
    Using directory: /var/lib/openvpn3
    Directory found

* Logger Configuration
    Configuration file: /var/lib/openvpn3/log-service.json
    systemd-journald active state: active
    :: Result ::  Will use systemd journald for logging
    !! Configuration UNCHANGED

* Network Configuration
    Configuration file: /var/lib/openvpn3/netcfg.json
    !! Could not connect to D-Bus
    Found accessible /etc/resolv.conf
    :: Result :: Will use /etc/resolv.conf
    !! Configuration UNCHANGED

* Ensuring SELinux file labels are correct
    - Could not retrieve SELinux status; skipping

I think I figured out some additional commands based on a thread over here.

$ sudo openvpn3-admin log-service --log-level 6
[sudo] password for geoff: 
                 Log method: journald
 Attached log subscriptions: 5
             Log timestamps: enabled
     Log tag prefix enabled: enabled
          Log D-Bus details: enabled
          Current log level: 6

Sun Dec 15 01:39:41 2024  Logger INFO: Log method: journald
Sun Dec 15 01:39:41 2024  Logger INFO: Idle exit set to 10 minutes
Sun Dec 15 01:39:41 2024  Logger VERB2: Attached: {tag:3785525035484998611}  [:1.69/net.openvpn.v3.sessions], pid 2864
Sun Dec 15 01:39:41 2024  {tag:3785525035484998611} Session Manager INFO: OpenVPN 3 Session Manager started
Sun Dec 15 01:39:41 2024  Logger VERB2: Attached: {tag:8660400497094378258}  [:1.71/net.openvpn.v3.configuration], pid 2874
Sun Dec 15 01:40:46 2024  {tag:8660400497094378258} Config Manager INFO: Parsed configuration 'roose_vpn.ovpn, owner: geoff
Sun Dec 15 01:40:54 2024  Logger VERB2: Attached: {tag:4042210473179141965}  [:1.76/net.openvpn.v3.backends], pid 3065
Sun Dec 15 01:40:54 2024  Logger VERB2: Attached: {tag:16910642498854420599}  [:1.77/net.openvpn.v3.backends], pid 3072
Sun Dec 15 01:40:54 2024  Logger VERB2: Attached: {tag:4905433542097237661}  [:1.77/net.openvpn.v3.sessions], pid 3072
Sun Dec 15 01:40:55 2024  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/36e02559se988s4faasa4ddsb4f56db49146, interface=net.openvpn.v3.backends to {tag:16910642498854420599}
Sun Dec 15 01:40:55 2024  Logger VERB2: Attached: {tag:1741106067448681043}  [:1.79/net.openvpn.v3.netcfg], pid 3078
Sun Dec 15 01:40:55 2024  Logger VERB2: Attached: {tag:7339746529397317625}  [:1.79/net.openvpn.v3.netcfg.core], pid 3078
Sun Dec 15 01:40:55 2024  {tag:1741106067448681043} Network Configuration VERB1: Redirect method: host-route
Sun Dec 15 01:41:03 2024  {tag:1741106067448681043} Network Configuration INFO: Cleaning up resources for PID 3072.
Sun Dec 15 01:41:03 2024  {tag:16910642498854420599} Client INFO: Starting connection
Sun Dec 15 01:41:03 2024  {tag:1741106067448681043} Network Configuration INFO: Socket protect called for socket 8, remote: '73.239.35.228', tun: '', ipv6: no, device_path=/, device-object: missing
Sun Dec 15 01:41:03 2024  {tag:16910642498854420599} Client INFO: Connecting
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Virtual device '9c821664te632t4734t9839t50adcd605ea3' registered on /net/openvpn/v3/netcfg/3072_9c821664te632t4734t9839t50adcd605ea3 (owner uid 117, owner pid 3072)
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Adding IP Address 192.168.1.46/30 gw 192.168.1.45 ipv6: no
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Setting remote IP address to 73.239.35.228 ipv6: no
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Adding network '192.168.1.0/24' excl: no ipv6: no
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Adding network '192.168.1.40/29' excl: no ipv6: no
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Adding network '192.168.1.10/32' excl: no ipv6: no
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration INFO: Adding network '192.168.1.40/29' excl: no ipv6: no
Sun Dec 15 01:41:04 2024  {tag:16910642498854420599} Client INFO: Connected: [email protected]:1194 (73.239.35.228) via /UDP on tun/192.168.1.46/ gw=[192.168.1.45/] mtu=(default)
Sun Dec 15 01:41:04 2024  {tag:16910642498854420599} Client -- ERROR --: Compression Error: server pushed compression settings that are not allowed and will result in a non-working connection. 
Sun Dec 15 01:41:04 2024  {tag:1741106067448681043} Network Configuration VERB1: Device 'tun0' was removed by openvpn
Sun Dec 15 01:41:05 2024  {tag:1741106067448681043} Network Configuration INFO: Cleaning up resources for PID 3072.
Sun Dec 15 01:41:05 2024  {tag:16910642498854420599} Client INFO: Stopping VPN client
Sun Dec 15 01:41:05 2024  Logger DEBUG: Removing AttachedService object for {tag:16910642498854420599}
Sun Dec 15 01:41:05 2024  Logger VERB2: Detached: {tag:16910642498854420599}  [:1.77/net.openvpn.v3.backends], pid 3072
Sun Dec 15 01:41:05 2024  Logger DEBUG: Removing AttachedService object for {tag:4905433542097237661}
Sun Dec 15 01:41:05 2024  Logger VERB2: Detached: {tag:4905433542097237661}  [:1.77/net.openvpn.v3.sessions], pid 3072
Sun Dec 15 01:41:54 2024  Logger DEBUG: Removing AttachedService object for {tag:4042210473179141965}
Sun Dec 15 01:41:54 2024  Logger VERB2: Detached: {tag:4042210473179141965}  [:1.76/net.openvpn.v3.backends], pid 3065
Sun Dec 15 01:42:11 2024  {tag:8660400497094378258} Config Manager INFO: Setting configuration override 'log-level' to '6' by UID 1000

The Compression error in this set of logs seems to be inconsistent. And I'm not sure why. If I retry the session, the error will go away. It seems to only do it on the first time after importing the config.

Can someone offer suggestion on what could be going on?

[dsommers]

There seems to be two issues here:

a) 2024-12-15T01:23:48.452562-08:00 geoff-lappy openvpn3-service-log[58231]: {tag:12273027263049481468} Failed configuring TUN device (TUN_SETUP_FAILED)

b) Sun Dec 15 01:41:04 2024 {tag:16910642498854420599} Client -- ERROR --: Compression Error: server pushed compression settings that are not allowed and will result in a non-working connection.

These two things should not be related. For a) the issues are often related to networking or kernel issues. But could also be related to not getting quick enough access to the openvpn3-service-netcfg service. To test if it is a slow start-up, stop all the openvpn3-service-* processes (stop the openvpn3-service-log last; killall -INT is enough and safe) and try again. Try more times to see if there's a pattern. Then try to pre-start openvpn3-service-netcfg manually as root and then try to start the VPN session afterwards.

In regards to b) - compression is not allowed by default anymore. You can try enabling "asymmetric" encryption as a workaround as well, by running openvpn3 config-manage --show --config roose_vpn.ovpn --allow-compression asym. But in general, try to move away from compression. More details here: https://community.openvpn.net/openvpn/wiki/Compression

[TheGorf]

It's clearly some sort of timing issue. Your compression recommendation definitely solved that issue. This I attempted to connect and it threw the sort of non-descript error message:

Sun Dec 15 14:28:47 2024  Logger VERB2: Attached: {tag:4391711175251893742}  [:1.98/net.openvpn.v3.backends], pid 5990
Sun Dec 15 14:28:47 2024  Logger VERB2: Attached: {tag:7092490142905028033}  [:1.98/net.openvpn.v3.sessions], pid 5990
Sun Dec 15 14:28:47 2024  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/af8d2e1ds2cf9s4b9dsab13s5275dd8d98cb, interface=net.openvpn.v3.backends to {tag:4391711175251893742}
Sun Dec 15 14:28:47 2024  {tag:4391711175251893742} Client VERB1: Configuration override 'log-level' set to '6'
Sun Dec 15 14:28:47 2024  {tag:4391711175251893742} Client VERB1: Configuration override 'allow-compression' set to 'asym'
Sun Dec 15 14:28:47 2024  {tag:4391711175251893742} Client VERB2: Assigned session path: /net/openvpn/v3/sessions/af8d2e1ds2cf9s4b9dsab13s5275dd8d98cb
Sun Dec 15 14:28:53 2024  {tag:4391711175251893742} Client INFO: Stopping VPN client
Sun Dec 15 14:28:53 2024  {tag:4391711175251893742} Client DEBUG: Stopping client mainloop
Sun Dec 15 14:28:53 2024  {tag:17334138538670274459} Session Manager VERB1: Session closing - /net/openvpn/v3/sessions/af8d2e1ds2cf9s4b9dsab13s5275dd8d98cb
Sun Dec 15 14:28:53 2024  {tag:17334138538670274459} Session Manager VERB2: Session disconnecting - /net/openvpn/v3/sessions/af8d2e1ds2cf9s4b9dsab13s5275dd8d98cb
Sun Dec 15 14:28:53 2024  Logger DEBUG: Removing AttachedService object for {tag:4391711175251893742}
Sun Dec 15 14:28:53 2024  Logger VERB2: Detached: {tag:4391711175251893742}  [:1.98/net.openvpn.v3.backends], pid 5990
Sun Dec 15 14:28:53 2024  Logger DEBUG: Removing AttachedService object for {tag:7092490142905028033}
Sun Dec 15 14:28:53 2024  Logger VERB2: Detached: {tag:7092490142905028033}  [:1.98/net.openvpn.v3.sessions], pid 5990
Sun Dec 15 14:28:53 2024  {tag:15294332327252311208} Network Configuration INFO: Cleaning up resources for PID 5990.
Sun Dec 15 14:28:54 2024  Logger VERB2: Attached: {tag:3426034149769375964}  [:1.100/net.openvpn.v3.backends], pid 6000
Sun Dec 15 14:28:54 2024  Logger VERB2: Attached: {tag:11991362904093285648}  [:1.100/net.openvpn.v3.sessions], pid 6000
Sun Dec 15 14:28:55 2024  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/78fbd68cs6445s4a62s95e4s3e71c4a3fbd2, interface=net.openvpn.v3.backends to {tag:3426034149769375964}
Sun Dec 15 14:28:55 2024  {tag:3426034149769375964} Client VERB1: Configuration override 'log-level' set to '6'
Sun Dec 15 14:28:55 2024  {tag:3426034149769375964} Client VERB1: Configuration override 'allow-compression' set to 'asym'
Sun Dec 15 14:28:55 2024  {tag:3426034149769375964} Client VERB2: Assigned session path: /net/openvpn/v3/sessions/78fbd68cs6445s4a62s95e4s3e71c4a3fbd2
Sun Dec 15 14:29:00 2024  {tag:3426034149769375964} Client INFO: Stopping VPN client
Sun Dec 15 14:29:00 2024  {tag:3426034149769375964} Client DEBUG: Stopping client mainloop
Sun Dec 15 14:29:00 2024  {tag:17334138538670274459} Session Manager VERB1: Session closing - /net/openvpn/v3/sessions/78fbd68cs6445s4a62s95e4s3e71c4a3fbd2
Sun Dec 15 14:29:00 2024  {tag:17334138538670274459} Session Manager VERB2: Session disconnecting - /net/openvpn/v3/sessions/78fbd68cs6445s4a62s95e4s3e71c4a3fbd2
Sun Dec 15 14:29:00 2024  Logger DEBUG: Removing AttachedService object for {tag:3426034149769375964}
Sun Dec 15 14:29:00 2024  Logger VERB2: Detached: {tag:3426034149769375964}  [:1.100/net.openvpn.v3.backends], pid 6000
Sun Dec 15 14:29:00 2024  Logger DEBUG: Removing AttachedService object for {tag:11991362904093285648}
Sun Dec 15 14:29:00 2024  Logger VERB2: Detached: {tag:11991362904093285648}  [:1.100/net.openvpn.v3.sessions], pid 6000
Sun Dec 15 14:29:00 2024  {tag:15294332327252311208} Network Configuration INFO: Cleaning up resources for PID 6000.
Sun Dec 15 14:29:01 2024  Logger VERB2: Attached: {tag:13871417453080745426}  [:1.102/net.openvpn.v3.backends], pid 6011
Sun Dec 15 14:29:01 2024  Logger VERB2: Attached: {tag:17580549518164642323}  [:1.102/net.openvpn.v3.sessions], pid 6011
Sun Dec 15 14:29:01 2024  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/68d3220fs5ab3s437as97d6s7fa72b23935c, interface=net.openvpn.v3.backends to {tag:13871417453080745426}
Sun Dec 15 14:29:01 2024  {tag:13871417453080745426} Client VERB1: Configuration override 'log-level' set to '6'
Sun Dec 15 14:29:01 2024  {tag:13871417453080745426} Client VERB1: Configuration override 'allow-compression' set to 'asym'
Sun Dec 15 14:29:01 2024  {tag:13871417453080745426} Client VERB2: Assigned session path: /net/openvpn/v3/sessions/68d3220fs5ab3s437as97d6s7fa72b23935c
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: Network configuration cleanup requested
Sun Dec 15 14:29:09 2024  {tag:15294332327252311208} Network Configuration INFO: Cleaning up resources for PID 6011.
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client INFO: Starting connection
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client VERB1: Username/password provided successfully for 'geoff'
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client VERB2: Using DNS resolver scope: global
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Connect] DCO flag: disabled
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] OpenVPN core v3.10.4 linux x86_64 64-bit OVPN-DCO
Sun Dec 15 14:29:09 2024  {tag:17334138538670274459} Session Manager VERB2: Starting connection - /net/openvpn/v3/sessions/68d3220fs5ab3s437as97d6s7fa72b23935c
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Frame=512/2112/512 mssfix-ctrl=1250
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] NOTE: This configuration contains options that were not used:
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Unsupported option (ignored)
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] 0 [allow-compression] [yes]
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] 1 [resolv-retry] [infinite]
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] 2 [persist-key]
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client VERB2: Resolving
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Contacting 73.239.35.228:1194 via UDP
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client VERB1: Waiting for server response
Sun Dec 15 14:29:09 2024  {tag:15294332327252311208} Network Configuration INFO: Socket protect called for socket 8, remote: '73.239.35.228', tun: '', ipv6: no, device_path=/, device-object: missing
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Connecting to [73.239.35.228]:1194 (73.239.35.228) via UDP
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client INFO: Connecting
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Tunnel Options:V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Creds: Username/Password
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Sending Peer Info:
               IV_VER=v3.10.4
               IV_PLAT=linux
               IV_NCP=2
               IV_TCPNL=1
               IV_PROTO=2974
               IV_MTU=1600
               IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
               IV_LZO=1
               IV_GUI_VER=OpenVPN3/Linux/v24
               IV_SSO=openurl,webauth,crtext
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] VERIFY OK: depth=1, /C=CN/ST=GD/L=ShenZhen/O=TP-Link/OU=SMB-OMADA/CN=TP-Link CA/name=EasyRSA/emailAddress=xxxx@xxxx, signature: RSA-SHA256
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] VERIFY OK: depth=0, /C=CN/ST=GD/L=ShenZhen/O=TP-Link/OU=SMB-OMADA/CN=server_server0/name=EasyRSA/emailAddress=xxxx@xxxx, signature: RSA-SHA256
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] SSL Handshake: peer certificate: CN=server_server0, 1024 bit RSA, cipher: ECDHE-RSA-AES256-GCM-SHA384    TLSv1.2 Kx=ECDH     Au=RSA   Enc=AESGCM(256)            Mac=AEAD
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Session is ACTIVE
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client VERB2: Retrieving configuration from server
Sun Dec 15 14:29:09 2024  {tag:13871417453080745426} Client DEBUG: [Core] Sending PUSH_REQUEST to server...
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: [Core] OPTIONS:
               0 [route] [192.168.1.0] [255.255.255.0]
               1 [route] [192.168.1.40] [255.255.255.248]
               2 [dhcp-option] [DNS] [192.168.1.10]
               3 [route] [192.168.1.10] [255.255.255.255]
               4 [comp-lzo] [no]
               5 [route] [192.168.1.40] [255.255.255.248]
               6 [topology] [net30]
               7 [ping] [10]
               8 [ping-restart] [120]
               9 [peer-id] [1]
               10 [cipher] [AES-256-GCM]
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: [Core] PROTOCOL OPTIONS:
                 cipher: AES-256-GCM
                 digest: none
                 key-derivation: OpenVPN PRF
                 compress: LZO_STUB
                 peer ID: 1
Sun Dec 15 14:29:10 2024  {tag:15294332327252311208} Network Configuration INFO: Virtual device 'e53c726atb39ct4bd0t80e4t485bb479715b' registered on /net/openvpn/v3/netcfg/6011_e53c726atb39ct4bd0t80e4t485bb479715b (owner uid 117, owner pid 6011)
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: [Core] TUN Error: tun_prop_error: one of ifconfig or ifconfig-ipv6 must be specified
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client !! CRITICAL !!: Failed configuring TUN device (TUN_SETUP_FAILED)
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: [Core] Client exception in transport_recv: tun_exception: not connected
Sun Dec 15 14:29:10 2024  {tag:15294332327252311208} Network Configuration VERB1: Device 'e53c726atb39ct4bd0t80e4t485bb479715b' was removed by openvpn
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: Network configuration cleanup requested
Sun Dec 15 14:29:10 2024  {tag:15294332327252311208} Network Configuration INFO: Cleaning up resources for PID 6011.
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client INFO: Stopping VPN client
Sun Dec 15 14:29:10 2024  {tag:13871417453080745426} Client DEBUG: Stopping client mainloop
Sun Dec 15 14:29:10 2024  {tag:17334138538670274459} Session Manager VERB1: Session closing - /net/openvpn/v3/sessions/68d3220fs5ab3s437as97d6s7fa72b23935c
Sun Dec 15 14:29:10 2024  {tag:17334138538670274459} Session Manager VERB2: Session disconnecting - /net/openvpn/v3/sessions/68d3220fs5ab3s437as97d6s7fa72b23935c
Sun Dec 15 14:29:10 2024  Logger DEBUG: Removing AttachedService object for {tag:13871417453080745426}
Sun Dec 15 14:29:10 2024  Logger VERB2: Detached: {tag:13871417453080745426}  [:1.102/net.openvpn.v3.backends], pid 6011
Sun Dec 15 14:29:10 2024  Logger DEBUG: Removing AttachedService object for {tag:17580549518164642323}
Sun Dec 15 14:29:10 2024  Logger VERB2: Detached: {tag:17580549518164642323}  [:1.102/net.openvpn.v3.sessions], pid 6011
Sun Dec 15 14:29:32 2024  Logger DEBUG: Removing AttachedService object for {tag:6585216574933869350}
Sun Dec 15 14:29:32 2024  Logger VERB2: Detached: {tag:6585216574933869350}  [:1.94/net.openvpn.v3.backends], pid 5963
Sun Dec 15 14:33:07 2024  Logger DEBUG: Removing AttachedService object for {tag:17334138538670274459}
Sun Dec 15 14:33:07 2024  Logger VERB2: Detached: {tag:17334138538670274459}  [:1.87/net.openvpn.v3.sessions], pid 5900

Then I basically just ran it again and it appeared to run just fine and connected.

Sun Dec 15 14:35:00 2024  Logger VERB2: Attached: {tag:16161124830054032052}  [:1.104/net.openvpn.v3.sessions], pid 6059
Sun Dec 15 14:35:00 2024  {tag:16161124830054032052} Session Manager INFO: OpenVPN 3 Session Manager started
Sun Dec 15 14:35:00 2024  Logger VERB2: Attached: {tag:16157968296814443238}  [:1.105/net.openvpn.v3.backends], pid 6067
Sun Dec 15 14:35:00 2024  Logger VERB2: Attached: {tag:17651666052804599022}  [:1.106/net.openvpn.v3.backends], pid 6073
Sun Dec 15 14:35:00 2024  Logger VERB2: Attached: {tag:1414362051343174528}  [:1.106/net.openvpn.v3.sessions], pid 6073
Sun Dec 15 14:35:00 2024  Logger DEBUG: Assigned session /net/openvpn/v3/sessions/2d6a74aes87f2s4937s8728sd2d5e93e0e65, interface=net.openvpn.v3.backends to {tag:17651666052804599022}
Sun Dec 15 14:35:00 2024  {tag:17651666052804599022} Client VERB1: Configuration override 'log-level' set to '6'
Sun Dec 15 14:35:00 2024  {tag:17651666052804599022} Client VERB1: Configuration override 'allow-compression' set to 'asym'
Sun Dec 15 14:35:00 2024  {tag:17651666052804599022} Client VERB2: Assigned session path: /net/openvpn/v3/sessions/2d6a74aes87f2s4937s8728sd2d5e93e0e65
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: Network configuration cleanup requested
Sun Dec 15 14:35:10 2024  {tag:15294332327252311208} Network Configuration INFO: Cleaning up resources for PID 6073.
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client INFO: Starting connection
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client VERB1: Username/password provided successfully for 'geoff'
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client VERB2: Using DNS resolver scope: global
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Connect] DCO flag: disabled
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] OpenVPN core v3.10.4 linux x86_64 64-bit OVPN-DCO
Sun Dec 15 14:35:10 2024  {tag:16161124830054032052} Session Manager VERB2: Starting connection - /net/openvpn/v3/sessions/2d6a74aes87f2s4937s8728sd2d5e93e0e65
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Frame=512/2112/512 mssfix-ctrl=1250
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] NOTE: This configuration contains options that were not used:
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Unsupported option (ignored)
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] 0 [allow-compression] [yes]
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] 1 [resolv-retry] [infinite]
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] 2 [persist-key]
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client VERB2: Resolving
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Contacting 73.239.35.228:1194 via UDP
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client VERB1: Waiting for server response
Sun Dec 15 14:35:10 2024  {tag:15294332327252311208} Network Configuration INFO: Socket protect called for socket 8, remote: '73.239.35.228', tun: '', ipv6: no, device_path=/, device-object: missing
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Connecting to [73.239.35.228]:1194 (73.239.35.228) via UDP
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client INFO: Connecting
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Tunnel Options:V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Creds: Username/Password
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Sending Peer Info:
               IV_VER=v3.10.4
               IV_PLAT=linux
               IV_NCP=2
               IV_TCPNL=1
               IV_PROTO=2974
               IV_MTU=1600
               IV_CIPHERS=AES-128-GCM:AES-192-GCM:AES-256-GCM:CHACHA20-POLY1305
               IV_LZO=1
               IV_GUI_VER=OpenVPN3/Linux/v24
               IV_SSO=openurl,webauth,crtext
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] VERIFY OK: depth=1, /C=CN/ST=GD/L=ShenZhen/O=TP-Link/OU=SMB-OMADA/CN=TP-Link CA/name=EasyRSA/emailAddress=xxxx@xxxx, signature: RSA-SHA256
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] VERIFY OK: depth=0, /C=CN/ST=GD/L=ShenZhen/O=TP-Link/OU=SMB-OMADA/CN=server_server0/name=EasyRSA/emailAddress=xxxx@xxxx, signature: RSA-SHA256
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] SSL Handshake: peer certificate: CN=server_server0, 1024 bit RSA, cipher: ECDHE-RSA-AES256-GCM-SHA384    TLSv1.2 Kx=ECDH     Au=RSA   Enc=AESGCM(256)            Mac=AEAD
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Session is ACTIVE
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client VERB2: Retrieving configuration from server
Sun Dec 15 14:35:10 2024  {tag:17651666052804599022} Client DEBUG: [Core] Sending PUSH_REQUEST to server...
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client DEBUG: [Core] OPTIONS:
               0 [route] [192.168.1.0] [255.255.255.0]
               1 [route] [192.168.1.40] [255.255.255.248]
               2 [dhcp-option] [DNS] [192.168.1.10]
               3 [route] [192.168.1.10] [255.255.255.255]
               4 [comp-lzo] [no]
               5 [route] [192.168.1.40] [255.255.255.248]
               6 [topology] [net30]
               7 [ping] [10]
               8 [ping-restart] [120]
               9 [ifconfig] [192.168.1.46] [192.168.1.45]
               10 [peer-id] [0]
               11 [cipher] [AES-256-GCM]
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client DEBUG: [Core] PROTOCOL OPTIONS:
                 cipher: AES-256-GCM
                 digest: none
                 key-derivation: OpenVPN PRF
                 compress: LZO_STUB
                 peer ID: 0
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Virtual device '3371bbc6teb39t460dtb761t58328db88269' registered on /net/openvpn/v3/netcfg/6073_3371bbc6teb39t460dtb761t58328db88269 (owner uid 117, owner pid 6073)
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Adding IP Address 192.168.1.46/30 gw 192.168.1.45 ipv6: no
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Setting remote IP address to 73.239.35.228 ipv6: no
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client VERB2: Session name: '73.239.35.228'
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Adding network '192.168.1.0/24' excl: no ipv6: no
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Adding network '192.168.1.40/29' excl: no ipv6: no
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Adding network '192.168.1.10/32' excl: no ipv6: no
Sun Dec 15 14:35:11 2024  {tag:15294332327252311208} Network Configuration INFO: Adding network '192.168.1.40/29' excl: no ipv6: no
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client DEBUG: [Core] Connected via tun
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client DEBUG: [Core] LZO-ASYM init swap=0 asym=1
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client DEBUG: [Core] Comp-stub init swap=0
Sun Dec 15 14:35:11 2024  {tag:17651666052804599022} Client INFO: Connected: [email protected]:1194 (73.239.35.228) via /UDP on tun/192.168.1.46/ gw=[192.168.1.45/] mtu=(default)
Sun Dec 15 14:36:00 2024  Logger DEBUG: Removing AttachedService object for {tag:16157968296814443238}
Sun Dec 15 14:36:00 2024  Logger VERB2: Detached: {tag:16157968296814443238}  [:1.105/net.openvpn.v3.backends], pid 6067

[dsommers]

Thanks a lot for verifying! I believe I have a strong hunch what's happening, where and why. We have already discussed how some of these code paths could be improved as well, so we will definitely take this into consideration.

I've created this public ticket to track this issue: https://codeberg.org/OpenVPN/openvpn3-linux/issues/34

[dsommers]

This was resolved in the OpenVPN 3 Linux v25 release. Closing this discussion.