Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Slow DHCP assignment #90

Open
Jip-Hop opened this issue Feb 16, 2024 · 13 comments
Open

Slow DHCP assignment #90

Jip-Hop opened this issue Feb 16, 2024 · 13 comments
Labels
bug Something isn't working help wanted Extra attention is needed

Comments

@Jip-Hop
Copy link
Owner

Jip-Hop commented Feb 16, 2024 •
edited

It can take about 1 minute for jails using --network-bridge to be assigned an IPv4 address via DHCP. Is this normal systemd-nspawn behavior or is this a jailmaker bug? What can we do to speed up the IPv4 assignment?
@Jip-Hop Jip-Hop added bug Something isn't working help wanted Extra attention is needed labels Feb 16, 2024
@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 2, 2024

Output from journalctl | grep systemd-networkd in the jail indicates it took 31 seconds.

Mar 02 19:20:05 myjail systemd-networkd[30]: host0: Configuring with /etc/systemd/network/80-container-host0.network.
Mar 02 19:20:05 myjail systemd-networkd[30]: lo: Link UP
Mar 02 19:20:05 myjail systemd-networkd[30]: lo: Gained carrier
Mar 02 19:20:05 myjail systemd-networkd[30]: Enumeration completed
Mar 02 19:20:05 myjail systemd[1]: Started systemd-networkd.service - Network Configuration.
Mar 02 19:20:05 myjail systemd[1]: Starting systemd-networkd-wait-online.service - Wait for Network to be Configured...
Mar 02 19:20:05 myjail systemd-networkd[30]: host0: Link UP
Mar 02 19:20:05 myjail systemd-networkd[30]: host0: Gained carrier
Mar 02 19:20:07 myjail systemd-networkd[30]: host0: Gained IPv6LL
Mar 02 19:20:36 myjail systemd-networkd[30]: host0: DHCPv4 address 192.168.1.246/24, gateway 192.168.1.1 acquired from 192.168.1.1

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 2, 2024

Input the below in systemctl edit systemd-networkd:

[Service]
Environment=SYSTEMD_LOG_LEVEL=debug

Restart jail and check output from journalctl | grep systemd-networkd | grep host0:

Mar 02 19:31:08 myjail systemd-networkd[29]: host0: DHCPv4 client: DISCOVER
Mar 02 19:31:11 myjail systemd-networkd[29]: host0: NDISC: Sent Router Solicitation, next solicitation in 8s
Mar 02 19:31:12 myjail systemd-networkd[29]: host0: DHCPv4 client: DISCOVER
Mar 02 19:31:18 myjail systemd-networkd[29]: host0: NDISC: No RA received before link confirmation timeout
Mar 02 19:31:18 myjail systemd-networkd[29]: host0: NDISC: Invoking callback for 'timeout' event.
Mar 02 19:31:18 myjail systemd-networkd[29]: host0: NDisc handler get timeout event
Mar 02 19:31:18 myjail systemd-networkd[29]: host0: link_check_ready(): DHCPv4, DHCPv6, DHCP-PD or IPv4LL is enabled but no dynamic address is assigned yet.
Mar 02 19:31:19 myjail systemd-networkd[29]: host0: NDISC: Sent Router Solicitation, next solicitation in 16s
Mar 02 19:31:20 myjail systemd-networkd[29]: host0: DHCPv4 client: DISCOVER
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: NDISC: Sent Router Solicitation, next solicitation in 32s
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: DISCOVER
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: Received message from RAW socket, processing.
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: OFFER
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: REQUEST (requesting)
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: Received message from RAW socket, processing.
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: ACK
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: lease expires in 11h 59min 59s
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: T2 expires in 10h 30min
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 client: T1 expires in 5h 59min 59s
Mar 02 19:31:36 myjail systemd-networkd[29]: host0: DHCPv4 address 192.168.1.246/24, gateway 192.168.1.1 acquired from 192.168.1.1

@Lockszmith-GH
Copy link

Interesting, only the 3rd DISCOVER gets the OFFER response.

I'm not at my system this weekend, and I use static IPs for the services in my jail. So I have not encountered this, but I'll be more than happy to test this out.

It would be interesting to see what happens on the NIC at that time. If you can capture the network traffic with tcpdump, I'll be happy to take a look and try and figure out why this is happening.

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 2, 2024

