Ubuntu 18.04: openvpn3 will hang on `session-start` after disconnect

[kartikbabu-bg]

I'm doing all my testing inside a Virtualbox VM running Ubuntu 18.04.6 server:

• Upon bootup, openvpn3 session-start --config client.ovpn successfully connects

ator:~$ openvpn3 session-start --config client.ovpn 
Using configuration profile from file: client.ovpn
Session path: /net/openvpn/v3/sessions/b53abdf4s5391s48b9s87das1e377d9226e6
Auth User name: <REDACTED-USERNAME>
Auth Password: 
Connected

• I can also close the session using the session-manage option:

ator:~$ openvpn3 session-manage --config client.ovpn --disconnect
Initiated session shutdown.

Connection statistics:
     BYTES_IN....................7144
     BYTES_OUT...................6379
     PACKETS_IN....................34
     PACKETS_OUT...................41
     TUN_BYTES_IN................2134
     TUN_BYTES_OUT...............2430
     TUN_PACKETS_IN................25
     TUN_PACKETS_OUT...............19

• However, when I attempt to reconnect after this first disconnect, openvpn3 will hang indefinitely after I finish entering my username/password credentials. Only a reboot of the VM will allow me to reconnect again successfully.

[dsommers]

Which openvpn3-service-* processes are running when you experience this hang? And what does the journalctl report, related to OpenVPN events?

[kartikbabu-bg]

When the connection succeeds, this the process list:

ator:~$ ps -Af | grep openvpn3
openvpn   1678     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-sessionmgr
openvpn   1687     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-logger --service --state-dir /var/lib/openvpn3 --log-level 4 --syslog
openvpn   1693     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-configmgr --state-dir /var/lib/openvpn3/configs
openvpn   1703     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-client 3cf21d10td1f3t46b0tb5d0tca5d0fa75c34
openvpn   1708     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-netcfg --resolv-conf /etc/resolv.conf --state-dir /var/lib/openvpn3

And the journalctl output:

Jul 05 15:57:29 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.sessions' requested by ':1.17' (uid=1000 pid=1674 comm="openvpn3 session-start --config client-too.ovpn --" label="unconfined") (using servicehelper)
Jul 05 15:57:29 rpw-emulator net.openvpn.v3.sessions[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-sessionmgr)
Jul 05 15:57:29 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.log' requested by ':1.18' (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") (using servicehelper)
Jul 05 15:57:29 rpw-emulator net.openvpn.v3.log[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-logger)
Jul 05 15:57:30 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.configuration' requested by ':1.17' (uid=1000 pid=1674 comm="openvpn3 session-start --config client-too.ovpn --" label="unconfined") (using servicehelper)
Jul 05 15:57:30 rpw-emulator net.openvpn.v3.configuration[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-configmgr)
Jul 05 15:57:31 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.18' (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") (using servicehelper)
Jul 05 15:57:31 rpw-emulator net.openvpn.v3.backends[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-backendstart)
Jul 05 15:57:31 rpw-emulator net.openvpn.v3.backends[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-client)
Jul 05 15:57:31 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.netcfg' requested by ':1.22' (uid=121 pid=1703 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") (using servicehelper)
Jul 05 15:57:31 rpw-emulator net.openvpn.v3.netcfg[620]: Loading configuration file: /var/lib/openvpn3/netcfg.json
Jul 05 15:57:31 rpw-emulator net.openvpn.v3.netcfg[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-netcfg)
Jul 05 15:57:36 rpw-emulator openvpn3-servic[1703]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jul 05 15:57:36 rpw-emulator dbus-daemon[620]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.22" (uid=121 pid=1703 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined")
Jul 05 15:57:39 rpw-emulator openvpn3-servic[1703]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jul 05 15:57:39 rpw-emulator dbus-daemon[620]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.22" (uid=121 pid=1703 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined")

[kartikbabu-bg]

After I disconnect:

ator:~$ openvpn3 session-manage --path /net/openvpn/v3/sessions/96b784ffsc945s4228sbba9se8093a351b9a --disconnect
Initiated session shutdown.

Connection statistics:
     BYTES_IN....................5728
     BYTES_OUT...................5115
     PACKETS_IN....................35
     PACKETS_OUT...................41
     TUN_BYTES_IN.................646
     TUN_BYTES_OUT................816
     TUN_PACKETS_IN................11
     TUN_PACKETS_OUT................4

