Openvpn3 - session-start: Backend VPN process is not ready

[pratham-sharma-uplight]

on Ubuntu 22.04

Openvpn details:

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

Getting error when trying to connect to VPN

$ sudo openvpn3 session-start --config config_file.ovpn
Using pre-loaded configuration profile config_file.ovpn
Session path: /net/openvpn/v3/sessions/46198bf0s15fbs4d9dsb6dds98041020920e
session-start: ** ERROR ** Failed to start new session: Failed calling D-Bus method Ready: GDBus.Error:net.openvpn.v3.sessions.error: Backend VPN process is not ready

[dsommers]

Please provide more logs.

 $ sudo openvpn3-admin log-service --log-level 6
 $ openvpn3 config-manage --show --config config_file.ovpn --log-level 6

Then run this command to get all the needed log details:

 $ sudo openvpn3-admin journal --since $(date +%F)

[pratham-sharma-uplight]

Hello @dsommers

$ sudo openvpn3-admin log-service --log-level 6

Log method: journald
Attached log subscriptions: 1
Log timestamps: enabled
Log tag prefix enabled: enabled
Log D-Bus details: disabled
Current log level: 6

$ openvpn3 config-manage --show --config config_file.ovpn --log-level 6

Set override 'log-level' to '6'

------------------------------------------------------------

                          Name: vpn_device_1.ovpn
                     Read only: No
             Persistent config: No
          Data Channel Offload: No

  Overrides: 
                  persist-tun: true
                  log-level: 6

$ sudo openvpn3-admin journal --since $(date +%F)

Thu Jan  4 15:30:09 2024  Logger INFO: OpenVPN3/Linux v20 (openvpn3-service-logger)
               OpenVPN core v3.7.2 linux x86_64 64-bit
               Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v20 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.7.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Thu Jan  4 15:30:09 2024  Logger INFO: Log method: journald
Thu Jan  4 15:30:09 2024  Logger INFO: Idle exit set to 10 minutes
Thu Jan  4 15:30:09 2024  Logger VERB2: Attached: {tag:16006046960397757405}  [:1.70/net.openvpn.v3.sessions]
Thu Jan  4 15:30:09 2024  Logger VERB2: Attached: {tag:6666382611828467354}  [:1.72/net.openvpn.v3.configuration]
Thu Jan  4 15:33:09 2024  Logger VERB2: Detached: {tag:16006046960397757405}  [:1.70/net.openvpn.v3.sessions]
Thu Jan  4 15:36:09 2024  Logger VERB2: Detached: {tag:6666382611828467354}  [:1.72/net.openvpn.v3.configuration]
Wed Jan 19 13:31:49 586524  openvpn3-service-logger starting idle shutdown (pid: 6361)
Thu Jan  4 19:58:37 2024  Logger INFO: OpenVPN3/Linux v20 (openvpn3-service-logger)
               OpenVPN core v3.7.2 linux x86_64 64-bit
               Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Thu Jan  4 19:58:37 2024  Logger INFO: Log method: journald
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v20 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.7.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Thu Jan  4 19:58:37 2024  Logger INFO: Idle exit set to 10 minutes
Thu Jan  4 19:58:46 2024  Logger VERB2: Attached: {tag:3977047199776577422}  [:1.185/net.openvpn.v3.configuration]
Thu Jan  4 20:00:41 2024  Logger VERB2: Attached: {tag:528159723475589405}  [:1.214/net.openvpn.v3.sessions]
Thu Jan  4 20:00:41 2024  {tag:3977047199776577422} Config Manager INFO: {tag:3977047199776577422} Parsed single-use configuration 'config_file.ovpn', owner: root
Thu Jan  4 20:00:41 2024  {tag:3977047199776577422} Config Manager INFO: {tag:3977047199776577422} Setting configuration override 'persist-tun' to 'true' by UID 0
Thu Jan  4 20:00:41 2024  Logger VERB2: Attached: {tag:11680149820217006088}  [:1.215/net.openvpn.v3.backends]
Thu Jan  4 20:00:47 2024  Logger VERB2: Detached: {tag:11680149820217006088}  [:1.215/net.openvpn.v3.backends]
Thu Jan  4 20:01:06 2024  {tag:3977047199776577422} Config Manager INFO: {tag:3977047199776577422} Setting configuration override 'log-level' to '6' by UID 0

[dsommers]

Okay, looks reasonable. But you need to also start a VPN session (I forgot that in the instructions above). What I see here is just the changes you did to the configuration profile.

 $ openvpn3 session-start --config vpn_device_1.ovpn

And then do the same sudo openvpn3-admin journal command to retrieve all the log entries once again.