Thanks for the offer! I can indeed use some help here. 🙂 IP assignment via macvlan is instant, even when the parent interface is the bridge (br0).

systemd_nspawn_user_args=--network-macvlan=br1
        --resolv-conf=bind-host

Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: OFFER
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: REQUEST (requesting)
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: Received message from RAW socket, processing.
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: ACK
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: lease expires in 11h 59min 59s
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: T2 expires in 10h 30min
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 client: T1 expires in 6h
Mar 02 20:12:05 myjail systemd-networkd[29]: mv-br1: DHCPv4 address 192.168.1.149/24, gateway 192.168.1.1 acquired from 192.168.1.1

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 2, 2024

64:8c:f7:89:14:56 = my router
8f:7a:f6:4c:78:49 = the jail

The config file:

systemd_nspawn_user_args=--network-bridge=br1
            --resolv-conf=bind-host

# Only used while creating the jail
distro=debian
release=bookworm

initial_setup=#!/usr/bin/bash
        set -euo pipefail
        apt-get update
        apt-get -y install tcpdump
        printf "\n%s\n%s\n" "[Link]" "Unmanaged=yes" >> /etc/systemd/network/80-container-host0.network

Create a jail with above config file jlmkr create --start --config ./config dhcpjail. The jail will have tcpdump installed and the host0 interface temporarily disabled due to Unmanaged=yes.

Then open a shell with jlmkr shell dhcpjail, undo the Unmanaged=yes setting, restart networking and start listening for dhcp traffic with tcpdump.

root@dhcpjail:~# sed -i 's/Unmanaged=yes/Unmanaged=no/g' /etc/systemd/network/80-container-host0.network; systemctl daemon-reload systemd-networkd; systemctl restart systemd-networkd; tcpdump --interface host0 port 67 or port 68 -e -n -vv
Too many arguments.
tcpdump: listening on host0, link-type EN10MB (Ethernet), snapshot length 262144 bytes
21:16:42.174415 8f:7a:f6:4c:78:49 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 330: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 316)
    0.0.0.0.68 > 255.255.255.255.67: [udp sum ok] BOOTP/DHCP, Request from 8f:7a:f6:4c:78:49, length 288, xid 0xbfbdcf2c, secs 4, Flags [none] (0x0000)
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Discover
	    Client-ID (61), length 19: hardware-type 255, 5d:bb:54:d7:0e:24:1b:19:90:ca:4a:7d:f4:6f:d9:2c:f4:cb
	    Parameter-Request (55), length 10: 
	      Subnet-Mask (1), Default-Gateway (3), Domain-Name-Server (6), Hostname (12)
	      Domain-Name (15), Static-Route (33), NTP (42), TZ-Name (101)
	      Unknown (120), Classless-Static-Route (121)
	    MSZ (57), length 2: 1472
	    Hostname (12), length 5: "dhcpjail"
21:16:46.290797 8f:7a:f6:4c:78:49 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 330: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 316)
    0.0.0.0.68 > 255.255.255.255.67: [udp sum ok] BOOTP/DHCP, Request from 8f:7a:f6:4c:78:49, length 288, xid 0xbfbdcf2c, secs 8, Flags [none] (0x0000)
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Discover
	    Client-ID (61), length 19: hardware-type 255, 5d:bb:54:d7:0e:24:1b:19:90:ca:4a:7d:f4:6f:d9:2c:f4:cb
	    Parameter-Request (55), length 10: 
	      Subnet-Mask (1), Default-Gateway (3), Domain-Name-Server (6), Hostname (12)
	      Domain-Name (15), Static-Route (33), NTP (42), TZ-Name (101)
	      Unknown (120), Classless-Static-Route (121)
	    MSZ (57), length 2: 1472
	    Hostname (12), length 5: "dhcpjail"
