protun: first connection after boot always fails with AuthDenied — NM's `NeedSecrets` call never reaches the newly started `nm-protun-service`

[eraezor]

Summary

On a fresh boot, the first connect with the protun-smart protocol always fails after
exactly 10 s with AuthDenied. NetworkManager's NeedSecrets D-Bus call to the plugin
times out: the plugin registers its bus name, but the call is never dispatched to it.
Clicking Connect a second time in the same boot works, as does every later connect.
There is no real authentication problem.

A follow-on bug: when the failure happens during connect_at_app_startup, the app is left
in a wedged state (see "Secondary issue" below).

Environment

• CachyOS (Arch-based), kernel 7.2.7-1-cachyos, KDE Plasma 6.7.5 (Wayland)
• NetworkManager 1.58.1
• proton-vpn-gtk-app 4.18.1 (Arch extra)
• python-proton-vpn-api-core 5.6.10 (ships /usr/lib/nm-protun-service, nm-protun.name)
• proton-vpn-daemon 0.13.8, python-proton-core 0.7.4, python-proton-keyring-linux 0.2.3
• Protocol: protun-smart, kill switch: on (non-permanent)

Steps to reproduce

1. Reboot.
2. Open the app (autostart or manually; connect_at_app_startup on or off makes no difference).
3. Click Connect → it fails after 10 s with "authentication error".
4. Click Connect again → it connects within about 1 s.

Reproduced on two consecutive boots. In both, the plasma-nm secret agent
(org.kde.plasma.networkmanagement) had registered with NM 47 s and 15 s before the
failing connect, so this does not look like a secret-agent readiness race at login. Also,
the call that times out is NM → plugin, not NM → agent.

Logs — failing (first attempt after boot)

21:01:33.784400 NetworkManager[763]: vpn[...,"ProtonVPN AU#143"]: starting protun
21:01:33.791368 NetworkManager[5464]: INFO proton_vpn_platform::protun::nm_protun_service::run] Starting Proton VPN NetworkManager plugin
21:01:33.793056 NetworkManager[5464]: INFO zbus::connection] start_object_server; started_event=None
21:01:33.793342 NetworkManager[5464]: INFO zbus::connection] monitor_name_lost; name=org.freedesktop.NetworkManager.protun
21:01:33.793378 NetworkManager[5464]: INFO ...::run] Plugin registered at /org/freedesktop/NetworkManager/VPN/Plugin with service name org.freedesktop.NetworkManager.protun
21:01:33.793378 NetworkManager[5464]: INFO ...::run] Waiting for NetworkManager connections...
            <-- no dispatch_call for 10 s -->
21:01:43.793975 NetworkManager[763]: <warn> vpn[...,"ProtonVPN AU#143"]: plugin NeedSecrets request #1 failed: Timeout was reached
21:01:43.794457 NetworkManager[5464]: INFO zbus::object_server] dispatch_call; ... member: "Disconnect"
21:01:43.795223 NetworkManager[5464]: ERROR ...::service] Failed to teardown routing: Received a netlink error message No such device (os error 19)
21:01:43.794725 protonvpn-app: WARNING | Reached connection error state: AuthDenied (None)
21:01:43.796055 protonvpn-app: ERROR | APP:ERROR | Reconnection not possible due to authentication error.

Logs — working (second click, same boot, same NM process, same server)

21:04:03.466380 NetworkManager[763]: vpn[...,"ProtonVPN AU#143"]: starting protun
21:04:03.469703 NetworkManager[7022]: INFO ...::run] Starting Proton VPN NetworkManager plugin
21:04:03.470316 NetworkManager[7022]: INFO ...::run] Plugin registered at /org/freedesktop/NetworkManager/VPN/Plugin ...
21:04:03.470965 NetworkManager[7022]: INFO zbus::object_server] dispatch_call; ... member: "NeedSecrets"
21:04:03.471071 NetworkManager[7022]: INFO ...::network_manager] Secrets are needed for this connection
21:04:03.475131 NetworkManager[7022]: INFO zbus::object_server] dispatch_call; ... member: "NeedSecrets"
21:04:03.475577 NetworkManager[7022]: INFO zbus::object_server] dispatch_call; ... member: "ConnectInteractive"
21:04:03.487038 protonvpn-app: CONN:STATE_CHANGED | Connected

Same NM process (PID 763), same server, 2.5 minutes apart. In the working case NeedSecrets
is dispatched about 0.7 ms after the plugin registers. In the failing case it never arrives,
although the plugin log looks identical up to that point. This looks like a startup race:
NM probably sends NeedSecrets before the plugin's zbus object server is serving the path
(or before the name is fully acquired), and the call is lost instead of being queued or
rejected. The previous boot showed the same pattern (first attempt failed, later ones worked).
It seems tied to the first plugin launch after boot (cold cache), but that part is a guess.

Secondary issue: the app wedges if this happens during connect_at_app_startup

When the failure above happens during the startup auto-connect:

• the first app instance stays alive in the tray in an error state, and relaunching from
  the launcher shows no window;
• each relaunch adds another non-persistent pvpn-killswitch dummy connection in NM, because
  the leftover one still owns pvpnksintrf0, then times out after 10 s and exits:

File ".../vpnconnector.py", line 294, in initialize_state
  await self._apply_kill_switch_setting(StateContext.kill_switch_setting)
File ".../wgkillswitch.py", line 74, in enable
  await self._ks_handler.add_kill_switch_connection(permanent)