I also see that you still run the v20 release. I would also recommend you to upgrade to v21. Please note that the apt repository has moved to a new location, so you need to tweak your setup slightly. Most likely you just need to update the URL to the repo; details here: https://community.openvpn.net/openvpn/wiki/OpenVPN3Linux#Stablerepository-DebianUbuntu

[pratham-sharma-uplight]

Hey @dsommers

After installing the latest version of Openvpn3(v21) I restarted my system and follows are the out for you:

$ sudo openvpn3 sessions-list No sessions available

$ sudo openvpn3 configs-list

Configuration Name                                        Last used
------------------------------------------------------------------------------
------------------------------------------------------------------------------

$ sudo openvpn3-admin journal --since $(date +%F)

Fri Jan  5 12:15:52 2024  {tag:528159723475589405} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Fri Jan  5 12:16:02 2024  {tag:528159723475589405} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Fri Jan  5 12:16:30 2024  Logger VERB2: Attached: {tag:6616519286352099422}  [:1.274/net.openvpn.v3.backends]
Fri Jan  5 12:16:36 2024  Logger VERB2: Detached: {tag:6616519286352099422}  [:1.274/net.openvpn.v3.backends]
Fri Jan  5 12:19:01 2024  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.
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v21 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.8.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Fri Jan  5 12:19:01 2024  Logger INFO: Log method: journald
Fri Jan  5 12:19:01 2024  Logger INFO: Idle exit set to 10 minutes
Fri Jan  5 12:19:01 2024  Logger VERB2: Attached: {tag:3785525035484998611}  [:1.69/net.openvpn.v3.sessions], pid 6255
Fri Jan  5 12:19:01 2024  Logger VERB2: Attached: {tag:8660400497094378258}  [:1.71/net.openvpn.v3.configuration], pid 6291

$ sudo openvpn3 session-start --config vpn_device_1.ovpn

Using configuration profile from file: vpn_device_1.ovpn
Session path: /net/openvpn/v3/sessions/f04a7143sbb43s489ds9538sfd45a63937be
session-start: ** ERROR ** Failed to start new session: Failed calling D-Bus method [net.openvpn.v3.sessions] net.openvpn.v3.sessions.Ready: GDBus.Error:net.openvpn.v3.sessions.error: Backend VPN process is not ready

$ sudo openvpn3 sessions-list

-----------------------------------------------------------------------------
        Path: /net/openvpn/v3/sessions/f04a7143sbb43s489ds9538sfd45a63937be
     Created: (Not available)                           PID: -
       Owner: (not available)                        Device: (None)
      Status: (No status)
-----------------------------------------------------------------------------

$ sudo openvpn3 configs-list

Configuration Name                                        Last used
------------------------------------------------------------------------------
vpn_device_1.ovpn                                         -
------------------------------------------------------------------------------

$ sudo openvpn3-admin journal --since $(date +%F)

Fri Jan  5 12:15:52 2024  {tag:528159723475589405} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Fri Jan  5 12:16:02 2024  {tag:528159723475589405} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Fri Jan  5 12:16:30 2024  Logger VERB2: Attached: {tag:6616519286352099422}  [:1.274/net.openvpn.v3.backends]
Fri Jan  5 12:16:36 2024  Logger VERB2: Detached: {tag:6616519286352099422}  [:1.274/net.openvpn.v3.backends]
Fri Jan  5 12:19:01 2024  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.
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v21 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.8.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Fri Jan  5 12:19:01 2024  Logger INFO: Log method: journald
Fri Jan  5 12:19:01 2024  Logger INFO: Idle exit set to 10 minutes
Fri Jan  5 12:19:01 2024  Logger VERB2: Attached: {tag:3785525035484998611}  [:1.69/net.openvpn.v3.sessions], pid 6255
Fri Jan  5 12:19:01 2024  Logger VERB2: Attached: {tag:8660400497094378258}  [:1.71/net.openvpn.v3.configuration], pid 6291
Fri Jan  5 12:25:02 2024  Logger VERB2: Detached: {tag:3785525035484998611}  [:1.69/net.openvpn.v3.sessions], pid 6255
Fri Jan  5 12:25:02 2024  Logger VERB2: Detached: {tag:8660400497094378258}  [:1.71/net.openvpn.v3.configuration], pid 6291
Fri Jan  5 12:29:59 2024  Logger VERB2: Attached: {tag:7919269897507281558}  [:1.149/net.openvpn.v3.configuration], pid 22813
Fri Jan  5 12:30:13 2024  Logger VERB2: Attached: {tag:16248270841017367073}  [:1.158/net.openvpn.v3.sessions], pid 23533
Fri Jan  5 12:30:14 2024  {tag:7919269897507281558} Config Manager INFO: Parsed single-use configuration 'vpn_device_1.ovpn', owner: root
Fri Jan  5 12:30:14 2024  {tag:7919269897507281558} Config Manager INFO: Setting configuration override 'persist-tun' to 'true' by UID 0
Fri Jan  5 12:30:14 2024  Logger VERB2: Attached: {tag:12638940724868537016}  [:1.159/net.openvpn.v3.backends], pid 23568
Fri Jan  5 12:30:20 2024  Logger VERB2: Detached: {tag:12638940724868537016}  [:1.159/net.openvpn.v3.backends], pid 23568
Fri Jan  5 12:32:05 2024  {tag:7919269897507281558} Config Manager INFO: Setting configuration override 'log-level' to '6' by UID 0
Fri Jan  5 12:32:27 2024  Logger VERB2: Attached: {tag:15084667738735099305}  [:1.167/net.openvpn.v3.backends], pid 27043
Fri Jan  5 12:32:33 2024  Logger VERB2: Detached: {tag:15084667738735099305}  [:1.167/net.openvpn.v3.backends], pid 27043

