bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi,

The /var/log/messages excerpt you sent me has nothing beyond:

> Jun 11 11:43:33 localhost shepherd[1]: Service networking has been started.

[…]

> Jun 11 11:43:33 localhost vmunix: [5.552395] wireguard: WireGuard
> 1.0.0 loaded. See www.wireguard.com for information.
> Jun 11 11:43:33 localhost vmunix: [5.552398] wireguard: Copyright
> (C) 2015-2019 Jason A. Donenfeld . All Rights
> Reserved.
> Jun 11 11:43:33 localhost shepherd[1]: Failed to start wireguard-test
> in the background.

That there’s not a single error message from wireguard doesn’t help.

Mathieu, Guillaume: any idea what might prevent the wireguard Shepherd
service from starting, or how we could gather debugging info?

(Context: .)

Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi,

Nathan Dehnel  skribis:

> I tried it again and found this
> Jun  9 10:47:44 localhost vmunix: [6.497581] wireguard: WireGuard
> 1.0.0 loaded. See www.wireguard.com for information.
> Jun  9 10:47:44 localhost vmunix: [6.497584] wireguard: Copyright
> (C) 2015-2019 Jason A. Donenfeld . All Rights
> Reserved.
> Jun  9 10:47:44 localhost shepherd[1]: Failed to start wireguard-test
> in the background.

Could you provide me (privately if you prefer) the /var/log/messages
sequence starting from boot (the line that reads “syslogd (GNU inetutils
2.0): restart”) up to the last line above?

Thanks in advance,
Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Nathan Dehnel]

>There should be lines like:

 > shepherd[1]: Service 'wireguard-XXX' has been started.

>Perhaps they’ve been moved to a different files due to log rotation?

>Without these, I cannot tell what happened.

I tried it again and found this
Jun  9 10:47:44 localhost vmunix: [6.497581] wireguard: WireGuard
1.0.0 loaded. See www.wireguard.com for information.
Jun  9 10:47:44 localhost vmunix: [6.497584] wireguard: Copyright
(C) 2015-2019 Jason A. Donenfeld . All Rights
Reserved.
Jun  9 10:47:44 localhost shepherd[1]: Failed to start wireguard-test
in the background.

On Thu, Jun 9, 2022 at 10:05 AM Ludovic Courtès  wrote:
>
> Hi Nathan,
>
> Nathan Dehnel  skribis:
>
> >>Could you be more specific?  Specifically, could you share
> >>/var/log/messages for the parts related to Wireguard?
> >
> > root@guixtest ~# cat /var/log/messages | grep -i wireguardJun  8
> > 18:20:07 localhost vmunix: [6.330271] wireguard: WireGuard 1.0.0
> > loaded. See www.wireguard.com for information.
> > Jun  8 18:20:07 localhost vmunix: [6.330276] wireguard: Copyright
> > (C) 2015-2019 Jason A. Donenfeld . All Rights
> > Reserved.
>
> There should be lines like:
>
>   shepherd[1]: Service 'wireguard-XXX' has been started.
>
> Perhaps they’ve been moved to a different files due to log rotation?
>
> Without these, I cannot tell what happened.
>
> >>However, the standard
> >>service constructors/destructors no longer block, and shepherd can serve
> >>multiple clients concurrently.
> >
> > I don't know, I guess wireguard uses "non-standard" constructors.
>
> Indeed, it invokes ‘wg-quick up’ and waits for completion.
>
> I suppose that command blocks until it has set up the VPN, right?
>
> If so, we’ll need to rewrite it differently.
>
> Thanks,
> Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi Nathan,

Nathan Dehnel  skribis:

>>Could you be more specific?  Specifically, could you share
>>/var/log/messages for the parts related to Wireguard?
>
> root@guixtest ~# cat /var/log/messages | grep -i wireguardJun  8
> 18:20:07 localhost vmunix: [6.330271] wireguard: WireGuard 1.0.0
> loaded. See www.wireguard.com for information.
> Jun  8 18:20:07 localhost vmunix: [6.330276] wireguard: Copyright
> (C) 2015-2019 Jason A. Donenfeld . All Rights
> Reserved.