ator:~$ ps -Af | grep openvpn3
openvpn   1678     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-sessionmgr
openvpn   1687     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-logger --service --state-dir /var/lib/openvpn3 --log-level 4 --syslog
openvpn   1693     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-configmgr --state-dir /var/lib/openvpn3/configs
openvpn   1708     1  0 15:57 ?        00:00:00 /usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-service-netcfg --resolv-conf /etc/resolv.conf --state-dir /var/lib/openvpn3

journalctl only shows one additional log entry:

Jul 05 16:03:30 rpw-emulator net.openvpn.v3.configuration[620]: openvpn3-service-configmgr starting idle shutdown (pid: 1693)

[kartikbabu-bg]

new journalctl log entries upon hang:

Jul 05 16:05:12 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.configuration' requested by ':1.25' (uid=1000 pid=1767 comm="openvpn3 session-start --config client-too.ovpn --" label="unconfined") (using servicehelper)
Jul 05 16:05:12 rpw-emulator net.openvpn.v3.configuration[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-configmgr)
Jul 05 16:05:13 rpw-emulator dbus-daemon[620]: [system] Activating service name='net.openvpn.v3.backends' requested by ':1.18' (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") (using servicehelper)
Jul 05 16:05:13 rpw-emulator net.openvpn.v3.backends[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-backendstart)
Jul 05 16:05:13 rpw-emulator net.openvpn.v3.backends[620]: OpenVPN 3/Linux v18_beta (openvpn3-service-client)
Jul 05 16:05:18 rpw-emulator openvpn3-servic[1781]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jul 05 16:05:18 rpw-emulator dbus-daemon[620]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.28" (uid=121 pid=1781 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined")
Jul 05 16:05:34 rpw-emulator openvpn3-servic[1781]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jul 05 16:05:34 rpw-emulator dbus-daemon[620]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.28" (uid=121 pid=1781 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined")

[dsommers]

These [system] Rejected send message errors indicate some D-Bus policy issues.

Can you verify that you don't have any net.openvpn.v3.*.conf policy files in /etc/dbus-1/system.d but that they are in /usr/share/dbus-1/system.d/ ?

In addition, double check that /usr/share/dbus-1/system.d/net.openvpn.v3.log.conf contains a block with: <policy context="mandatory">...</policy>.

[kartikbabu-bg]

I verified that the files are where they are expected to be, and this is the mandatory policy context tag in /usr/share/dbus-1/system.d/net.openvpn.v3.log.conf

  <policy context="mandatory">
    <!--
          Needed to allow log forwarding which are
          requested via net.openvpn.v3.sessions but
          delivered by net.openvpn.v3.log to another
          log listener, typically without a well-known
          busname
    -->
    <allow receive_sender="net.openvpn.v3.log"
           receive_interface="net.openvpn.v3.backends"
           receive_type="signal"
           receive_member="Log"/>
    <allow receive_sender="net.openvpn.v3.log"
           receive_interface="net.openvpn.v3.backends"
           receive_type="signal"
           receive_member="StatusChange"/>
  </policy>

[dsommers]

Hey again, it's been silent from me - I'm sorry for that. This issue has anyway been bothering me for quite some time.

I believe might have stumbled across a similar situation now in one of my development boxes. I am working on some fixes which I believe is related to these two log lines:

Jul 05 15:57:36 rpw-emulator openvpn3-servic[1703]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Jul 05 15:57:36 rpw-emulator dbus-daemon[620]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.22" (uid=121 pid=1703 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.18" (uid=121 pid=1678 comm="/usr/lib/x86_64-linux-gnu/openvpn3-linux/openvpn3-" label="unconfined")

And I have a strong hunch these log incidents is related to why openvpn3 session-manage --disconnect halts on your end.

It would be great if you could verify one detail for me .... In this old example I see PID 1703 having issues. Can you verify to me that this is the openvpn3-service-client process?

A possible way to check this is to do the openvpn3 session-start, then do a openvpn3-admin log-service --list-subscriptions and ps faxuw | grep openvpn3-service-client. Save the output of these two commands and then do a openvpn3 session-manage --disconnect and inspect the journalctl again.