$ sudo openvpn3-admin version --services

OpenVPN 3 D-Bus services:

  - Client backend starter service
     openvpn3-service-backendstart: v21

  - Configuration Service
     openvpn3-service-configmgr:    v21

  - Log Service
     openvpn3-service-logger:       v21

  - Network Configuration Service
     openvpn3-service-netcfg:       v21

  - Session Manager Service
     openvpn3-service-sessionmgr:   v21

[leocao91]

Fix it with the following steps:

• Ubuntu 22.04 with OpenVPN3/Linux v20 (openvpn3)
  1. Update file: /usr/share/dbus-1/system-services/net.openvpn.v3.netcfg.service
  2. Replace line to: Exec=/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-netcfg --resolv-conf /etc/resolv.conf --state-dir "/var/lib/openvpn3"

  3. Run command: openvpn3-admin netcfg-service --config-set resolve-conf /etc/resolv.conf openvpn3-admin netcfg-service --config-set systemd-resolved false

     *Ubuntu 22.04 with OpenVPN3/Linux v21 + (openvpn3)

  4. Update file: /usr/share/dbus-1/system-services/net.openvpn.v3.netcfg.service
  5. Replace line to: Exec=/usr/libexec/openvpn3-linux/openvpn3-service-netcfg --resolv-conf /etc/resolv.conf --state-dir "/var/lib/openvpn3"
  6. Run command: openvpn3-admin netcfg-service --config-set resolve-conf /etc/resolv.conf openvpn3-admin netcfg-service --config-set systemd-resolved false

[pratham-sharma-uplight]

Hi @leocao91

Here are the following outputs for you, but no success.

$ cat /usr/share/dbus-1/system-services/net.openvpn.v3.netcfg.service

#  This file is part of the OpenVPN 3 Linux client
#
#  SPDX-License-Identifier: AGPL-3.0-only
#
#  Copyright (C) 2018 - 2023  OpenVPN Inc <sales@openvpn.net>
#  Copyright (C) 2018 - 2023  David Sommerseth <davids@openvpn.net>
#

[D-BUS Service]
Name=net.openvpn.v3.netcfg
User=root
#Exec=/usr/libexec/openvpn3-linux/openvpn3-service-netcfg --systemd-resolved --state-dir "/var/lib/openvpn3"
Exec=/usr/libexec/openvpn3-linux/openvpn3-service-netcfg --resolv-conf /etc/resolv.conf --state-dir "/var/lib/openvpn3"

$ sudo openvpn3-admin netcfg-service --config-set resolve-conf /etc/resolv.conf Loading configuration file: /var/lib/openvpn3/netcfg.json

$ sudo openvpn3-admin netcfg-service --config-set systemd-resolved false

Loading configuration file: /var/lib/openvpn3/netcfg.json
Configuration file updated.  Changes will be activated next time openvpn3-service-netcfg restarts

$ sudo cat /var/lib/openvpn3/netcfg.json

{
    //  Option --systemd-resolved :: Systemd-resolved in use
    "systemd_resolved" : false
}

$ sudo openvpn3 session-start --config vpn_device_1.ovpn

Using pre-loaded configuration profile 'vpn_device_1.ovpn'
Session path: /net/openvpn/v3/sessions/12c8cc12s4276s4734s8aa2s069566cadb77
session-start: ** ERROR ** Failed to start new session: Failed calling D-Bus method [net.openvpn.v3.sessions] net.openvpn.v3.sessions.Ready: GDBus.Error:net.openvpn.v3.sessions.error: Backend VPN process is not ready

[dsommers]

@leocao91 Your step which modifies the auto-start service file may actually make things worse. That is not even needed when you do the openvpn3-admin netcfg-service steps. Those settings overrides the command line.

@pratham-sharma-uplight Your log output still does not provide any log output from the session manager nor the VPN client process. So lets try a different approach. First, revert the change you did in /usr/share/dbus-1/system-services/net.openvpn.v3.netcfg.service. That is just plain wrong at this point.