There should be lines like:

  shepherd[1]: Service 'wireguard-XXX' has been started.

Perhaps they’ve been moved to a different files due to log rotation?

Without these, I cannot tell what happened.

>>However, the standard
>>service constructors/destructors no longer block, and shepherd can serve
>>multiple clients concurrently.
>
> I don't know, I guess wireguard uses "non-standard" constructors.

Indeed, it invokes ‘wg-quick up’ and waits for completion.

I suppose that command blocks until it has set up the VPN, right?

If so, we’ll need to rewrite it differently.

Thanks,
Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Nathan Dehnel]

>Could you be more specific?  Specifically, could you share
>/var/log/messages for the parts related to Wireguard?

root@guixtest ~# cat /var/log/messages | grep -i wireguardJun  8
18:20:07 localhost vmunix: [6.330271] wireguard: WireGuard 1.0.0
loaded. See www.wireguard.com for information.
Jun  8 18:20:07 localhost vmunix: [6.330276] wireguard: Copyright
(C) 2015-2019 Jason A. Donenfeld . All Rights
Reserved.

>However, the standard
>service constructors/destructors no longer block, and shepherd can serve
>multiple clients concurrently.

I don't know, I guess wireguard uses "non-standard" constructors.

On Thu, Jun 2, 2022 at 8:38 AM Ludovic Courtès  wrote:
>
> Hi Nathan,
>
> Nathan Dehnel  skribis:
>
> > Just tested and Shepherd 0.9 does not fix this issue.
>
> Could you be more specific?  Specifically, could you share
> /var/log/messages for the parts related to Wireguard?
>
> > On Mon, Jan 17, 2022 at 7:48 AM Ludovic Courtès  wrote:
>
> [...]
>
> >> One command sent to shepherd by ‘herd …’ must have completed before the
> >> next one is processed.
> >>
> >> You can experience it like this:
> >>
> >>   sudo herd eval root '(sleep 3)' & echo status && sudo herd status
> >>
> >> Here the first ‘herd’ command has shepherd block for 3 seconds, so the
> >> second ‘herd’ command won’t print anything until 3 seconds have passed.
>
> This is actually still the case with 0.9, because here we’re calling
> (@ (guile) sleep), which blocks.  So… not a good example.
>
> The short story is: it is still possible to write code that blocks
> shepherd, as with the ‘sleep’ example above.  However, the standard
> service constructors/destructors no longer block, and shepherd can serve
> multiple clients concurrently.
>
> Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi Nathan,

Nathan Dehnel  skribis:

> Just tested and Shepherd 0.9 does not fix this issue.

Could you be more specific?  Specifically, could you share
/var/log/messages for the parts related to Wireguard?

> On Mon, Jan 17, 2022 at 7:48 AM Ludovic Courtès  wrote:

[...]

>> One command sent to shepherd by ‘herd …’ must have completed before the
>> next one is processed.
>>
>> You can experience it like this:
>>
>>   sudo herd eval root '(sleep 3)' & echo status && sudo herd status
>>
>> Here the first ‘herd’ command has shepherd block for 3 seconds, so the
>> second ‘herd’ command won’t print anything until 3 seconds have passed.

This is actually still the case with 0.9, because here we’re calling
(@ (guile) sleep), which blocks.  So… not a good example.

The short story is: it is still possible to write code that blocks
shepherd, as with the ‘sleep’ example above.  However, the standard
service constructors/destructors no longer block, and shepherd can serve
multiple clients concurrently.

Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Nathan Dehnel]

Just tested and Shepherd 0.9 does not fix this issue.

