Bug 84373

Summary: systemd-networkd: dhcp client not working (invalid argument)
Product: systemd Reporter: Markus Rathgeb <maggu2810>
Component: generalAssignee: systemd-bugs
Status: RESOLVED WONTFIX QA Contact: systemd-bugs
Severity: normal    
Priority: medium    
Version: unspecified   
Hardware: ARM   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:

Description Markus Rathgeb 2014-09-26 13:44:02 UTC
I installed a new system on a board and systemd-networkd stopped working.
I thought I was using the same configuration as before, but there must be something wrong...

systemd-networkd write to the journal:
===
eth0            : gained carrier
eth0            : DHCP error: client failed: Invalid argument
eth0            : could not acquire DHCPv4 lease
eth0            : failed
===

Here more debug log:
===
[root@ct-mara ~]# SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-networkd
timestamp of '/etc/systemd/network' changed
sd-rtnl: discarding 20 bytes of incoming message
wlan0           : link 5 added
wlan0           : udev initialized link
wlan0           : saved original MTU: 1500
wlan0           : flags change: +MULTICAST +BROADCAST
p2p0            : link 4 added
p2p0            : udev initialized link
p2p0            : saved original MTU: 1500
p2p0            : flags change: +MULTICAST +BROADCAST
tunl0           : MAC address not found for new device, continuing without
tunl0           : link 3 added
tunl0           : udev initialized link
tunl0           : saved original MTU: 1480
tunl0           : flags change: +NOARP
eth0            : link 2 added
eth0            : udev initialized link
eth0            : saved original MTU: 1500
eth0            : flags change: +UP +LOWER_UP +RUNNING +MULTICAST +BROADCAST
eth0            : gained carrier
lo              : link 1 added
lo              : udev initialized link
lo              : saved original MTU: 16436
lo              : flags change: +LOOPBACK +UP +LOWER_UP +RUNNING
lo              : gained carrier
wlan0           : link state is up-to-date
wlan0           : unmanaged
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=Hello cookie=1 reply_cookie=0 error=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.12 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
p2p0            : getting address failed: Device or resource busy
Got message type=signal sender=org.freedesktop.DBus destination=:1.12 object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 error=n/a
p2p0            : link state is up-to-date
p2p0            : unmanaged
tunl0           : getting address failed: Device or resource busy
tunl0           : link state is up-to-date
tunl0           : unmanaged
eth0            : getting address failed: Device or resource busy
eth0            : link state is up-to-date
eth0            : found matching network '/etc/systemd/network/00-ethernet.network'
eth0            : acquiring DHCPv4 lease
DHCP CLIENT (0xce36fbdb): STOPPED: Invalid argument
eth0            : DHCP error: client failed: Invalid argument
eth0            : could not acquire DHCPv4 lease
Event source 0xb70c4dd0 returned error, disabling: Invalid argument
Event source 0xb70c4f70 returned error, disabling: Operation not supported
===

The network configuration file
===
[root@ct-mara ~]# cat /etc/systemd/network/00-ethernet.network
[Match]
Name=eth0

[Network]
DHCP=v4
===
Comment 1 Markus Rathgeb 2014-09-26 14:17:30 UTC
Used version is 216.
Comment 2 Markus Rathgeb 2014-09-29 10:24:13 UTC
I used strace to get more details what is going on:

child_stack=0xb6cf6f58, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb6cf7488, tls=0xb6cf78e0, child_tidptr=0xb6cf7488) = 184
[pid   184] set_robust_list(0xb6cf7490, 12 <unfinished ...>
[pid   183] open("/dev/urandom", O_RDONLY|O_NOCTTY|O_LARGEFILE|O_CLOEXEC <unfinished ...>
[pid   184] <... set_robust_list resumed> ) = 0
[pid   183] <... open resumed> )        = 9
[pid   184] madvise(0xb64f8000, 8364032, MADV_DONTNEED <unfinished ...>
[pid   183] read(9,  <unfinished ...>
[pid   184] <... madvise resumed> )     = 0
[pid   183] <... read resumed> "T\237Td", 4) = 4
[pid   184] exit(0)                     = ?
[pid   183] close(9)                    = 0
[pid   184] +++ exited with 0 +++
socket(PF_PACKET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 9
setsockopt(9, SOL_PACKET, PACKET_AUXDATA, [1], 4) = 0
setsockopt(9, SOL_SOCKET, SO_ATTACH_FILTER, "-\0\226|\250\325\353\276", 8) = -1 EINVAL (Invalid argument)
close(9)                                = 0
writev(2, [{"DHCP CLIENT (0x64549f54): STOPPE"..., 51}, {"\n", 1}], 2DHCP CLIENT (0x64549f54): STOPPED: Invalid argument
) = 52
writev(2, [{"eth0            : DHCP error: cl"..., 61}, {"\n", 1}], 2eth0            : DHCP error: client failed: Invalid argument
) = 62
clone(Process 185 attached
 <unfinished ...>
[pid   185] set_robust_list(0xb6cf7490, 12 <unfinished ...>
[pid   183] <... clone resumed> child_stack=0xb6cf6f58, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb6cf7488, tls=0xb6cf78e0, child_tidptr=0xb6cf7488) = 185
[pid   185] <... set_robust_list resumed> ) = 0
[pid   183] writev(2, [{"eth0            : could not acqu"..., 48}, {"\n", 1}], 2eth0            : could not acquire DHCPv4 lease
 <unfinished ...>
[pid   185] madvise(0xb64f8000, 8364032, MADV_DONTNEED <unfinished ...>
[pid   183] <... writev resumed> )      = 49
[pid   185] <... madvise resumed> )     = 0
[pid   183] writev(2, [{"Event source 0xb7717dd0 returned"..., 67}, {"\n", 1}], 2Event source 0xb7717dd0 returned error, disabling: Invalid argument
 <unfinished ...>
[pid   185] exit(0)                     = ?
[pid   183] <... writev resumed> )      = 68
[pid   185] +++ exited with 0 +++
epoll_ctl(3, EPOLL_CTL_DEL, 5, NULL)    = 0
epoll_wait(3, 

So, the code that raised the EINVAL is the following:
setsockopt(9, SOL_SOCKET, SO_ATTACH_FILTER, "-\0\226|\250\325\353\276", 8) = -1 EINVAL (Invalid argument)

Are you using filters that needs a kernel > 3.4?
Comment 3 Markus Rathgeb 2014-09-29 11:19:56 UTC
This filter will raise a EINVAL on my 3.4 kernel:

BPF_STMT(BPF_ALU + BPF_XOR + BPF_X, 0),  /* A xor X */
Comment 4 Markus Rathgeb 2014-09-29 11:39:00 UTC
BPF_XOR is not known in the 3.4 kernel.
Nothing new, if we know what to search for...

https://www.mail-archive.com/systemd-devel@lists.freedesktop.org/msg22454.html
Comment 5 Markus Rathgeb 2014-09-29 12:08:49 UTC
BPF_XOR was introduced in kernel 3.7.

The requirements for systemd were already bumped to 3.7 (https://www.mail-archive.com/systemd-devel@lists.freedesktop.org/msg22454.html).

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.