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

kartikbabu-bg commented 2 years ago

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 commented 2 years ago

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

kartikbabu-bg commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 1 year ago

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.

dsommers commented 2 months ago

I'm closing this ticket now. It's been lingering for too long and lots of things has happened since the last update. The Ubuntu 18.04 release has been EOL for over a year and both v21 and v22_dev should be available for newer releases.

If this issue is still present on Ubuntu 22.04 running v22_dev, please file a new issue ticket on Codeberg.

OpenVPN / openvpn3-linux

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