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

Fri Mar 21 13:47:44 PDT 2014

On 03/21/2014 07:03 PM, Tom Gundersen wrote:
> On Tue, Mar 18, 2014 at 10:38 AM, Henrik /KaarPoSoft
> <henrik at kaarposoft.dk> wrote:
>> On 03/18/2014 10:10 AM, Tom Gundersen wrote:
>>>
>>> On Tue, Mar 18, 2014 at 10:00 AM, Henrik /KaarPoSoft
>>> <henrik at kaarposoft.dk> wrote:
>>>>
>>>> On 03/18/2014 09:18 AM, Henrik /KaarPoSoft wrote:
>>>>>
>>>>>
>>>>> On 03/17/2014 10:32 PM, Tom Gundersen wrote:
>>>>>>
>>>>>>
>>>>>> On Mon, Mar 17, 2014 at 10:21 PM, Henrik /KaarPoSoft
>>>>>> <henrik at kaarposoft.dk> wrote:
>>>>>>>
>>>>>>>
>>>>>>> Hi Tom,
>>>>>>>
>>>>>>> Thanks for your feedback...
>>>>>>>
>>>>>>> I was briefly looking through git commits after 211 without finding
>>>>>>> anything
>>>>>>> related. But then again I did not look into too much detail.
>>>>>>>
>>>>>>> Do you know which commit would solve this?
>>>>>>
>>>>>>
>>>>>>
>>>>>> Ah, this was not obvious at all. This was almost certainly fixed as a
>>>>>> side-effect of refactoring the rtnl_message_read_*() code, so if you
>>>>>> pull in 9842de0d93d and the commits it relies on that should do it (I
>>>>>> haven't verified that that's the culprit, but it seems likely from
>>>>>> looking at it).
>>>>>>
>>>>>> Cheers,
>>>>>>
>>>>>> Tom
>>>>>>
>>>>> Tom,
>>>>> As far as I can see, 9842de0d93d was already included in 211.
>>>>> I have rebuild my systemd from the head of git 4dd5da7f.
>>>>> And the problem remains )))-:
>>>>> /Henrik
>>>>
>>>>
>>>>
>>>> As a quick hack, I tried this:
>>>>
>>>> cat > /etc/systemd/network/42-br0.link<<EOF
>>>> [Match]
>>>> Type=bridge
>>>> [Link]
>>>> MACAddress=10:bf:48:d7:68:e1
>>>> EOF
>>>>
>>>> And now I get an IP address by DHCP, and I have connectivity.
>>>>
>>>> But hard-coding the MAC is hardly a viable long-term solution...
>>>
>>>
>>> Yeah, that's not going to fly.
>>>
>>> Could you attach the full debug output of a failing run? To get it,
>>> you probably want to stop systemd-networkd, "ip link del" the bridge,
>>> and start networkd from the commandline:
>>>
>>> # SYSTEMD_LOG_LEVEL=debug /lib/systemd/systemd-networkd
>>>
>>> I think I understand what's going on, but I'd like to have it verified
>>> before changing anything.
>>>
>>> Cheers,
>>>
>>> Tom
>>>
>>
>> I guess running from the commandline should not be necessary since I have
>> [Service]
>> Environment=SYSTEMD_LOG_LEVEL=debug
>> in
>> /etc/systemd/system/systemd-networkd.service.d/debug.conf
>
> Hi Henrik,
>
> Thanks for the bug report. Could you try again with current git to see
> if the problem is now solved for you?
>
> Cheers,
>
> Tom
>

Tom,

THANK YOU VERY MUCH!

Yes, it works now for me.

Logs attached.

I was busy with something else, so only watched the list and git with 
half an eye.
However, I find it disturbing that DHCP is attempted first on the 
"wrong" MAC, only to be killed and restarted on the "right" MAC.
Is this really the best way of solving this ???

/Henrik

-------------- next part --------------
systemd GIT b5db00e52ee2e20578839e4e4488f7b9af9abc38

journalctl -b _SYSTEMD_UNIT=systemd-networkd.service|cat

Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: timestamp of '/etc/systemd/network' changed
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: timestamp of '/run/systemd/network' changed
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: br0: creating netdev
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: eno1: found matching network '/etc/systemd/network/44-en.network'
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: eno1: requesting link status
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: eno1: enslaving by 'br0'
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: eno1: link (with ifindex 2) added
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: enp11s0: found matching network '/etc/systemd/network/50-dhcp.network'
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: enp11s0: requesting link status
Mar 21 21:38:27 komplett-21 systemd-networkd[2682]: enp11s0: bringing link up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: enp11s0: link (with ifindex 3) added
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: found matching network '/etc/systemd/network/46-br0.network'
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: requesting link status
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: bringing link up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link (with ifindex 5) added
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: lo: link (with ifindex 1) added
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: sit0: link (with ifindex 4) added
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link already exists, ignoring
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: netdev ready
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: enslaving link 'eno1'
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: MAC address: 1e:ac:96:2e:3d:25
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link status updated: 00000000 -> 0x00001002
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: 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
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: MAC address: 10:bf:48:d7:68:e1
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: link status updated: 00000000 -> 0x00001002
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: enp11s0: MAC address: 10:bf:48:d7:64:aa
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: enp11s0: link status updated: 00000000 -> 0x00001002
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.7 object=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 error=n/a
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: enp11s0: link status updated: 0x00001002 -> 0x00001003
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: enp11s0: link is up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: Got message type=signal sender=org.freedesktop.DBus destination=:1.7 object=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameAcquired cookie=2 reply_cookie=0 error=n/a
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link status updated: 0x00001002 -> 0x00011043
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link is up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: carrier on
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: acquiring DHCPv4 lease
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: STARTED
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: DISCOVER
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: MAC address: 10:bf:48:d7:68:e1
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: Changing MAC address on running DHCP client, restarting
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: STOPPED
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: STARTED
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link status updated: 0x00011043 -> 0x00001043
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: carrier off
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: DHCP CLIENT: STOPPED
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: enslaved
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: bringing link up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: link configured
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: link status updated: 0x00001002 -> 0x00001003
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: eno1: link is up
Mar 21 21:38:28 komplett-21 systemd-networkd[2682]: br0: link status updated: 0x00001043 -> 0x00001003
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: eno1: link status updated: 0x00001003 -> 0x00011043
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: eno1: carrier on
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: br0: link status updated: 0x00001003 -> 0x00011043
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: br0: carrier on
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: br0: acquiring DHCPv4 lease
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: DHCP CLIENT: STARTED
Mar 21 21:38:30 komplett-21 systemd-networkd[2682]: DHCP CLIENT: DISCOVER
Mar 21 21:38:31 komplett-21 systemd-networkd[2682]: DHCP CLIENT: DISCOVER
Mar 21 21:38:34 komplett-21 systemd-networkd[2682]: DHCP CLIENT: DISCOVER
Mar 21 21:38:34 komplett-21 systemd-networkd[2682]: DHCP CLIENT: ignoring packet: packet (48 bytes) smaller than expected (60537) by UDP header
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: OFFER
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: REQUEST
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: ACK
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: lease expires in 1h 59min 58.557776s
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: T2 expires in 1h 44min 57.567708s
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: DHCP CLIENT: T1 expires in 59min 59.165172s
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: DHCPv4 address 192.168.99.181/24 via 192.168.99.254
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: setting addresses
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: addresses set
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: setting routes
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: routes set
Mar 21 21:38:35 komplett-21 systemd-networkd[2682]: br0: link configured