[systemd-devel] systemd-networkd bridge with DHCP not working

[Tom Gundersen]

On Wed, Mar 19, 2014 at 2:09 PM, Tom Gundersen <teg at jklm.no> wrote:
> On Wed, Mar 19, 2014 at 1:25 PM, poma <pomidorabelisima at gmail.com> wrote:
>> Still the same issue, DHCPC starts too early, before the correct MAC
>> address is set for the bridge.
>>
>> git 7bf2f4397255bc8f6cf20a0f2adab4c984ea7d14
>
> I haven't yet gotten around to this. We probably should just restart
> the dhcp client if the mac address changes, for whatever reason.
> Unless anyone else has a better idea.

Adding Umut as well as this problem is the same in sd-ipv4ll.

I have now shuffled the code around a bit in git to give a clearer
error message when this problem is encountered. The underlying problem
remains though.

My proposal is:

Whenever the MAC address changes under us networkd calls
sd_{dhcp_client,ipv4ll}_set_mac(), and it is the libs' responsibility
to then do the right thing.

Currently the libs don't support this and will fail with EBUSY, so I
suggest we change that into letting them restart themselves
internally, and send out notifications that the lease has been lost
(so networkd will drop the addresses correctly, if it has any
assigned).

Umut, Patrik, what do you think?

Cheers,

Tom

