No network (IPv4?) connectivity via Ethernet at first boot for LUKS/Clevis setup

Project Discussion
2

From @bgilbert I got a tip at GitHub:

As for why you don’t have networking in the initramfs… that’s another question. I’d suggest starting by checking for NetworkManager journal entries.

So:

  • I first noticed I had included the /adv for the tang server in the domain in the CoreOS configuration file, which is of course not what we want, as it duplicated that key. However, that’s just another little problem that I would have seen later.
  • Another maybe related problem I see is that I cannot mount any USB drive, respectively the initramfs system does not detect it. I can run lsblk and although the USB stick is connected I always get the same result with only my internal disk. Maybe it has a problem with all peripherals? Though, input/output devices work, so my USB keyboard is recognized.
  • I managed to now mount /boot properly, so I can now give you logs as text files, at least… :tada:

And this dracut guide gave also some good hints.
BTW I’m not using fedora-coreos-33.20210426.2.0-metal.x86_64.raw (from current testing) as that was said to wait for a Tang server.

$ ip addr show
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
   link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
   inet 127.0.0.1/8 scope host lo
      valid_lft forever preferred_lft forever
   inet6 ::1/128 scope host 
      valid_lft forever preferred_lft forever
2: enp3s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
   link/ether 00:*****:11 brd ff:ff:ff:ff:ff:ff
   inet6 fd1c:f1a1:f84b::bee/128 scope global noprefixroute 
      valid_lft forever preferred_lft forever
   inet6 fd1c:f1a1:f84b:0:2e0:4cff:fee9:2411/64 scope global noprefixroute 
      valid_lft forever preferred_lft forever
   inet6 fe80::2e0:4cff:fee9:2411/64 scope link noprefixroute 
      valid_lft forever preferred_lft forever

Thankfully I also have the 300kB full copy of rdsosreport.txt, which dracut or so generated, which, however, also just contains this information. But feel free to ask for more.

NetworkManager CLI logs:

$ journalctl -t NetworkManager
-- Logs begin at Sun 2021-05-02 18:23:06 UTC, end at Sun 2021-05-02 19:13:00 UTC. --
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4938] NetworkManager (version 1.26.8-1.fc33) is starting... (for the first time)
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4938] Read config: /etc/NetworkManager/NetworkManager.conf
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4949] auth[0x5557cdd39f00]: create auth-manager: D-Bus connection not available. Polkit is disabled and only root will be authorized.
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4955] manager[0x5557cdd84010]: monitoring kernel firmware directory '/lib/firmware'.
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4956] hostname: hostname: hostnamed not used as proxy creation failed with: Could not connect: No such file or directory
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4957] dns-mgr[0x5557cdd7d2c0]: init: dns=default,systemd-resolved rc-manager=symlink
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4998] manager[0x5557cdd84010]: rfkill: Wi-Fi hardware radio set enabled
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.4998] manager[0x5557cdd84010]: rfkill: WWAN hardware radio set enabled
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5006] Loaded device plugin: NMTeamFactory (/usr/lib64/NetworkManager/1.26.8-1.fc33/libnm-device-plugin-team.so)
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5006] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5006] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5006] manager: Networking is enabled by state file
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5006] dhcp-init: Using DHCP client 'internal'
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5007] settings: Loaded settings plugin: keyfile (internal)
May 02 18:23:08 localhost NetworkManager[531]: <warn>  [1619979788.5007] settings: could not load plugin 'ifcfg-rh' from file '/usr/lib64/NetworkManager/1.26.8-1.fc33/libnm-settings-plugin-ifcfg-rh.so': No such file or directory
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5016] device (lo): carrier: link connected
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5016] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5018] manager: (enp3s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
May 02 18:23:08 localhost NetworkManager[531]: <info>  [1619979788.5020] device (enp3s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 02 18:23:08 localhost NetworkManager[531]: <warn>  [1619979788.7301] sleep-monitor-sd: failed to acquire D-Bus proxy: Could not connect: No such file or directory
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5203] device (enp3s0): carrier: link connected
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5204] device (enp3s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5207] policy: auto-activating connection 'Wired Connection' (2d90b610-a502-4954-a9a8-64a67ae0a4a3)
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5209] device (enp3s0): Activation: starting connection 'Wired Connection' (2d90b610-a502-4954-a9a8-64a67ae0a4a3)
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5209] device (enp3s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5209] manager: NetworkManager state is now CONNECTING
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5210] device (enp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5211] device (enp3s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 02 18:23:11 localhost NetworkManager[531]: <info>  [1619979791.5212] dhcp4 (enp3s0): activation: beginning transaction (timeout in 45 seconds)
May 02 18:23:13 localhost NetworkManager[531]: <info>  [1619979793.4855] dhcp6 (enp3s0): activation: beginning transaction (timeout in 45 seconds)
May 02 18:23:13 localhost NetworkManager[531]: <info>  [1619979793.4869] dhcp6 (enp3s0): option dhcp6_name_servers   => 'fd1c:f1a1:f84b::1'
May 02 18:23:13 localhost NetworkManager[531]: <info>  [1619979793.4869] dhcp6 (enp3s0): option ip6_address          => 'fd1c:f1a1:f84b::bee'
May 02 18:23:13 localhost NetworkManager[531]: <info>  [1619979793.4869] dhcp6 (enp3s0): state changed unknown -> bound
May 02 18:23:15 localhost NetworkManager[531]: <info>  [1619979795.2218] device (enp3s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2219] device (enp3s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2219] device (enp3s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2220] manager: NetworkManager state is now CONNECTED_LOCAL
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2222] policy: set-hostname: set hostname to 'localhost.localdomain' (no default device)
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2223] device (enp3s0): Activation: successful, device activated.
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2223] manager: startup complete
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2224] quitting now that startup is complete
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2355] dhcp4 (enp3s0): canceled DHCP transaction
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2355] dhcp4 (enp3s0): state changed unknown -> done
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2356] dhcp6 (enp3s0): canceled DHCP transaction
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2356] dhcp6 (enp3s0): state changed bound -> done
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2356] device (enp3s0): DHCPv6: trying to acquire a new lease within 90 seconds
May 02 18:23:15 localhost.localdomain NetworkManager[531]: <info>  [1619979795.2356] exiting (success)

And here is the Clevis error this results in:

May 02 18:23:37 localhost.localdomain ignition[580]: Ignition failed: failed to create luks: binding clevis device: exit status 1: Cmd: "clevis" "luks" "bind" "-f" "-k" "/run/ignition/luks-keyfiles/root" "-d" "/run/ignition/dev_aliases/dev/disk/by-partlabel/root" "sss" "{\"pins\":{\"tang\":[{\"url\":\"http://**my-IPv4-to-tang-server**:**my-tang-server-port**\",\"thp\":\"J-***********\"}]},\"t\":1}" Stdout: "" Stderr: "Warning: Value 512 is outside of the allowed entropy range, adjusting it.\nUnable to fetch advertisement: 'http://**my-IPv4-to-tang-server**:**my-tang-server-port**/adv/J-*********!\nInvalid input!\nUsage: jose jwe fmt -i JWE [-I CT] [-o JWE] [-O CT] [-c]\n\nConverts a JWE between serialization formats\n\n  -i JSON --input=JSON     Parse JWE from JSON\n  -i FILE --input=FILE     Read JWE from FILE\n  -i -    --input=-        Read JWE from standard input\n\n  -I FILE --detached=FILE  Read decoded ciphertext from FILE\n  -I -    --detached=-     Read decoded ciphertext from standard input\n\n  -o JSON --output=JSON    Parse JWE from JSON\n  -o FILE --output=FILE    Read JWE from FILE\n  -o -    --output=-       Read JWE from standard input\n                           Default: \"-\"\n\n  -O JSON --detach=JSON    Parse JWE from JSON\n  -O FILE --detach=FILE    Read JWE from FILE\n  -O -    --detach=-       Read JWE from standard input\n\n  -c      --compact        Output JWE using compact serialization\n\nFailed to import token from file.\nError saving metadata to LUKS2 header in device /run/ignition/dev_aliases/dev/disk/by-partlabel/root\nUnable to update metadata; operation cancelled\nError adding new binding to /run/ignition/dev_aliases/dev/disk/by-partlabel/root\n"

