dbus error with openvpn3 on EL7

[opoplawski]

Testing out the openvpn3 client on EL7. Seems to be working, but I am seeing some error messages:

Apr 20 14:32:01  dbus[5335]: [system] Successfully activated service 'net.openvpn.v3.backends'
Apr 20 14:32:01  net.openvpn.v3.backends[5335]: Re-initiated process from pid 26757 to backend process pid 26758
Apr 20 14:32:01  net.openvpn.v3.backends[5335]: OpenVPN 3/Linux v5_beta (openvpn3-service-client)
Apr 20 14:32:01  net.openvpn.v3.backends[5335]: OpenVPN core 3.git:HEAD:d4e50f8c linux x86_64 64-bit built on Apr  8 2019 19:27:55
Apr 20 14:32:01  net.openvpn.v3.backends[5335]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
Apr 20 14:32:01  openvpn3-service-logger[26710]: Logger VERB2: Attached: [:1.225/net.openvpn.v3.backends]  {tag:2747416622617513492}
Apr 20 14:32:01  openvpn3-service-logger[26710]: Logger VERB2: Attached: [:1.225/net.openvpn.v3.sessions]  {tag:12808456550255092827}
Apr 20 14:32:01  openvpn3-service-logger[26710]: {tag:2747416622617513492} Client VERB1: Initializing VPN client session, token 2aa3cf59t3dc3t49fet9040t3c04597f6c46
Apr 20 14:32:01  dbus[5335]: [system] Activating service name='net.openvpn.v3.netcfg' (using servicehelper)
Apr 20 14:32:01  openvpn3-service-logger[26710]: {tag:2747416622617513492} Client VERB1: Configuration override 'persist-tun' set to True
Apr 20 14:32:01  openvpn3-service-logger[26710]: Logger VERB2: Attached: [:1.226/net.openvpn.v3.netcfg]  {tag:6052018150848225234}
Apr 20 14:32:01  openvpn3-service-logger[26710]: Logger VERB2: Attached: [:1.226/net.openvpn.v3.netcfg.core]  {tag:10250592700443972709}
Apr 20 14:32:01  net.openvpn.v3.netcfg[5335]: OpenVPN 3/Linux v5_beta (openvpn3-service-netcfg)
Apr 20 14:32:01  net.openvpn.v3.netcfg[5335]: OpenVPN core 3.git:HEAD:d4e50f8c linux x86_64 64-bit built on Apr  8 2019 19:28:01
Apr 20 14:32:01  net.openvpn.v3.netcfg[5335]: Copyright (C) 2012-2017 OpenVPN Inc. All rights reserved.
Apr 20 14:32:01  dbus[5335]: [system] Successfully activated service 'net.openvpn.v3.netcfg'
Apr 20 14:32:01  openvpn3-service-logger[26710]: {tag:6052018150848225234} Network Configuration VERB1: Redirect method: host-route
Apr 20 14:32:02  dbus[5335]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.225" (uid=992 pid=26758 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.221" (uid=992 pid=26705 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Apr 20 14:32:02  openvpn3-servic[26758]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Apr 20 14:32:05  openvpn3-servic[26758]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Apr 20 14:32:05  dbus[5335]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.225" (uid=992 pid=26758 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.221" (uid=992 pid=26705 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Apr 20 14:32:11  openvpn3-service-logger[26710]: Logger VERB2: Detached: [:1.224/net.openvpn.v3.backends] {tag:11667059514516551004}
Apr 20 14:32:12  openvpn3-servic[26758]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
Apr 20 14:32:12  dbus[5335]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.225" (uid=992 pid=26758 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.221" (uid=992 pid=26705 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")
Apr 20 14:32:12  openvpn3-service-logger[26710]: {tag:2747416622617513492} Client INFO: Starting connection

openvpn3-client-5-0.beta1.el7.x86_64

[David Sommerseth]

Thanks for testing!

There are two issues here, they are kind of known and not completely unexpected. I will try to get these sorted out for the next beta releases.

Issue 1:

Apr 20 14:32:02  dbus[5335]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.225" (uid=992 pid=26758 comm="/usr/libexec/openvpn3-linux/openvpn3-service-clien") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.221" (uid=992 pid=26705 comm="/usr/libexec/openvpn3-linux/openvpn3-service-sessi")

Issue 2

Apr 20 14:32:02  openvpn3-servic[26758]: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

[David Sommerseth]

This issue should be fixed by this commit:

commit f4ecd91a5feef5461371e2c1da301b76cc0c37b8
Author: David Sommerseth <davids@openvpn.net>
Date:   Thu Dec 19 20:33:38 2019 +0100

    client: Fix incorrect return in the Ready D-Bus method
    
    If the net.openvpn.v3.backends.Ready method call throws a D-Bus
    exception, it would first call g_dbus_method_invocation_return_gerror()
    and then call g_dbus_method_invocation_return_value(invoc, NULL) later
    in the callback method.  This results in the following errors in the
    logs:
    
      dbus[1665]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.573" (uid=989 pid=21817 comm="/usr/local/openvpn-dev/libexec/openvpn3-linux/open") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.150" (uid=989 pid=6527 comm="/usr/local/openvpn-dev/libexec/openvpn3-linux/open")
      (process:21817): GLib-GObject-CRITICAL **: 20:25:46.794: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
    
    The proper fix is to return from the callback method right after calling
    the g_dbus_method_invocation_return_gerror() call.
    
    Trac: #1180
    Signed-off-by: David Sommerseth <davids@openvpn.net>

The complete commit on ​GitHub and ​GitLab

This will be part of the next v8_beta release.