Is systemd notification too soon?

This forum is for admins who are looking to build or expand their OpenVPN setup.
Forum rules
Please use the [oconf] BB tag for openvpn Configurations. See viewtopic.php?f=30&t=21589 for an example.
Post Reply
flewaway
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Is systemd notification too soon?

Post by flewaway » Wed Mar 31, 2021 11:00 pm

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?

User avatar
TinCanTech
OpenVPN Protagonist
Posts: 9018
Joined: Fri Jun 03, 2016 1:17 pm

Re: Is systemd notification too soon?

Post by TinCanTech » Wed Mar 31, 2021 11:35 pm


flewaway
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Re: Is systemd notification too soon?

Post by flewaway » Wed Mar 31, 2021 11:54 pm

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?

User avatar
TinCanTech
OpenVPN Protagonist
Posts: 9018
Joined: Fri Jun 03, 2016 1:17 pm

Re: Is systemd notification too soon?

Post by TinCanTech » Thu Apr 01, 2021 1:27 am

flewaway wrote:
Wed Mar 31, 2021 11:00 pm
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:
TinCanTech wrote:
Wed Mar 31, 2021 11:35 pm
viewtopic.php?f=30&t=22603#p68963
which you chose to ignore...

flewaway
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Re: Is systemd notification too soon?

Post by flewaway » Thu Apr 01, 2021 5:58 am

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

flewaway
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Re: Is systemd notification too soon?

Post by flewaway » Fri Apr 02, 2021 7:48 am

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
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Re: Is systemd notification too soon?

Post by flewaway » Fri Apr 02, 2021 11:22 am

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
OpenVpn Newbie
Posts: 6
Joined: Wed Mar 31, 2021 10:50 pm

Re: Is systemd notification too soon?

Post by flewaway » Mon Apr 12, 2021 12:51 pm

TinCanTech wrote:
Thu Apr 01, 2021 1:27 am
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?

Post Reply