On Mon, Jan 17, 2022 at 7:48 AM Ludovic Courtès  wrote:
>
> Hi,
>
> Nathan Dehnel  skribis:
>
> >>What do you mean by “freezing”?  Does ‘herd status’ and similar commands
> > block forever?
> > Yes
> >
> >>Requests in the Shepherd are currently handled sequentially.  So if you
> > issue several ‘herd restart’ commands, they’ll be processed one at a
> > time.  This is usually okay because ‘start’ commands are expected to be
> > quick (just wait for the daemon to write its PID file or similar).
> > What is the nature of this serialization? Does wireguard need to
> > finish before resolvconf can start? Because that's probably the issue.
>
> One command sent to shepherd by ‘herd …’ must have completed before the
> next one is processed.
>
> You can experience it like this:
>
>   sudo herd eval root '(sleep 3)' & echo status && sudo herd status
>
> Here the first ‘herd’ command has shepherd block for 3 seconds, so the
> second ‘herd’ command won’t print anything until 3 seconds have passed.
>
> HTH,
> Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi,

Nathan Dehnel  skribis:

>>What do you mean by “freezing”?  Does ‘herd status’ and similar commands
> block forever?
> Yes
>
>>Requests in the Shepherd are currently handled sequentially.  So if you
> issue several ‘herd restart’ commands, they’ll be processed one at a
> time.  This is usually okay because ‘start’ commands are expected to be
> quick (just wait for the daemon to write its PID file or similar).
> What is the nature of this serialization? Does wireguard need to
> finish before resolvconf can start? Because that's probably the issue.

One command sent to shepherd by ‘herd …’ must have completed before the
next one is processed.

You can experience it like this:

  sudo herd eval root '(sleep 3)' & echo status && sudo herd status

Here the first ‘herd’ command has shepherd block for 3 seconds, so the
second ‘herd’ command won’t print anything until 3 seconds have passed.

HTH,
Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Nathan Dehnel]

>What do you mean by “freezing”?  Does ‘herd status’ and similar commands
block forever?
Yes

>Requests in the Shepherd are currently handled sequentially.  So if you
issue several ‘herd restart’ commands, they’ll be processed one at a
time.  This is usually okay because ‘start’ commands are expected to be
quick (just wait for the daemon to write its PID file or similar).
What is the nature of this serialization? Does wireguard need to
finish before resolvconf can start? Because that's probably the issue.


On Thu, Jan 13, 2022 at 9:11 AM Ludovic Courtès  wrote:
>
> Hi,
>
> Nathan Dehnel  skribis:
>
> > When dns is specified, wireguard runs wg-quick, which runs resolvconf,
> > which runs /run/current-system/profile/bin/herd restart, which causes
> > shepherd to freeze because I guess it doesn't like being given
> > multiple start commands at once. I'm not sure how to fix it.
>
> What do you mean by “freezing”?  Does ‘herd status’ and similar commands
> block forever?  Or is it something else?
>
> Requests in the Shepherd are currently handled sequentially.  So if you
> issue several ‘herd restart’ commands, they’ll be processed one at a
> time.  This is usually okay because ‘start’ commands are expected to be
> quick (just wait for the daemon to write its PID file or similar).
>
> Thanks,
> Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Ludovic Courtès]

Hi,

Nathan Dehnel  skribis:

> When dns is specified, wireguard runs wg-quick, which runs resolvconf,
> which runs /run/current-system/profile/bin/herd restart, which causes
> shepherd to freeze because I guess it doesn't like being given
> multiple start commands at once. I'm not sure how to fix it.

What do you mean by “freezing”?  Does ‘herd status’ and similar commands
block forever?  Or is it something else?

Requests in the Shepherd are currently handled sequentially.  So if you
issue several ‘herd restart’ commands, they’ll be processed one at a
time.  This is usually okay because ‘start’ commands are expected to be
quick (just wait for the daemon to write its PID file or similar).

Thanks,
Ludo’.

bug#53225: shepherd freezes if wireguard is started with dns config enabled

[Nathan Dehnel]

When dns is specified, wireguard runs wg-quick, which runs resolvconf,
which runs /run/current-system/profile/bin/herd restart, which causes
shepherd to freeze because I guess it doesn't like being given
multiple start commands at once. I'm not sure how to fix it.