Is systemd notification too soon?

[flewaway]

Hi,

I'm late into migrating a CentOS 6 service to CentOS 7 and I'm having trouble with an openvpn dependency.

On CentOS 6, starting after openvpn meant that the VPN was generally up and running before the next service started. systemd changes all of that.

What appears to happen is that openvpn (client mode) appears to notify systemd that the VPN tunnel is up at about the same time as the openvpn client sends the "PUSH_REQUEST". This is important because there's a 1 to 2 second window here where the openvpn client hasn't configured the networking but the openvpn tunnel is up.

What appears to happen is that the openvpn client notifies systemd that it is alive and well at around the same time as the PUSH_REQUEST is sent. systemd then sees that the dependency on openvpn-client@server can be satisfied and starts prorgrams that want to talk over the VPN. If they start before the openvpn client has finished configuring the interface (i.e adding static routes that are pushed or running external scripts using "up") then they fail to connect.

Comparing the openvpn log file with the "active" state of the systemd service, it appears that the systemd service goes active somewhere between the "Peer connection Initiated with" and "SENT CONTROL" log messages (verb 4.)

Should systemd receive its "Active" notification when openvpn reaches the "Initialization Sequence Completed" stage instead?

[TinCanTech]

viewtopic.php?f=30&t=22603#p68963

[flewaway]

Ok, that's 1 reply that didn't understand the question/problem (hint: openvpn log files/config files alone won't provide the answer.)

Do I have to dig into the source code and provide a suggested patch before I get a worthwhile reply?

[TinCanTech]

it appears that the systemd service goes active somewhere between the "Peer connection Initiated with" and "SENT CONTROL" log messages (verb 4.)

We can just take your word on that then .. I mean, if you don't want to share your logs, as per the request clearly made here:

viewtopic.php?f=30&t=22603#p68963

which you chose to ignore...

[flewaway]

I'll be back after i've checked the source code and found the bug.

[flewaway]

The problem is here in src/openvpn/init.c (from 2.4.6):

Code: Select all

#ifdef ENABLE_SYSTEMD
    /* We can report the PID via getpid() to systemd here as OpenVPN will not
     * do any fork due to daemon() a future call.
     * See possibly_become_daemon() [init.c] for more details.
     */
    sd_notifyf(0, "READY=1\nSTATUS=Pre-connection initialization successful\nMAINPID=%lu",
               (unsigned long) getpid());
#endif

What we see here is openvpn telling systemd that it is "ready" because pre-connection initialization has been successful.

For a service that is dependent on the openvpn-client status reflecting that the tunnel is actually up, the above notification is misleading. Providing an update for STATUS is correct, but stating "READY=1" is not correct for client mode operation.

[flewaway]

This is the change that looks necessary ... need to test.

The logic here is that the server side initialization is fairly simple for it to declare "I'm ready" to accept incoming client connections. For the client side, I've used the log message that I've referred to above as being the "indicator" that the link has come up. There may be better internal context to go by but I don't know the openvpn source code in detail (nor its internal state machine.)

Code: Select all

--- init.c.orig 2018-04-24 17:12:55.000000000 +1000
+++ init.c      2021-04-02 22:20:07.000000000 +1100
@@ -650,12 +650,14 @@
 #endif

 #ifdef ENABLE_SYSTEMD
-    /* We can report the PID via getpid() to systemd here as OpenVPN will not
-     * do any fork due to daemon() a future call.
-     * See possibly_become_daemon() [init.c] for more details.
-     */
-    sd_notifyf(0, "READY=1\nSTATUS=Pre-connection initialization successful\nMAINPID=%lu",
-               (unsigned long) getpid());
+    if (c->cptions.mode == MODE_SERVER) {
+        /* We can report the PID via getpid() to systemd here as OpenVPN will not
+         * do any fork due to daemon() a future call.
+         * See possibly_become_daemon() [init.c] for more details.
+         */
+        sd_notifyf(0, "READY=1\nSTATUS=Pre-connection initialization successful\nMAINPID=%lu",
+                   (unsigned long) getpid());
+    }
 #endif

 }
@@ -1515,16 +1517,20 @@
     }
     else
     {
-#ifdef ENABLE_SYSTEMD
-        sd_notifyf(0, "STATUS=%s", message);
-#endif
         msg(M_INFO, "%s", message);
-    }

-    /* Flag that we initialized */
-    if ((flags & (ISC_ERRORS|ISC_SERVER)) == 0)
-    {
-        c->options.no_advance = true;
+        /* Flag that we initialized */
+        if ((flags & ISC_SERVER) == 0)
+        {
+#ifdef ENABLE_SYSTEMD
+            sd_notifyf(0, "READY=1\nSTATUS=%s", message);
+#endif
+            c->options.no_advance = true;
+        } else {
+#ifdef ENABLE_SYSTEMD
+            sd_notifyf(0, "STATUS=%s", message);
+#endif
+        }
     }

 #ifdef _WIN32

[flewaway]

which you chose to ignore...

Yes, because the problem is not a configuration problem - openvpn client & server work fine - it is an interaction problem: how well does openvpn play with systemd? That isn't something that can be configured and there's nothing in the log files that relate directly to how openvpn is communicating with systemd. The problem is a result of a dependency created between openvpn and other services using systemd.

Or in other words, providing the configuration and log files referenced in your link would be of no use to addressing this problem because the evidence of the problem is not in the openvpn logs and nor is the behaviour of openvpn & others under systemd controllable via the openvpn configuration file.

Now, how do I file a bug with openvpn to get someone to look at the source code/integrate/fix?