Then try starting the configuration using a configuration file:

 $ openvpn2 --config vpn_device_1.ovpn --verb 6

If it fails, then run this command and provide the output (without key/certificate data):

 $ OPENVPN3_DEBUG=DUMP_PARSE openvpn2 --config vpn_device_1.ovpn --verb 6

[pratham-sharma-uplight]

Hey @dsommers

$ openvpn2 --config vpn_device_1.ovpn --verb 6

** ERROR ** org.freedesktop.DBus.Error.AccessDenied: Rejected send message, 1 matched rules; type="method_call", sender=":1.190" (uid=0 pid=262724 comm="/usr/bin/python3 /usr/bin/openvpn2 --config vpn_de" label="unconfined") interface="net.openvpn.v3.sessions" member="Ready" error name="(unset)" requested_reply="0" destination=":1.188" (uid=129 pid=261024 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi" label="unconfined")

$ OPENVPN3_DEBUG=DUMP_PARSE openvpn2 --config vpn_device_1.ovpn --verb 6

auth SHA256
<ca>
-----BEGIN CERTIFICATE-----
// some key here
-----END CERTIFICATE-----
</ca>
<cert>
-----BEGIN CERTIFICATE-----
// some key here
-----END CERTIFICATE-----
</cert>
cipher AES-256-CBC
client
dev tun
<key>
-----BEGIN RSA PRIVATE KEY-----
// some key here
-----END RSA PRIVATE KEY-----
</key>
key-direction 1
persist-tun
push-peer-info
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 443 tcp
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 1194 udp
remote in-bom.gw.openvpn.com 1194 udp
remote-cert-tls server
setenv USERNAME "uplight/pratham.sharma%40uplight.com_3453/XXXXXXXXXXXXXXXXXXXXXX"
verb 6
<tls-auth>
-----BEGIN OpenVPN Static key V1-----
// some key here
-----END OpenVPN Static key V1-----
</tls-auth>

[dsommers]

Okay, this gives some more informative clues ... can you try to reload the D-Bus daemon? (not restart) ...

  $ sudo systemctl reload dbus.service

Also ensure you have some D-Bus policy files installed here:

$ ls -l /usr/share/dbus-1/system.d/net.openvpn.v3.*.conf
-rw-r--r-- 1 root root 5982 Dec 16 18:09 /usr/share/dbus-1/system.d/net.openvpn.v3.client.conf
-rw-r--r-- 1 root root 5126 Mar 20  2023 /usr/share/dbus-1/system.d/net.openvpn.v3.configuration.conf
-rw-r--r-- 1 root root 4509 Mar 20  2023 /usr/share/dbus-1/system.d/net.openvpn.v3.log.conf
-rw-r--r-- 1 root root 8026 Mar 20  2023 /usr/share/dbus-1/system.d/net.openvpn.v3.netcfg.conf
-rw-r--r-- 1 root root 5904 Mar 20  2023 /usr/share/dbus-1/system.d/net.openvpn.v3.sessions.conf
$

[pratham-sharma-uplight]

yes I have all the D-Bus policy files installed here:

$ ls -l /usr/share/dbus-1/system.d/net.openvpn.v3.*.conf
-rw-r--r-- 1 root root 5982 Oct  6 15:57 /usr/share/dbus-1/system.d/net.openvpn.v3.client.conf
-rw-r--r-- 1 root root 5881 Oct  6 15:57 /usr/share/dbus-1/system.d/net.openvpn.v3.configuration.conf
-rw-r--r-- 1 root root 4509 Oct  6 15:57 /usr/share/dbus-1/system.d/net.openvpn.v3.log.conf
-rw-r--r-- 1 root root 8026 Oct  6 15:57 /usr/share/dbus-1/system.d/net.openvpn.v3.netcfg.conf
-rw-r--r-- 1 root root 5904 Oct  6 15:57 /usr/share/dbus-1/system.d/net.openvpn.v3.sessions.conf

I tried this too $ sudo systemctl reload dbus.service

and in following journal output: $ sudo openvpn3-admin journal --since $(date +%F)

Mon Jan  8 10:54:18 2024  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.
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v21 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.8.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Mon Jan  8 10:54:18 2024  Logger INFO: Log method: journald
Mon Jan  8 10:54:18 2024  Logger INFO: Idle exit set to 10 minutes
Mon Jan  8 10:54:18 2024  Logger VERB2: Attached: {tag:16006046960397757405}  [:1.70/net.openvpn.v3.sessions], pid 6406
Mon Jan  8 10:54:18 2024  Logger VERB2: Attached: {tag:6666382611828467354}  [:1.72/net.openvpn.v3.configuration], pid 6444
Mon Jan  8 10:57:23 2024  Logger VERB2: Detached: {tag:16006046960397757405}  [:1.70/net.openvpn.v3.sessions], pid 6406
Mon Jan  8 11:00:23 2024  Logger VERB2: Detached: {tag:6666382611828467354}  [:1.72/net.openvpn.v3.configuration], pid 6444
Wed Jan 19 13:31:49 586524  openvpn3-service-logger starting idle shutdown (pid: 6425)
Mon Jan  8 15:22:58 2024  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.
Mon Jan  8 15:22:58 2024  Logger INFO: Log method: journald
Wed Jan 19 13:31:49 586524  OpenVPN3/Linux v21 (openvpn3-service-logger)
Wed Jan 19 13:31:49 586524  OpenVPN core v3.8.2 linux x86_64 64-bit
Wed Jan 19 13:31:49 586524  Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
Wed Jan 19 13:31:49 586524  Log method: journald
Mon Jan  8 15:22:58 2024  Logger INFO: Idle exit set to 10 minutes
Mon Jan  8 15:22:58 2024  Logger VERB2: Attached: {tag:659435728684274318}  [:1.184/net.openvpn.v3.netcfg], pid 259489
Mon Jan  8 15:22:58 2024  Logger VERB2: Attached: {tag:8377701857831903868}  [:1.184/net.openvpn.v3.netcfg.core], pid 259489
Mon Jan  8 15:22:58 2024  {tag:8377701857831903868} Network Configuration DEBUG: OpenVPN 3 Core library logging initialized
Mon Jan  8 15:22:58 2024  {tag:659435728684274318} Network Configuration VERB1: Redirect method: host-route
Mon Jan  8 15:23:51 2024  Logger VERB2: Attached: {tag:14493396140449146603}  [:1.187/net.openvpn.v3.configuration], pid 261006
Mon Jan  8 15:23:51 2024  {tag:14493396140449146603} Config Manager INFO: Parsed single-use configuration 'vpn_device_1.ovpn', owner: prathamsharma
Mon Jan  8 15:23:51 2024  {tag:14493396140449146603} Config Manager INFO: Setting configuration override 'persist-tun' to 'true' by UID 1003
Mon Jan  8 15:23:51 2024  Logger VERB2: Attached: {tag:12220714250632486670}  [:1.188/net.openvpn.v3.sessions], pid 261024
Mon Jan  8 15:23:51 2024  Logger VERB2: Attached: {tag:11212960311964532105}  [:1.189/net.openvpn.v3.backends], pid 261042
Mon Jan  8 15:23:57 2024  Logger VERB2: Detached: {tag:11212960311964532105}  [:1.189/net.openvpn.v3.backends], pid 261042
Mon Jan  8 15:24:27 2024  {tag:14493396140449146603} Config Manager INFO: Parsed single-use configuration 'vpn_device_1.ovpn', owner: root
Mon Jan  8 15:24:27 2024  {tag:14493396140449146603} Config Manager INFO: Setting configuration override 'persist-tun' to 'true' by UID 0
Mon Jan  8 15:24:27 2024  Logger VERB2: Attached: {tag:13050616340229785464}  [:1.191/net.openvpn.v3.backends], pid 262743
Mon Jan  8 15:24:33 2024  Logger VERB2: Detached: {tag:13050616340229785464}  [:1.191/net.openvpn.v3.backends], pid 262743
Mon Jan  8 15:27:54 2024  Logger VERB2: Attached: {tag:14155269390281304573}  [:1.195/net.openvpn.v3.backends], pid 266399
Mon Jan  8 15:28:00 2024  Logger VERB2: Detached: {tag:14155269390281304573}  [:1.195/net.openvpn.v3.backends], pid 266399
Mon Jan  8 15:32:58 2024  Logger VERB2: Detached: {tag:659435728684274318}  [:1.184/net.openvpn.v3.netcfg], pid 259489
Mon Jan  8 15:32:58 2024  Logger WARNING: Unexpected Detach call from :1.184, pid not found for this sender
Mon Jan  8 15:32:58 2024  Logger VERB2: Detached: {tag:8377701857831903868}  [:1.184/net.openvpn.v3.netcfg.core]
Mon Jan  8 15:34:05 2024  {tag:12220714250632486670} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Mon Jan  8 15:34:12 2024  {tag:12220714250632486670} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Mon Jan  8 15:35:57 2024  {tag:14493396140449146603} Config Manager INFO: Parsed single-use configuration 'vpn_device_1.ovpn', owner: prathamsharma
Mon Jan  8 15:35:57 2024  {tag:14493396140449146603} Config Manager INFO: Setting configuration override 'persist-tun' to 'true' by UID 1003
Mon Jan  8 15:35:57 2024  Logger VERB2: Attached: {tag:8869862730241784378}  [:1.218/net.openvpn.v3.backends], pid 277212
Mon Jan  8 15:36:03 2024  Logger VERB2: Detached: {tag:8869862730241784378}  [:1.218/net.openvpn.v3.backends], pid 277212
Mon Jan  8 15:36:24 2024  Logger VERB2: Attached: {tag:3555200485608283618}  [:1.221/net.openvpn.v3.backends], pid 277763
Mon Jan  8 15:36:30 2024  Logger VERB2: Detached: {tag:3555200485608283618}  [:1.221/net.openvpn.v3.backends], pid 277763
Mon Jan  8 16:03:39 2024  {tag:12220714250632486670} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration
Mon Jan  8 16:03:47 2024  Logger VERB2: Attached: {tag:16936617597321978154}  [:1.227/net.openvpn.v3.backends], pid 303048
Mon Jan  8 16:03:53 2024  Logger VERB2: Detached: {tag:16936617597321978154}  [:1.227/net.openvpn.v3.backends], pid 303048
Mon Jan  8 16:10:03 2024  {tag:12220714250632486670} Session Manager !! CRITICAL !!: Forced session shutdown before backend registration

[dsommers]

Hmmm .... for some reason, the client process seems to abruptly stop before it can do everything it need to do.

Can you open another terminal to this host, enable the /bin/bash shell for the openvpn user (sudo chsh openvpn). Then run sudo su - openvpn. As this openvpn user, you need to start a process manually with some extra arguments. I would like to see the console output of this command as you start the openvpn2 command line you did. I need to see the full output from the command starts and until the openvpn2 command fails.

[openvpn@host: ~] $ /usr/libexec/openvpn3-linux/openvpn3-service-backendstart --log-level 6 --idle-exit 0 --client-log-level 6 --client-log-file stdout:

[pratham-sharma-uplight]

Hey @dsommers

I think system does not have openvpn user.

Can you check If I am doing it right?

[dsommers]

@pratham-sharma-uplight When you run the sudo chsh openvpn command, you are expected to type /bin/bash. The warning with /nonexistent can be ignored (the openvpn user does not need to have a real home directory).

The reason it says This account is currently not available. is because the login shell is still set to /usr/sbin/nologin.

[pratham-sharma-uplight]

Hey @dsommers I tried to run the commands as follows:

Terminal 1: $ sudo chsh openvpn

Changing the login shell for openvpn
Enter the new value, or press ENTER for the default
    Login Shell [/bin/bash]: /bin/bash

 $ sudo systemctl reload dbus.service
 $ openvpn2 --config device_1_ubuntu22_pratham_sharma@uplight.openvpn.com_[Mumbai].ovpn --verb 6

(This is not failing now)

Terminal 2:

 $ /usr/libexec/openvpn3-linux/openvpn3-service-backendstart --log-level 6 --idle-exit 0 --client-log-level 6 --client-log-file stdout:

OpenVPN3/Linux v21 (openvpn3-service-backendstart)
OpenVPN core v3.8.2 linux x86_64 64-bit
Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
terminate called after throwing an instance of 'DBusProxyAccessDeniedException'
  what():  Access denied to Attach
Aborted (core dumped)

[dsommers]

Okay, now this is getting interesting. Finally a real failure we can debug more into. This looks like an issue which only some installs experience, and sometimes seems to resolve itself after a reboot. I would like to understand this issue better, so we can get a proper fix in place.

Can you please provide the output if this command?

 $ sudo journalctl --since -4weeks -u dbus | grep -E 'Rejected .*="net.openvpn.v3'

[pratham-sharma-uplight]

hey @dsommers

$ sudo journalctl --since -4weeks -u dbus | grep -E 'Rejected .*="net.openvpn.v3'

Jan 08 15:33:27 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.190" (uid=0 pid=262724 comm="/usr/bin/python3 /usr/bin/openvpn2 --config vpn_de" label="unconfined") interface="net.openvpn.v3.sessions" member="Ready" error name="(unset)" requested_reply="0" destination=":1.188" (uid=129 pid=261024 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi" label="unconfined")
Jan 08 17:58:47 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.242" (uid=1003 pid=404499 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 08 17:58:59 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.243" (uid=0 pid=405716 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 08 18:04:58 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.251" (uid=1003 pid=412126 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 08 18:23:07 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.255" (uid=1003 pid=429962 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 10 12:22:07 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.358" (uid=1003 pid=1078379 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 10 12:22:58 xipl91903 dbus-daemon[3397]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.363" (uid=1003 pid=1081836 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.185" (uid=129 pid=259505 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 12 19:47:37 xipl91903 dbus-daemon[3322]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.165" (uid=1003 pid=171977 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.162" (uid=129 pid=168414 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 12 19:50:44 xipl91903 dbus-daemon[3322]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.173" (uid=1003 pid=177668 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.162" (uid=129 pid=168414 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 12 19:52:07 xipl91903 dbus-daemon[3322]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.183" (uid=1003 pid=180202 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.162" (uid=129 pid=168414 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")
Jan 12 19:52:49 xipl91903 dbus-daemon[3322]: [system] Rejected send message, 1 matched rules; type="method_call", sender=":1.184" (uid=1003 pid=180820 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined") interface="net.openvpn.v3.log" member="Attach" error name="(unset)" requested_reply="0" destination=":1.162" (uid=129 pid=168414 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")

[dsommers]

Good! A few more questions:

1. Can you grep the following from your /etc/passwd log (passwords are not stored there; just the accounts on the host):

    $ sudo grep "129" /etc/passwd
    $ sudo grep "openvpn" /etc/passwd

2. Can you provide the output of this command:

   $ sudo stat /proc/$(pidof openvpn3-service-logger)/exe

The unexpected detail in that output is the difference between these two parts of the log lines:

 sender=":1.184" (uid=1003 pid=180820 comm="/usr/libexec/openvpn3-linux/openvpn3-service-backe" label="unconfined")

and this part

 destination=":1.162" (uid=129 pid=168414 comm="/usr/libexec/openvpn3-linux/openvpn3-service-logge" label="unconfined")

The uid field here is expected to the same. So I need to understand what UID 129 and 1003 are.

[pratham-sharma-uplight]

$ sudo grep "129" /etc/passwd openvpn:x:129:136::/nonexistent:/bin/bash

$ sudo grep "openvpn" /etc/passwd

openvpn:x:129:136::/nonexistent:/bin/bash
nm-openvpn:x:134:144:NetworkManager OpenVPN,,,:/var/lib/openvpn/chroot:/usr/sbin/nologin

$ sudo stat /proc/$(pidof openvpn3-service-logger)/exe

  File: /proc/168414/exe -> /usr/libexec/openvpn3-linux/openvpn3-service-logger
  Size: 0           Blocks: 0          IO Block: 1024   symbolic link
Device: 17h/23d Inode: 1260141     Links: 1
Access: (0777/lrwxrwxrwx)  Uid: (  129/ openvpn)   Gid: (  136/ openvpn)
Access: 2024-01-15 16:30:54.486008286 +0530
Modify: 2024-01-15 16:09:01.689487203 +0530
Change: 2024-01-15 16:09:01.689487203 +0530
 Birth: -

[dsommers]

Alright, it seems you were not able to start openvpn3-service-backendstart as the openvpn user at all.

When you do: sudo su - openvpn ... run the id command and ensure it reports something like: uid=129(openvpn) gid=136(openvpn). When that happens, then you can start the openvpn3-service-backendstart command.

[pratham-sharma-uplight]

@dsommers

Terminal 1:

Terminal 2:

$ sudo openvpn3 sessions-list && sudo openvpn3 configs-list

[sudo] password for prathamsharma: 
No sessions available
Configuration Name                                        Last used
------------------------------------------------------------------------------
------------------------------------------------------------------------------

$ sudo openvpn3 session-start --config vpn_device_1.ovpn

Using configuration profile from file: vpn_device_1.ovpn
Session path: /net/openvpn/v3/sessions/412e8c53s2265s4f4as9f8asfbc2264d2a62
session-start: ** ERROR ** Failed to start new session: Failed calling D-Bus method [net.openvpn.v3.sessions] net.openvpn.v3.sessions.Ready: GDBus.Error:net.openvpn.v3.sessions.error: Backend VPN process is not ready

$ sudo openvpn3 sessions-list && sudo openvpn3 configs-list

-----------------------------------------------------------------------------
        Path: /net/openvpn/v3/sessions/412e8c53s2265s4f4as9f8asfbc2264d2a62
     Created: (Not available)                           PID: -
       Owner: (not available)                        Device: (None)
      Status: (No status)
-----------------------------------------------------------------------------
Configuration Name                                        Last used
------------------------------------------------------------------------------
vpn_device_1.ovpn                                         -
------------------------------------------------------------------------------

[dsommers]

Okay, this looks somewhat better. Please, what is the output found in "Terminal 1"? With those arguments presented there to openvpn3-service-backend, it should be a lot more debug details there.

[pratham-sharma-uplight]

It's nothing there! Just blank screen till now.

[dsommers]

Okay, that is completely unexpected. The openvpn3-service-backend start program is responsible to start new openvpn3-service-client processes when you request a new VPN session (via the openvpn3 command). The real VPN client process is openvpn3-service-client.

What kind of specifications do this computer have? Can you provide the output of lscpu and free -m?

Also, don't use sudo in front of the openvpn3 commands. OpenVPN 3 Linux is designed so that unprivileged users can start and manage their own VPN configurations and VPN sessions out-of-the-box. That's why there are several openvpn3-service-* processes in the background; it's part of the privilege separation between the VPN tunnels itself, the privileged operations and the user requesting a VPN session.

You can also in a third terminal, sudo su - openvpn and start the Session Manager manually ... to see if we get more details from there:

  openvpn@xipl91903:~ $ /usr/libexec/openvpn3-linux/openvpn3-service-sessionmgr --log-level 6 --log-file stdout: --idle-exit 0

When starting the VPN session, please provide the output of this third terminal as well.

[pratham-sharma-uplight]

$ /usr/libexec/openvpn3-linux/openvpn3-service-sessionmgr --log-level 6 --log-file stdout: --idle-exit 0

OpenVPN3/Linux v21 (openvpn3-service-sessionmgr)
OpenVPN core v3.8.2 linux x86_64 64-bit
Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
2024-01-19 12:05:20  Session Manager DEBUG: SessionManagerObject registered on 'net.openvpn.v3.sessions': /net/openvpn/v3/sessions
2024-01-19 12:05:20  Session Manager INFO: Shutting down
terminate called after throwing an instance of 'DBusException'
  what():  openvpn3-service-sessionmgr could not register 'net.openvpn.v3.sessions' on the D-Bus
Aborted (core dumped)

$ /usr/libexec/openvpn3-linux/openvpn3-service-backendstart --log-level 6 --idle-exit 0 --client-log-level 6 --client-log-file stdout:

OpenVPN3/Linux v21 (openvpn3-service-backendstart)
OpenVPN core v3.8.2 linux x86_64 64-bit
Copyright (C) 2012-2022 OpenVPN Inc. All rights reserved.
terminate called after throwing an instance of 'DBusProxyAccessDeniedException'
  what():  Access denied to Attach
Aborted (core dumped)

$ free -m

               total        used        free      shared  buff/cache   available
Mem:           15668        7035         444        5127        8187        3168
Swap:            979         978           1

$ lscpu

Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         39 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  8
  On-line CPU(s) list:   0-7
Vendor ID:               GenuineIntel
  Model name:            11th Gen Intel(R) Core(TM) i7-1165G7 @ 2.80GHz
    CPU family:          6
    Model:               140
    Thread(s) per core:  2
    Core(s) per socket:  4
    Socket(s):           1
    Stepping:            1
    CPU max MHz:         4700.0000
    CPU min MHz:         400.0000
    BogoMIPS:            5606.40
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdts
                         cp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor d
                         s_cpl vmx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm
                          3dnowprefetch cpuid_fault epb cat_l2 invpcid_single cdp_l2 ssbd ibrs ibpb stibp ibrs_enhanced tpr_shadow flexpriority ept vpid ept_ad fsgsbase
                          tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb intel_pt avx512cd sha_ni avx512b
                         w avx512vl xsaveopt xsavec xgetbv1 xsaves split_lock_detect dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp hwp_pkg_req vnmi avx5
                         12vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq rdpid movdiri movdir64b fsrm avx512_vp2inter
                         sect md_clear ibt flush_l1d arch_capabilities
Virtualization features: 
  Virtualization:        VT-x
Caches (sum of all):     
  L1d:                   192 KiB (4 instances)
  L1i:                   128 KiB (4 instances)
  L2:                    5 MiB (4 instances)
  L3:                    12 MiB (1 instance)
NUMA:                    
  NUMA node(s):          1
  NUMA node0 CPU(s):     0-7
Vulnerabilities:         
  Gather data sampling:  Mitigation; Microcode
  Itlb multihit:         Not affected
  L1tf:                  Not affected
  Mds:                   Not affected
  Meltdown:              Not affected
  Mmio stale data:       Not affected
  Retbleed:              Not affected
  Spec rstack overflow:  Not affected
  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl
  Spectre v1:            Mitigation; usercopy/swapgs barriers and __user pointer sanitization
  Spectre v2:            Mitigation; Enhanced / Automatic IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS SW sequence
  Srbds:                 Not affected
  Tsx async abort:       Not affected

[dsommers]

Can you stop all the openvpn3-service-* processes running on the system? Use kill -TERM with their appropriate PID value. The openvpn3-service-sessionmgr could not register 'net.openvpn.v3.sessions' on the D-Bustypically indicates that there are some processes already running on your system.

Also, do you try this on the bare metal, or are you trying to run the VPN via some containers?

[dsommers]

Closing this issue ticket due to no response since January 20.

Before re-opening this issue on Codeberg, please upgrade to the PPA repository to get the development snapshot builds (unless you've upgraded to Ubuntu 24.04, the v22_dev release will arrive in the standard repos soon).