What is basically just says it what it always said:

Unable to fetch advertisement

So given the NetworkManager extract only talks about IPv6, could it really be that ignores IPv4 as I intitially thought?

I searched for Ipv4 in the whole system log:

May 02 18:23:07 localhost systemd[1]: Starting Apply Kernel Variables...
May 02 18:23:07 localhost systemd-journald[254]: Missed 1 kernel messages
May 02 18:23:07 localhost kernel: usb 1-4: New USB device found, idVendor=03f0, idProduct=034a, bcdDevice= 1.21
May 02 18:23:07 localhost kernel: usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May 02 18:23:07 localhost kernel: usb 1-4: Product: HP Elite USB Keyboard 
# NOTE: It detected my keyboard here.
May 02 18:23:07 localhost kernel: usb 1-4: Manufacturer: Chicony
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/all/rp_filter (explicit setting exists).
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/default/rp_filter (explicit setting exists).
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/all/accept_source_route (explicit setting exists).
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/default/accept_source_route (explicit setting exists).
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/all/promote_secondaries (explicit setting exists).
May 02 18:23:07 localhost systemd-sysctl[294]: Not setting net/ipv4/conf/default/promote_secondaries (explicit setting exists).
May 02 18:23:07 localhost systemd[1]: Finished Apply Kernel Variables.
# […]
May 02 19:10:08 localhost.localdomain kernel: audit: type=1130 audit(1619982608.244:109): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/all/rp_filter (explicit setting exists).
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/default/rp_filter (explicit setting exists).
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/all/accept_source_route (explicit setting exists).
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/default/accept_source_route (explicit setting exists).
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/all/promote_secondaries (explicit setting exists).
May 02 19:10:08 localhost.localdomain systemd-sysctl[2616]: Not setting net/ipv4/conf/default/promote_secondaries (explicit setting exists).
May 02 19:10:08 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:08 localhost.localdomain systemd[1]: Finished Apply Kernel Variables.
# […]

May 02 19:10:13 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/all/rp_filter (explicit setting exists).
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/default/rp_filter (explicit setting exists).
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/all/accept_source_route (explicit setting exists).
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/default/accept_source_route (explicit setting exists).
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/all/promote_secondaries (explicit setting exists).
May 02 19:10:13 localhost.localdomain systemd-sysctl[2900]: Not setting net/ipv4/conf/default/promote_secondaries (explicit setting exists).
May 02 19:10:13 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:13 localhost.localdomain systemd[1]: Finished Apply Kernel Variables.
# […]
May 02 19:10:15 localhost.localdomain systemd[1]: Finished Create Static Device Nodes in /dev.
May 02 19:10:15 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/all/rp_filter (explicit setting exists).
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/default/rp_filter (explicit setting exists).
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/all/accept_source_route (explicit setting exists).
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/default/accept_source_route (explicit setting exists).
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/all/promote_secondaries (explicit setting exists).
May 02 19:10:15 localhost.localdomain systemd-sysctl[3196]: Not setting net/ipv4/conf/default/promote_secondaries (explicit setting exists).
May 02 19:10:15 localhost.localdomain audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 02 19:10:15 localhost.localdomain systemd[1]: Finished Apply Kernel Variables.

Does anyone know how to further debug this? Is there any way I can access nmcli from dracut e.g.? It’s not in /sbin or so, I already checked that.