File ".../killswitch_connection_handler.py", line 56, in _wrap_future
  return await asyncio.wait_for(
TimeoutError

nmcli showed four pvpn-killswitch connections plus a stale ProtonVPN SG#214.
Recovery: kill the app, nmcli con delete every pvpn-killswitch / ProtonVPN * connection,
ip link del pvpnksintrf0, relaunch.

Expected

• The first connect after boot succeeds, or at least retries NeedSecrets instead of
  reporting a fatal AuthDenied.
• A plugin/NM timeout is not reported to the user as an authentication error.
• On startup the app cleans up or reuses existing pvpn-killswitch connections instead of
  piling up duplicates and exiting.

[ptr1337]

Arch Packager here. Can you please try with following diff?

Ive precompiled a package and uploded it here:

sudo pacman -U https://debug.cachyos.org/protonvpn/python-proton-vpn-api-core-5.6.20-2-x86_64.pkg.tar.zst

If you want to compile yourself:

pkgctl repo clone --protocol=https python-proton-vpn-api-core
cd python-proton-vpn-api-core

Add patch to source and prepare, like this:

diff --git a/PKGBUILD b/PKGBUILD
index b7b61bb..9db02e3 100644
--- a/PKGBUILD
+++ b/PKGBUILD
@@ -3,7 +3,7 @@

 pkgname=python-proton-vpn-api-core
 pkgver=5.6.20
-pkgrel=1
+pkgrel=2
 _protun_commit=12e7755a112f59b7b843da79290b3de25febf653
 pkgdesc="The proton-vpn-core-api acts as a facade to the other Proton VPN components, exposing a uniform API to the available Proton VPN services."
 arch=(x86_64)
@@ -52,16 +52,20 @@ source=(
   "git+https://github.com/ProtonVPN/${pkgname}.git#tag=v${pkgver}"
   "protun::git+https://github.com/ProtonVPN/protun.git#commit=${_protun_commit}"
   fix-protun-protocol.patch
+  fix-protun-dbus-startup-race.patch
 )
 sha256sums=('90e811a2acf770d6611278c4fd7f68fa06b6c436caa47de5a2e0316673f0f4d4'
             '3f90b4967711c9750042b5621695ed91c374fab92d5e8fa2100645862a47f66b'
-            '28abe281b8dee47fe5b3e5f3a612a902f6e7504bcb7509e809e1d422c71df750')
+            '28abe281b8dee47fe5b3e5f3a612a902f6e7504bcb7509e809e1d422c71df750'
+            '36b89eacb44d3e4a63522db312ce8a138b1b80234b862566a59c2b6f8e2a0a7d')
 optdepends=("network-manager-applet: password prompt on Gnome and other GTK DEs"
             "plasma-nm: password prompt on KDE Plasma")

 prepare() {
   cd "$pkgname"
   patch -Np1 < ../fix-protun-protocol.patch
+  # https://github.com/ProtonVPN/python-proton-vpn-api-core/issues/31
+  patch -Np1 < ../fix-protun-dbus-startup-race.patch
   sed -i '/^SystemdService=/d' resources/nm-protun.name

   rm -rf dependencies/protun

diff --git a/src/protun/nm_protun_service/run.rs b/src/protun/nm_protun_service/run.rs
index e17cfa8..b36327e 100644
--- a/src/protun/nm_protun_service/run.rs
+++ b/src/protun/nm_protun_service/run.rs
@@ -25,7 +25,7 @@

 use std::sync::Arc;

-use zbus::Connection;
+use zbus::connection;

 use super::interfaces::new_interfaces;

@@ -41,20 +41,18 @@ pub async fn run() -> Result<(), Box<dyn std::error::Error>> {

     let shutdown = Arc::new(tokio::sync::Notify::new());
     let (plugin, connection_updates) = new_interfaces(shutdown.clone());
-    let zbus_connection = Connection::system().await?;
-
-    zbus_connection
-        .object_server()
-        .at(DBUS_OBJECT_PATH, plugin)
-        .await?;
-
-    zbus_connection
-        .object_server()
-        .at(DBUS_OBJECT_PATH, connection_updates)
+    // Use the connection builder so the object server is fully started
+    // before the bus name is requested. Registering interfaces on an
+    // existing connection starts the object server lazily without waiting
+    // for it, so NetworkManager could call NeedSecrets as soon as the name
+    // appears and the call would be silently dropped.
+    let _zbus_connection = connection::Builder::system()?
+        .serve_at(DBUS_OBJECT_PATH, plugin)?
+        .serve_at(DBUS_OBJECT_PATH, connection_updates)?
+        .name(DBUS_SERVICE_NAME)?
+        .build()
         .await?;

-    zbus_connection.request_name(DBUS_SERVICE_NAME).await?;
-
     log::info!(
         "Plugin registered at {} with service name {}",
         DBUS_OBJECT_PATH,

[eraezor]

Tested: rebuilt 5.6.10 with only the zbus connection::Builder patch applied (to isolate it from the 5.6.20 changes). After a reboot, the first connect succeeds: NeedSecrets is dispatched about 0.8 ms after Plugin registered, followed by ConnectInteractive and Connected. There's no 10 s timeout and no AuthDenied. Before the patch this failed on the first attempt of every boot. Thanks for the quick fix! Really appreciate all your work Peter, cachy is awesome

[ptr1337]

Tested: rebuilt 5.6.10 with only the zbus connection::Builder patch applied (to isolate it from the 5.6.20 changes). After a reboot, the first connect succeeds: NeedSecrets is dispatched about 0.8 ms after Plugin registered, followed by ConnectInteractive and Connected. There's no 10 s timeout and no AuthDenied. Before the patch this failed on the first attempt of every boot. Thanks for the quick fix! Really appreciate all your work Peter, cachy is awesome

Thanks for testing, ive forwarded it to the ProtonVPN Developer Team.