21:16:55.047479 8f:7a:f6:4c:78:49 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 330: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 316)
    0.0.0.0.68 > 255.255.255.255.67: [udp sum ok] BOOTP/DHCP, Request from 8f:7a:f6:4c:78:49, length 288, xid 0xbfbdcf2c, secs 17, Flags [none] (0x0000)
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Discover
	    Client-ID (61), length 19: hardware-type 255, 5d:bb:54:d7:0e:24:1b:19:90:ca:4a:7d:f4:6f:d9:2c:f4:cb
	    Parameter-Request (55), length 10: 
	      Subnet-Mask (1), Default-Gateway (3), Domain-Name-Server (6), Hostname (12)
	      Domain-Name (15), Static-Route (33), NTP (42), TZ-Name (101)
	      Unknown (120), Classless-Static-Route (121)
	    MSZ (57), length 2: 1472
	    Hostname (12), length 5: "dhcpjail"
21:17:11.780372 8f:7a:f6:4c:78:49 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 330: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 316)
    0.0.0.0.68 > 255.255.255.255.67: [udp sum ok] BOOTP/DHCP, Request from 8f:7a:f6:4c:78:49, length 288, xid 0xbfbdcf2c, secs 33, Flags [none] (0x0000)
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Discover
	    Client-ID (61), length 19: hardware-type 255, 5d:bb:54:d7:0e:24:1b:19:90:ca:4a:7d:f4:6f:d9:2c:f4:cb
	    Parameter-Request (55), length 10: 
	      Subnet-Mask (1), Default-Gateway (3), Domain-Name-Server (6), Hostname (12)
	      Domain-Name (15), Static-Route (33), NTP (42), TZ-Name (101)
	      Unknown (120), Classless-Static-Route (121)
	    MSZ (57), length 2: 1472
	    Hostname (12), length 5: "dhcpjail"
21:17:14.786900 64:8c:f7:89:14:56 > 8f:7a:f6:4c:78:49, ethertype IPv4 (0x0800), length 354: (tos 0xc0, ttl 64, id 54699, offset 0, flags [none], proto UDP (17), length 340)
    192.168.1.1.67 > 192.168.1.171.68: [udp sum ok] BOOTP/DHCP, Reply, length 312, xid 0xbfbdcf2c, secs 33, Flags [none] (0x0000)
	  Your-IP 192.168.1.171
	  Server-IP 192.168.1.1
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Offer
	    Server-ID (54), length 4: 192.168.1.1
	    Lease-Time (51), length 4: 43200
	    RN (58), length 4: 21600
	    RB (59), length 4: 37800
	    Subnet-Mask (1), length 4: 255.255.255.0
	    BR (28), length 4: 192.168.1.255
	    Default-Gateway (3), length 4: 192.168.1.1
	    Domain-Name (15), length 14: "example.com"
	    Domain-Name-Server (6), length 8: 192.168.1.18,192.168.1.1
21:17:14.787267 8f:7a:f6:4c:78:49 > ff:ff:ff:ff:ff:ff, ethertype IPv4 (0x0800), length 342: (tos 0xc0, ttl 64, id 0, offset 0, flags [none], proto UDP (17), length 328)
    0.0.0.0.68 > 255.255.255.255.67: [udp sum ok] BOOTP/DHCP, Request from 8f:7a:f6:4c:78:49, length 300, xid 0xbfbdcf2c, secs 36, Flags [none] (0x0000)
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: Request
	    Client-ID (61), length 19: hardware-type 255, 5d:bb:54:d7:0e:24:1b:19:90:ca:4a:7d:f4:6f:d9:2c:f4:cb
	    Parameter-Request (55), length 10: 
	      Subnet-Mask (1), Default-Gateway (3), Domain-Name-Server (6), Hostname (12)
	      Domain-Name (15), Static-Route (33), NTP (42), TZ-Name (101)
	      Unknown (120), Classless-Static-Route (121)
	    MSZ (57), length 2: 1472
	    Server-ID (54), length 4: 192.168.1.1
	    Requested-IP (50), length 4: 192.168.1.171
	    Hostname (12), length 5: "dhcpjail"