>> journalctl -b -u systemd-networkd
>> ...
>> 12:51:55 networkd[579]: timestamp of '/etc/systemd/network' changed
>> 12:51:55 networkd[579]: timestamp of '/run/systemd/network' changed
>> 12:51:55 networkd[579]: bridge0: creating netdev
>> 12:51:55 networkd[579]: enp1s6: link (with ifindex 2) added
>> 12:51:55 networkd[579]: enp1s9: link (with ifindex 3) added
>> 12:51:55 networkd[579]: enp3s0: found matching network
>> '/etc/systemd/network/base0.network'
>> 12:51:55 networkd[579]: enp3s0: requesting link status
>> 12:51:55 networkd[579]: enp3s0: enslaving by 'bridge0'
>> 12:51:55 networkd[579]: enp3s0: link (with ifindex 4) added
>> 12:51:55 networkd[579]: lo: link (with ifindex 1) added
>> 12:51:55 networkd[579]: bridge0: found matching network
>> '/etc/systemd/network/bridge0dhcp.network'
>> 12:51:55 networkd[579]: bridge0: requesting link status
>> 12:51:55 networkd[579]: bridge0: bringing link up
>> 12:51:55 networkd[579]: bridge0: link (with ifindex 5) added
>> 12:51:55 networkd[579]: bridge0: netdev ready
>> 12:51:55 networkd[579]: bridge0: enslaving link 'enp3s0'
>> 12:51:55 networkd[579]: bridge0: MAC address: 96:c0:ae:06:29:ce
>> 12:51:55 networkd[579]: bridge0: link status updated: 00000000 -> 0x00001002
>> 12:51:55 networkd[579]: 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
>> 12:51:55 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:55 networkd[579]: enp3s0: link status updated: 00000000 -> 0x00001002
>> 12:51:55 networkd[579]: bridge0: MAC address: 96:c0:ae:06:29:ce
>> 12:51:55 networkd[579]: bridge0: MAC address: 96:c0:ae:06:29:ce
>> 12:51:55 networkd[579]: bridge0: link is up
>> 12:51:55 networkd[579]: bridge0: carrier on
>> 12:51:55 networkd[579]: DHCP CLIENT: set MAC address to 96:c0:ae:06:29:ce
>> 12:51:55 networkd[579]: bridge0: acquiring DHCPv4 lease
>> 12:51:55 networkd[579]: DHCP CLIENT: STARTED
>> 12:51:55 networkd[579]: bridge0: link status updated: 0x00001002 ->
>> 0x00011043
>> 12:51:55 networkd[579]: Got message type=method_return
>> sender=org.freedesktop.DBus destination=:1.6 object=n/a interface=n/a
>> member=n/a cookie=1 reply_cookie=1 error=n/a
>> 12:51:55 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:51:55 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:55 networkd[579]: Got message type=signal
>> sender=org.freedesktop.DBus destination=:1.6
>> object=/org/freedesktop/DBus interface=org.freedesktop.DBus
>> member=NameAcquired cookie=2 reply_cookie=0 error=n/a
>> 12:51:55 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:55 networkd[579]: bridge0: MAC address: 96:c0:ae:06:29:ce
>> 12:51:55 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:55 networkd[579]: bridge0: MAC address: 00:12:34:56:78:30
>> 12:51:55 networkd[579]: bridge0: carrier off
>> 12:51:55 networkd[579]: DHCP CLIENT: STOPPED
>> 12:51:56 networkd[579]: bridge0: link status updated: 0x00011043 ->
>> 0x00001043
>> 12:51:56 networkd[579]: enp3s0: enslaved
>> 12:51:56 networkd[579]: enp3s0: bringing link up
>> 12:51:56 networkd[579]: enp3s0: link configured
>> 12:51:56 networkd[579]: bridge0: MAC address: 00:12:34:56:78:30
>> 12:51:56 networkd[579]: bridge0: link status updated: 0x00001043 ->
>> 0x00001003
>> 12:51:56 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:56 networkd[579]: enp3s0: link is up
>> 12:51:56 networkd[579]: enp3s0: link status updated: 0x00001002 ->
>> 0x00001003
>> 12:51:56 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: enp3s0: carrier on
>> 12:51:57 networkd[579]: enp3s0: link status updated: 0x00001003 ->
>> 0x00011043
>> 12:51:57 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: bridge0: MAC address: 00:12:34:56:78:30
>> 12:51:57 networkd[579]: bridge0: carrier on
>> 12:51:57 networkd[579]: bridge0: acquiring DHCPv4 lease
>> 12:51:57 networkd[579]: DHCP CLIENT: STARTED
>> 12:51:57 networkd[579]: bridge0: link status updated: 0x00001003 ->
>> 0x00011043
>> 12:51:57 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:51:59 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:52:02 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:52:07 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:52:12 networkd[579]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:52:16 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:52:32 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:52:55 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (4476) by UDP header
>> 12:52:56 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (5656) by UDP header
>> 12:53:03 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (61459) by UDP header
>> 12:53:03 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (57364) by UDP header
>> 12:53:03 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:54:08 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:55:02 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (4476) by UDP header
>> 12:55:02 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (5656) by UDP header
>> 12:55:10 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (61459) by UDP header
>> 12:55:10 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (57364) by UDP header
>> 12:55:13 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:55:18 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:18 networkd[579]: DHCP CLIENT: DISCOVER
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:47 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:56:48 networkd[579]: DHCP CLIENT: ignoring packet: to port 1900,
>> which is not the DHCP client port (68)
>> 12:57:08 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (4476) by UDP header
>> 12:57:13 networkd[579]: DHCP CLIENT: ignoring packet: packet (32 bytes)
>> smaller than expected (5656) by UDP header
>> 12:57:15 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (61459) by UDP header
>> 12:57:15 networkd[579]: DHCP CLIENT: ignoring packet: packet (28 bytes)
>> smaller than expected (57364) by UDP header
>> 12:57:22 networkd[579]: DHCP CLIENT: DISCOVER
>> ...
>> systemctl restart systemd-networkd
>> ...
>> 12:57:40 systemd[1]: Stopping Network Service...
>> 12:57:40 networkd[579]: Received SIGTERM from PID 1 (systemd).
>> 12:57:40 networkd[579]: Assertion 's->event->state != SD_EVENT_FINISHED'
>> failed at ../src/libsystemd/sd-event/sd-event.c:1229, function
>> sd_event_source_set_enabled(). Ignoring.
>> 12:57:40 networkd[579]: Assertion 's->event->state != SD_EVENT_FINISHED'
>> failed at ../src/libsystemd/sd-event/sd-event.c:1229, function
>> sd_event_source_set_enabled(). Ignoring.
>> 12:57:40 networkd[579]: Assertion 's->event->state != SD_EVENT_FINISHED'
>> failed at ../src/libsystemd/sd-event/sd-event.c:1229, function
>> sd_event_source_set_enabled(). Ignoring.
>> 12:57:40 networkd[579]: DHCP CLIENT: STOPPED
>> 12:57:40 systemd[1]: Starting Network Service...
>> 12:57:40 networkd[1449]: timestamp of '/etc/systemd/network' changed
>> 12:57:40 networkd[1449]: timestamp of '/run/systemd/network' changed
>> 12:57:40 networkd[1449]: bridge0: creating netdev
>> 12:57:40 networkd[1449]: enp1s6: link (with ifindex 2) added
>> 12:57:40 networkd[1449]: enp1s9: link (with ifindex 3) added
>> 12:57:40 networkd[1449]: enp3s0: found matching network
>> '/etc/systemd/network/base0.network'
>> 12:57:40 networkd[1449]: enp3s0: requesting link status
>> 12:57:40 networkd[1449]: enp3s0: enslaving by 'bridge0'
>> 12:57:40 networkd[1449]: enp3s0: link (with ifindex 4) added
>> 12:57:40 networkd[1449]: bridge0: found matching network
>> '/etc/systemd/network/bridge0dhcp.network'
>> 12:57:40 networkd[1449]: bridge0: requesting link status
>> 12:57:40 networkd[1449]: bridge0: bringing link up
>> 12:57:40 networkd[1449]: bridge0: link (with ifindex 5) added
>> 12:57:40 networkd[1449]: lo: link (with ifindex 1) added
>> 12:57:40 networkd[1449]: bridge0: requesting netdev status
>> 12:57:40 networkd[1449]: enp3s0: MAC address: 00:12:34:56:78:30
>> 12:57:40 networkd[1449]: enp3s0: link is up
>> 12:57:40 networkd[1449]: enp3s0: carrier on
>> 12:57:40 systemd[1]: Started Network Service.
>> 12:57:40 networkd[1449]: enp3s0: link status updated: 00000000 -> 0x00011043
>> 12:57:40 networkd[1449]: 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
>> 12:57:40 networkd[1449]: bridge0: MAC address: 00:12:34:56:78:30
>> 12:57:40 networkd[1449]: bridge0: link is up
>> 12:57:40 networkd[1449]: bridge0: carrier on
>> 12:57:40 networkd[1449]: DHCP CLIENT: set MAC address to 00:12:34:56:78:30
>> 12:57:40 networkd[1449]: bridge0: acquiring DHCPv4 lease
>> 12:57:40 networkd[1449]: DHCP CLIENT: STARTED
>> 12:57:40 networkd[1449]: bridge0: link status updated: 00000000 ->
>> 0x00011043
>> 12:57:40 networkd[1449]: Got message type=method_return
>> sender=org.freedesktop.DBus destination=:1.34 object=n/a interface=n/a
>> member=n/a cookie=1 reply_cookie=1 error=n/a
>> 12:57:40 networkd[1449]: DHCP CLIENT: DISCOVER
>> 12:57:40 networkd[1449]: Got message type=signal
>> sender=org.freedesktop.DBus destination=:1.34
>> object=/org/freedesktop/DBus interface=org.freedesktop.DBus
>> member=NameAcquired cookie=2 reply_cookie=0 error=n/a
>> 12:57:40 networkd[1449]: bridge0: netdev ready
>> 12:57:40 networkd[1449]: bridge0: enslaving link 'enp3s0'
>> 12:57:40 networkd[1449]: enp3s0: enslaved
>> 12:57:40 networkd[1449]: enp3s0: bringing link up
>> 12:57:40 networkd[1449]: enp3s0: link configured
>> 12:57:40 networkd[1449]: DHCP CLIENT: OFFER
>> 12:57:40 networkd[1449]: DHCP CLIENT: REQUEST
>> 12:57:40 networkd[1449]: DHCP CLIENT: ACK
>> 12:57:40 networkd[1449]: bridge0: DHCPv4 address 192.168.2.35/24 via
>> 192.168.2.1
>> 12:57:40 networkd[1449]: bridge0: setting addresses
>> 12:57:40 networkd[1449]: bridge0: addresses set
>> 12:57:40 networkd[1449]: bridge0: setting routes
>> 12:57:40 networkd[1449]: bridge0: routes set
>> 12:57:40 networkd[1449]: bridge0: link configured
>>
>>
>> poma
>>
>>