Timing issue (?) with wg-quick up on Raspberry Pi B+

Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jim Darby]

[-- Attachment #1: Type: text/plain, Size: 1216 bytes --]

I've been using WireGuard and it's proven great. However, I've noticed a 
perclirary on a Raspberry Pi B+.

When I do a wg-quick up wg0 it echos the commands it's running and 
they're fine. So it says:

    [#] ip link add wg0 type wireguard
    [#] wg setconf wg0 /dev/fd/63
    [#] ip address add 192.168.2.3/32 dev wg0
    [#] ip link set mtu 1420 dev wg0
    [#] ip link set wg0 up
    [#] ip route add 192.168.2.0/24 dev wg0

However, if I look at wg0 I get:

wg0       Link encap:UNSPEC  HWaddr 
00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
           UP POINTOPOINT RUNNING NOARP MTU:1420  Metric:1
           RX packets:0 errors:0 dropped:0 overruns:0 frame:0
           TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
           collisions:0 txqueuelen:1
           RX bytes:0 (0.0 B)  TX bytes:0 (0.0 B)

So, it's all worked /apart/ from the ip address add 192.168.2.3/32 dev wg0.

It works fine on the faster Raspberry Pi 3 and if run the ip address 
command manually it performs perfectly.

This leads me to suspect some sort of timing problem that rarely shows 
due to most machines being significantly faster.

Any ideas?

Regards,

Jim.



[-- Attachment #2: Type: text/html, Size: 2503 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

Hey Jim,

That's very odd indeed. Do you have any other network management
daemons running on there that could be interfering?

Also: what snapshot version, kernel version, distribution, etc are you
using? Anything odd in dmesg after running wg-quick?

Regards,
Jason

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jim Darby]

[-- Attachment #1: Type: text/plain, Size: 1583 bytes --]

Hi Jason,

Thanks for the very quick response.

It happens with both the August and September snapshots. Kernel 4.9.35+, 
Raspbian based on Debian 9 and nothing odd in dmesg.

However, your comment about network management daemons running is most 
interesting. Here's an extract from journalctl's output:

    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: ifplugd 0.28 initializing.
    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Using interface
    wg0/00:00:00:00:00:00
    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Using detection mode:
    IFF_RUNNING
    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Initialization complete,
    link beat detected.
    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Executing
    '/etc/ifplugd/ifplugd.action wg0 up'.
    Sep 09 21:31:28 janus ifplugd(wg0)[6903]: client: Ignoring unknown
    interface wg0=wg0.
    Sep 09 21:31:29 janus ifplugd(wg0)[6903]: Program executed successfully.

So, something is triggering ifplug. I'm unsure what it might be doing 
and it /seems/ to imply that it's ignoring it but maybe this is the 
cause of the problem. wg0 is /not/ mentioned in /etc/network/interfaces 
so maybe ifup is trying to be helpful? There may well be a race 
condition between ifup and wg-quick…

Regards,

Jim.



On 10/09/17 13:44, Jason A. Donenfeld wrote:
> Hey Jim,
>
> That's very odd indeed. Do you have any other network management
> daemons running on there that could be interfering?
>
> Also: what snapshot version, kernel version, distribution, etc are you
> using? Anything odd in dmesg after running wg-quick?
>
> Regards,
> Jason


[-- Attachment #2: Type: text/html, Size: 2540 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

On Sun, Sep 10, 2017 at 3:09 PM, Jim Darby <uberscubajim@gmail.com> wrote:
> However, your comment about network management daemons running is most
> interesting. Here's an extract from journalctl's output:
> Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Executing
> '/etc/ifplugd/ifplugd.action wg0 up'.
> Sep 09 21:31:28 janus ifplugd(wg0)[6903]: client: Ignoring unknown interface
> wg0=wg0.

That is interesting. Thanks for that. Indeed it looks like ifplugd is
just calling ifup wg0, and I'm not totally sure why that would remove
an IP address if there's nothing in /etc/network/interfaces, though
I'm not a huge Debian person so there could be a detail I'm
overlooking.

Another more direct way that might help debug this is `ip monitor
all`. On my (working) system, running `ip monitor all` in one window
and `wg-quick up martino` in another yields this:

[NETCONF]ipv4 dev martino forwarding off rp_filter loose mc_forwarding
off proxy_neigh off ignore_routes_with_linkdown off
[NETCONF]ipv6 dev martino forwarding off mc_forwarding off proxy_neigh
off ignore_routes_with_linkdown off
[LINK]107: martino: <POINTOPOINT,NOARP,200000> mtu 1420 qdisc noop
state DOWN group default
   link/none
[ADDR]107: martino    inet 10.10.11.100/32 scope global martino
      valid_lft forever preferred_lft forever
[ROUTE]local 10.10.11.100 dev martino table local proto kernel scope
host src 10.10.11.100
[ROUTE]ff00::/8 dev martino table local metric 256 linkdown pref medium
[ROUTE]2a01:e35:8be7:9122:100::/96 dev martino proto kernel metric 256
linkdown pref medium
[ADDR]107: martino    inet6 2a01:e35:8be7:9122:100::1/96 scope global
      valid_lft forever preferred_lft forever
[ROUTE]local 2a01:e35:8be7:9122:100::1 dev lo table local proto kernel
metric 0 pref medium
[LINK]107: martino: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1420 qdisc
noqueue state UNKNOWN group default
   link/none
[ROUTE]default dev martino table 51820 metric 1024 pref medium
[RULE]32765:    not from all fwmark 0xca6c lookup 51820
[RULE]32764:    from all lookup main suppress_prefixlength 0
[ROUTE]default dev martino table 51820 scope link
[RULE]32765:    not from all fwmark 0xca6c lookup 51820
[RULE]32764:    from all lookup main suppress_prefixlength 0

If I then type in `ip addr flush dev martino`, I get this:

[ADDR]Deleted 107: martino    inet 10.10.11.100/32 scope global martino
      valid_lft forever preferred_lft forever
[ROUTE]Deleted local 10.10.11.100 dev martino table local proto kernel
scope host src 10.10.11.100
[NEIGH]Deleted 10.10.11.1 dev martino lladdr 08 NOARP
[NEIGH]Deleted 66.102.1.127 dev martino lladdr 08 NOARP
[NEIGH]Deleted 52.205.56.176 dev martino lladdr 08 NOARP
[ADDR]Deleted 107: martino    inet6 2a01:e35:8be7:9122:100::1/96 scope global
      valid_lft forever preferred_lft forever
[ROUTE]Deleted local 2a01:e35:8be7:9122:100::1 dev lo table local
proto kernel metric 0 pref medium
[ROUTE]Deleted 2a01:e35:8be7:9122:100::/96 dev martino proto kernel
metric 256 pref medium

So, it remains to be seen whether or not something else in userspace
is actually interacting with the interface. Once we figure out what,
we might be able to monitor all callers of those netlink commands.

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jim Darby]

[-- Attachment #1: Type: text/plain, Size: 4830 bytes --]

The plot thickens! Here's the output from ip monitor all:

    [NETCONF]ipv4 dev wg0 forwarding on rp_filter strict mc_forwarding 0
    proxy_neigh off
    [NETCONF]ipv6 dev wg0 forwarding off mc_forwarding 0 proxy_neigh off
    [LINK]27: wg0: <POINTOPOINT,NOARP,200000> mtu 1420 qdisc noop state
    DOWN group default
         link/none
    [ADDR]27: wg0    inet 192.168.2.3/32 scope global wg0
            valid_lft forever preferred_lft forever
    [ROUTE]local 192.168.2.3 dev wg0  table local  proto kernel scope
    host  src 192.168.2.3
    [ADDR]Deleted 27: wg0    inet 192.168.2.3/32 scope global wg0
            valid_lft forever preferred_lft forever
    [ROUTE]Deleted local 192.168.2.3 dev wg0  table local  proto kernel 
    scope host  src 192.168.2.3
    [LINK]27: wg0: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1420 qdisc
    noqueue state UNKNOWN group default
         link/none
    [ROUTE]ff00::/8 dev wg0  table local  metric 256
    [LINK]27: wg0: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1420 state UNKNOWN
         link/none
    [LINK]27: wg0: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1420 qdisc
    noqueue state UNKNOWN group default
         link/none
    [ROUTE]192.168.2.0/24 dev wg0  scope link

The route delete on the sixth line is most interesting. I wonder where 
it came from? I'll try it one some Debian 8 machines and see what 
happens. So far it's /only/ Debain 9 that seems to have the issue.

Jim.


On 10/09/17 15:26, Jason A. Donenfeld wrote:
> On Sun, Sep 10, 2017 at 3:09 PM, Jim Darby <uberscubajim@gmail.com> wrote:
>> However, your comment about network management daemons running is most
>> interesting. Here's an extract from journalctl's output:
>> Sep 09 21:31:28 janus ifplugd(wg0)[6903]: Executing
>> '/etc/ifplugd/ifplugd.action wg0 up'.
>> Sep 09 21:31:28 janus ifplugd(wg0)[6903]: client: Ignoring unknown interface
>> wg0=wg0.
> That is interesting. Thanks for that. Indeed it looks like ifplugd is
> just calling ifup wg0, and I'm not totally sure why that would remove
> an IP address if there's nothing in /etc/network/interfaces, though
> I'm not a huge Debian person so there could be a detail I'm
> overlooking.
>
> Another more direct way that might help debug this is `ip monitor
> all`. On my (working) system, running `ip monitor all` in one window
> and `wg-quick up martino` in another yields this:
>
> [NETCONF]ipv4 dev martino forwarding off rp_filter loose mc_forwarding
> off proxy_neigh off ignore_routes_with_linkdown off
> [NETCONF]ipv6 dev martino forwarding off mc_forwarding off proxy_neigh
> off ignore_routes_with_linkdown off
> [LINK]107: martino: <POINTOPOINT,NOARP,200000> mtu 1420 qdisc noop
> state DOWN group default
>     link/none
> [ADDR]107: martino    inet 10.10.11.100/32 scope global martino
>        valid_lft forever preferred_lft forever
> [ROUTE]local 10.10.11.100 dev martino table local proto kernel scope
> host src 10.10.11.100
> [ROUTE]ff00::/8 dev martino table local metric 256 linkdown pref medium
> [ROUTE]2a01:e35:8be7:9122:100::/96 dev martino proto kernel metric 256
> linkdown pref medium
> [ADDR]107: martino    inet6 2a01:e35:8be7:9122:100::1/96 scope global
>        valid_lft forever preferred_lft forever
> [ROUTE]local 2a01:e35:8be7:9122:100::1 dev lo table local proto kernel
> metric 0 pref medium
> [LINK]107: martino: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1420 qdisc
> noqueue state UNKNOWN group default
>     link/none
> [ROUTE]default dev martino table 51820 metric 1024 pref medium
> [RULE]32765:    not from all fwmark 0xca6c lookup 51820
> [RULE]32764:    from all lookup main suppress_prefixlength 0
> [ROUTE]default dev martino table 51820 scope link
> [RULE]32765:    not from all fwmark 0xca6c lookup 51820
> [RULE]32764:    from all lookup main suppress_prefixlength 0
>
> If I then type in `ip addr flush dev martino`, I get this:
>
> [ADDR]Deleted 107: martino    inet 10.10.11.100/32 scope global martino
>        valid_lft forever preferred_lft forever
> [ROUTE]Deleted local 10.10.11.100 dev martino table local proto kernel
> scope host src 10.10.11.100
> [NEIGH]Deleted 10.10.11.1 dev martino lladdr 08 NOARP
> [NEIGH]Deleted 66.102.1.127 dev martino lladdr 08 NOARP
> [NEIGH]Deleted 52.205.56.176 dev martino lladdr 08 NOARP
> [ADDR]Deleted 107: martino    inet6 2a01:e35:8be7:9122:100::1/96 scope global
>        valid_lft forever preferred_lft forever
> [ROUTE]Deleted local 2a01:e35:8be7:9122:100::1 dev lo table local
> proto kernel metric 0 pref medium
> [ROUTE]Deleted 2a01:e35:8be7:9122:100::/96 dev martino proto kernel
> metric 256 pref medium
>
> So, it remains to be seen whether or not something else in userspace
> is actually interacting with the interface. Once we figure out what,
> we might be able to monitor all callers of those netlink commands.


[-- Attachment #2: Type: text/html, Size: 5632 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

[-- Attachment #1: Type: text/plain, Size: 313 bytes --]

I just wrote the attached script, which will tell you all the
processes that have an open netlink socket...

There's a bit too much fluff in there on a desktop system, but I
imagine the pi might help boil it down to a few candidates. Probably
we'll determine it's an ifplugd/ifupdown.action thing, but we'll see.

[-- Attachment #2: netlistenwho.sh --]
[-- Type: application/x-sh, Size: 559 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

Another "direct" debugging thing you could do is:

$ ip link add nlmon0 type nlmon
$ ip link set nlmon0 set up

And then start looking at the output in Wireshark. When you see the
obvious culprit (a rtnetlink message deleting the address), look at
the port ID. Then look in /proc/net/netlink to correlate the port id
("Pid") with an inode ("Inode"). Then look at the symbolic link
targets of /proc/{pid}/fd/[0-9]+ to see which pid has a fd belonging
to that inode. Then we'll know for certain.

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jim Darby]

[-- Attachment #1: Type: text/plain, Size: 2950 bytes --]

On 10/09/17 23:25, Jason A. Donenfeld wrote:
> I just wrote the attached script, which will tell you all the
> processes that have an open netlink socket...
>
> There's a bit too much fluff in there on a desktop system, but I
> imagine the pi might help boil it down to a few candidates. Probably
> we'll determine it's an ifplugd/ifupdown.action thing, but we'll see.

Many thanks again for such great work. Here's the output of the 
netlistenerwho.sh program. It's awash with potential culprits!

   PID TTY      STAT   TIME COMMAND
     1 ?        Ss     2:35 /sbin/init
   128 ?        Ss     0:01 /lib/systemd/systemd-udevd
   770 ?        Ss     2:24 /sbin/dhcpcd -q -b
   783 ?        Ss     0:15 avahi-daemon: running [janus.local]
   840 ?        Ss     0:32 /lib/systemd/systemd-logind
   896 ?        Ss    10:19 /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 
107:112
   906 ?        S      0:02 /usr/sbin/dnsmasq -x 
/run/dnsmasq/dnsmasq.pid -u dnsmasq -r /run/dnsmasq/resolv.conf -7 
/etc/dnsmasq.
  1204 ?        Ss     0:00 /lib/systemd/systemd --user
18942 ?        Ss     0:00 /lib/systemd/systemd --user

I also made a great mistake earlier: the problematic system is the 
version of Raspbian based on begin *8* and /not/ *9*. Debian 9 works fine!

I've tweaked the /etc/network/interfaces file to have the line “iface 
wg0 inet manual” in it so we /shouldn't/ get DHCP running or anything…

I tried the nlmon trick but I got the response “RTNETLINK answers: 
Operation not supported” which isn't too helpful.

After some more playing I've found that running the wg-quick script's 
commands by hand works. But then, I'm /manually/ entering them and that 
affects timing.

I note you perform the ”ip link set wg0 up” /after/ the “ip address add 
192.168.2.3/32 dev wg0” and “ip link set mtu 1420 dev wg0”. /However, 
/the act of creating the interface with the “ip link add wg0 type 
wireguard” seems to trigger the ip up automatically. The log files give:

Sep 10 23:57:51 janus kernel: wireguard: WireGuard 0.0.20170907 loaded. 
See www.wireguard.com for information.
Sep 10 23:57:51 janus kernel: wireguard: Copyright (C) 2015-2017 Jason 
A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: ifplugd 0.28 initializing.
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using interface 
wg0/00:00:00:00:00:00
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using detection mode: IFF_RUNNING
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Initialization complete, link 
beat detected.
Sep 10 23:57:52 janus ifplugd(wg0)[14109]: Executing 
'/etc/ifplugd/ifplugd.action wg0 up'.
Sep 10 23:57:52 janus ifplugd(wg0)[14109]: client: /sbin/ifup: interface 
wg0 already configured
Sep 10 23:57:52 janus ifplugd(wg0)[14109]: Program executed successfully.

Which could well be interesting. I manually ran ifdown then ifup on wg0 
and it /didn't/ lose its IP address.

Most perplexing!

Jim.

[-- Attachment #2: Type: text/html, Size: 4354 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

[-- Attachment #1: Type: text/plain, Size: 1359 bytes --]

I figured it out. ifplugd clears all addresses when bringing up an
interface:

void interface_up(int fd, char *iface) {
...
        ((struct sockaddr_in *)(&ifr.ifr_addr))->sin_addr.s_addr =
INADDR_ANY;
        if (ioctl(fd, SIOCSIFADDR, &ifr) < 0) {
...
}

Since wg-quick sets the address before bringing it up, this running in
between is problematic. One workaround in wg-quick would be for me to
reverse the order of setting the IP and bringing it up, but this introduces
other races I'm not very fond of introducing. So, rather, we should address
the larger question: why on earth is ifplugd being started when wg0 is
added?

Sep 10 23:57:51 janus ifplugd(wg0)[14109]: ifplugd 0.28 initializing.
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using interface
wg0/00:00:00:00:00:00
Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using detection mode: IFF_RUNNING

What causes it to be launched here? Digging a bit deeper, it looks like
ifplugd is being launched by a udev rule which calls a Debian file called
ifplugd.agent. It is in here that unholy hotplugging occurs.

I don't actually have a Debian system running to fish around and see, but
my guess is that you have a file /etc/default/ifplugd that has in it
HOTPLUG_INTERFACES=all. If you change this to HOTPLUG_INTERFACES="wlan0
eth0" or something more restrictive, things might work better. Just a guess.

[-- Attachment #2: Type: text/html, Size: 1633 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jim Darby]

[-- Attachment #1: Type: text/plain, Size: 2279 bytes --]

Nailed it!

Specifically, you were spot on about the /etc/default/ifplugd file and 
its HOTPLUG_INTERFACES line. Changing that to HOTPLUG_INTERFACES="eth0 
eth1" meant that it just worked out of the box.

In fact, I suspect that eth0 could be omitted because it's part of the 
hardware (eth1 is a USB dongle so hotplugging may be useful). I'd prefer 
a way to specifically /exclude/ wg* interfaces rather then include the 
known ones but that may be too complex.

I hope this discussion and its solution will be a useful part of the 
WireGuard documentation. It'll hopefully stop others becoming confused 
in the future.

Many thanks for your help in resolving this! I'm very much enjoying 
playing with WireGuard. I heard about it during your talk at FOSDEM by 
the way.

Regards,

Jim.


On 11/09/17 01:52, Jason A. Donenfeld wrote:
> I figured it out. ifplugd clears all addresses when bringing up an 
> interface:
>
> void interface_up(int fd, char *iface) {
> ...
>         ((struct sockaddr_in *)(&ifr.ifr_addr))->sin_addr.s_addr = 
> INADDR_ANY;
>         if (ioctl(fd, SIOCSIFADDR, &ifr) < 0) {
> ...
> }
>
> Since wg-quick sets the address before bringing it up, this running in 
> between is problematic. One workaround in wg-quick would be for me to 
> reverse the order of setting the IP and bringing it up, but this 
> introduces other races I'm not very fond of introducing. So, rather, 
> we should address the larger question: why on earth is ifplugd being 
> started when wg0 is added?
>
> Sep 10 23:57:51 janus ifplugd(wg0)[14109]: ifplugd 0.28 initializing.
> Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using interface 
> wg0/00:00:00:00:00:00
> Sep 10 23:57:51 janus ifplugd(wg0)[14109]: Using detection mode: 
> IFF_RUNNING
>
> What causes it to be launched here? Digging a bit deeper, it looks 
> like ifplugd is being launched by a udev rule which calls a Debian 
> file called ifplugd.agent. It is in here that unholy hotplugging occurs.
>
> I don't actually have a Debian system running to fish around and see, 
> but my guess is that you have a file /etc/default/ifplugd that has in 
> it HOTPLUG_INTERFACES=all. If you change this to 
> HOTPLUG_INTERFACES="wlan0 eth0" or something more restrictive, things 
> might work better. Just a guess.


[-- Attachment #2: Type: text/html, Size: 3487 bytes --]

Re: Timing issue (?) with wg-quick up on Raspberry Pi B+

[Jason A. Donenfeld]

Hey Jim,

Great to hear this resolved things.

> I'm very much enjoying playing with WireGuard.
> I heard about it during your talk at FOSDEM by the way.

In case you didn't get any stickers there, I'm mailing them out via:
https://lists.zx2c4.com/pipermail/wireguard/2017-May/001338.html

Jason