21:17:14.789413 64:8c:f7:89:14:56 > 8f:7a:f6:4c:78:49, ethertype IPv4 (0x0800), length 361: (tos 0xc0, ttl 64, id 54700, offset 0, flags [none], proto UDP (17), length 347)
    192.168.1.1.67 > 192.168.1.171.68: [udp sum ok] BOOTP/DHCP, Reply, length 319, xid 0xbfbdcf2c, secs 36, Flags [none] (0x0000)
	  Your-IP 192.168.1.171
	  Server-IP 192.168.1.1
	  Client-Ethernet-Address 8f:7a:f6:4c:78:49
	  Vendor-rfc1048 Extensions
	    Magic Cookie 0x63825363
	    DHCP-Message (53), length 1: ACK
	    Server-ID (54), length 4: 192.168.1.1
	    Lease-Time (51), length 4: 43200
	    RN (58), length 4: 21600
	    RB (59), length 4: 37800
	    Subnet-Mask (1), length 4: 255.255.255.0
	    BR (28), length 4: 192.168.1.255
	    Default-Gateway (3), length 4: 192.168.1.1
	    Domain-Name (15), length 14: "example.com"
	    Hostname (12), length 5: "dhcpjail"
	    Domain-Name-Server (6), length 8: 192.168.1.18,192.168.1.1
^C
7 packets captured
7 packets received by filter
0 packets dropped by kernel

Started at 21:16:42 and done at 21:17:14. So it took 32 seconds for IP address assignment. Looks like it does a few discovers. @Lockszmith-GH anything you can tell from this logging? Should I be logging something else instead?

@Lockszmith-GH
Copy link

Sorry for the late response, it's harder than looking at it in wireshark (the way to do this, would be to have tcpdump into a pcap file)

What I CAN see right now matches what your previous 'journald' output shows:

021:16:42.174415jail-MACBROADCAST BOOTP/DHCP Discover Request for hostname dhcpjail 
+4s21:16:46.290797jail-MACBROADCAST BOOTP/DHCP Discover Request for hostname dhcpjailrepeat#1
+11s21:16:55.047479jail-MACBROADCAST BOOTP/DHCP Discover Request for hostname dhcpjailrepeat#2
+16s21:17:11.780372jail-MACBROADCAST BOOTP/DHCP Discover Request for hostname dhcpjailrepeat#3
+3s21:17:14.786900router-MACjail-MACBOOTP/DHCP, Reply (assigned IP) 

I think what you need to do here is to capture from outside the jail while capturing from the inside of the jail.
I would love to know whether those first 3 DHCP Requests actually get to the physical LAN.

I was looking up your Router's MAC address to try and figure out if I can give vendor specific tips, but it doesn't register, so I'm guessing it's a Virtual Router.

Can your router capture network traffic? If so, also capture network traffic on that end.

Hope all of this points you in the right direction.

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 5, 2024

Thanks for your suggestions. Sorry I replaced the original MAC addresses with random ones. Do you think you could try to reproduce this setup? A bridge interface on TrueNAS SCALE and a DHCP enabled jail using this bridge. I'd be curious to know if you have it too.

@Lockszmith-GH
Copy link

I'm planning to, but didn't want to commit, because not sure I'll have the time for more than a review - if I do, I'll update you. (Just been swamped with a lot of stuff, tracking GitHub is my escapasim)

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented Mar 6, 2024

No worries! Any help is appreciated :) And it's not a major issue anyway. Just a bit annoying that it's slow to start. Let me know if you ever look into it more.

@dasunsrule32
Copy link

This happens with Truenas Scale's Apps as well, especially when using Custom Apps and adding the br0 interface. It's slow with static or dhcp addresses. I'm thinking it might be a Scale thing.

@Lockszmith-GH
Copy link

Too late for me now, but wanted to visit this myself as well. These are all notes to myself for tomorrow to read some more:
https://superuser.com/a/1676319/100730
https://www.golinuxcloud.com/configure-network-bridge-nmcli-static-dhcp/

Slow DHCP is usually attributed to STP (need to research whether STP enabled is slowing down, or whether it's disabled and slowing down)

@mrstux
Copy link
Contributor

mrstux commented May 2, 2024 •
edited

Linux Bridge certainly implements STP. I'd be surprised if it wasn't enabled by default.

And there we go:

Spanning tree protocol (STP) is enabled by default

@Jip-Hop
Copy link
Owner Author

Jip-Hop commented May 2, 2024

This happens with Truenas Scale's Apps as well, especially when using Custom Apps and adding the br0 interface

Would be interesting to know if it is slow as well with a VM connected to a bridge interface. But good information that it doesn't just happen with jailmaker!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working help wanted Extra attention is needed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@dasunsrule32 @Lockszmith-GH @mrstux @Jip-Hop