| 5 Jun 2023 |
 oddlama |
| 18:22:00 |
| oddlama | * ○ systemd-networkd.service - Network Configuration
Loaded: loaded (/etc/systemd/system/systemd-networkd.service; enabled; preset: enabled)
Drop-In: /nix/store/4cx8q44c60saw5jz7qrda31h22qgbviy-system-units/systemd-networkd.service.d
└─overrides.conf
Active: inactive (dead) since Mon 2023-06-05 19:38:12 CEST; 16min ago
Duration: 43.928s
TriggeredBy: ● systemd-networkd.socket
Docs: man:systemd-networkd.service(8)
Main PID: 181 (code=exited, status=0/SUCCESS)
Status: "Shutting down..."
IP: 0B in, 0B out
CPU: 47ms
Jun 05 19:37:28 localhost systemd[1]: Starting Network Configuration...
Jun 05 19:37:28 localhost systemd-networkd[181]: lo: Link UP
Jun 05 19:37:28 localhost systemd-networkd[181]: lo: Gained carrier
Jun 05 19:37:28 localhost systemd-networkd[181]: Enumeration completed
Jun 05 19:37:28 localhost systemd[1]: Started Network Configuration.
Jun 05 19:37:28 localhost systemd-networkd[181]: wan: Configuring with /etc/systemd/network/10-wan.network.
Jun 05 19:37:28 localhost systemd-networkd[181]: wan: Link UP
Jun 05 19:37:29 localhost systemd-networkd[181]: wan: Gained carrier
Jun 05 19:37:30 localhost systemd-networkd[181]: wan: Gained IPv6LL | 18:22:04 |
| oddlama | * ○ systemd-networkd.service - Network Configuration
Loaded: loaded (/etc/systemd/system/systemd-networkd.service; enabled; preset: enabled)
Drop-In: /nix/store/4cx8q44c60saw5jz7qrda31h22qgbviy-system-units/systemd-networkd.service.d
└─overrides.conf
Active: inactive (dead) since Mon 2023-06-05 19:38:12 CEST; 16min ago
Duration: 43.928s
TriggeredBy: ● systemd-networkd.socket
Docs: man:systemd-networkd.service(8)
Main PID: 181 (code=exited, status=0/SUCCESS)
Status: "Shutting down..."
IP: 0B in, 0B out
CPU: 47ms
Jun 05 19:37:28 localhost systemd\[1\]: Starting Network Configuration...
Jun 05 19:37:28 localhost systemd-networkd\[181\]: lo: Link UP
Jun 05 19:37:28 localhost systemd-networkd\[181\]: lo: Gained carrier
Jun 05 19:37:28 localhost systemd-networkd\[181\]: Enumeration completed
Jun 05 19:37:28 localhost systemd\[1\]: Started Network Configuration.
Jun 05 19:37:28 localhost systemd-networkd\[181\]: wan: Configuring with /etc/systemd/network/10-wan.network.
Jun 05 19:37:28 localhost systemd-networkd\[181\]: wan: Link UP
Jun 05 19:37:29 localhost systemd-networkd\[181\]: wan: Gained carrier
Jun 05 19:37:30 localhost systemd-networkd\[181\]: wan: Gained IPv6LL
| 18:22:32 |
| oddlama | I didn't have these problems some a week ago, so maybe it's something else I enabled that interferes, or this is non-deterministic? I have no idea where to start investigating | 18:27:15 |
| oddlama | * I didn't have these problems week ago, so maybe it's something else I enabled that interferes, or this is non-deterministic? I have no idea where to start investigating | 18:27:20 |
 ElvishJerricco | yea I'm not really sure where to look next | 18:27:36 |
| oddlama | Let me restart with the same configuration to see whether it happens every tiem | 18:27:57 |
| oddlama | * Let me restart with the same configuration to see whether it happens every time | 18:27:58 |
| ElvishJerricco | maybe systemctl list-dependencies --reverse/--after/--before systemd-networkd.service? | 18:28:02 |
| oddlama | Seems reproducible | 18:30:10 |
| oddlama | A notable thing in the logs is that even though | 18:32:14 |
| oddlama | * A notable thing in the logs is that even though
Jun 05 20:29:40 sentinel systemd[1]: systemd-networkd.service: Deactivated successfully.
is printed when switching
| 18:32:27 |
| oddlama | I get another output from systemd-networkd in stage2 | 18:32:46 |
| oddlama | Jun 05 20:29:38 sentinel systemd-networkd[180]: wan: DHCPv6 lease lost | 18:32:49 |
| oddlama | No wair | 18:33:12 |
| oddlama | * No wait | 18:33:13 |
| oddlama | the logs are not in order?! | 18:33:17 |
| oddlama | Okay now I'm totally lost. Why would the logs be unordered? | 18:34:05 |
| ElvishJerricco | wait wut | 18:36:59 |
| ElvishJerricco | maybe systemd-timesyncd is changing the system clock once stage 2 gets going? | 18:37:27 |
| oddlama | It's just some select lines | 18:37:47 |
| oddlama | Jun 05 20:29:40 sentinel systemd[1]: Starting Journal Service...
Jun 05 20:29:40 sentinel systemd[1]: Starting Load Kernel Modules...
Jun 05 20:29:40 sentinel kernel: fuse: init (API version 7.37)
Jun 05 20:29:40 sentinel systemd[1]: systemd-networkd-wait-online.service: Bound to unit systemd-networkd.service, but unit isn't active.
Jun 05 20:29:40 sentinel systemd[1]: Dependency failed for Wait for Network to be Configured.
Jun 05 20:29:40 sentinel systemd[1]: systemd-networkd-wait-online.service: Job systemd-networkd-wait-online.service/start failed with result 'dependency'.
Jun 05 20:29:40 sentinel systemd[1]: Starting Remount Root and Kernel File Systems...
Jun 05 20:29:40 sentinel systemd[1]: Starting Coldplug All udev Devices...
Jun 05 20:29:40 sentinel systemd[1]: Mounted Huge Pages File System.
Jun 05 20:29:40 sentinel systemd[1]: Mounted POSIX Message Queue File System.
Jun 05 20:29:40 sentinel systemd-journald[730]: Collecting audit messages is disabled.
Jun 05 20:29:40 sentinel systemd[1]: Mounted Kernel Debug File System.
Jun 05 20:29:40 sentinel systemd[1]: Finished Create List of Static Device Nodes.
Jun 05 20:29:40 sentinel systemd[1]: modprobe@configfs.service: Deactivated successfully.
Jun 05 20:29:40 sentinel systemd[1]: Finished Load Kernel Module configfs.
Jun 05 20:29:40 sentinel systemd[1]: modprobe@efi_pstore.service: Deactivated successfully.
Jun 05 20:29:40 sentinel systemd[1]: Finished Load Kernel Module efi_pstore.
Jun 05 20:29:40 sentinel systemd[1]: modprobe@fuse.service: Deactivated successfully.
Jun 05 20:29:40 sentinel systemd[1]: Finished Load Kernel Module fuse.
Jun 05 20:29:40 sentinel systemd-journald[730]: Journal started
Jun 05 20:29:40 sentinel systemd-journald[730]: Runtime Journal (/run/log/journal/25e272da45124b238d42df4ec5fca13c) is 8.0M, max 94.1M, 86.1M free.
Jun 05 20:29:38 sentinel systemd-networkd[180]: wan: DHCPv6 lease lost
Jun 05 20:29:38 sentinel sshd[197]: syslogin_perform_logout: logout() returned an error
Jun 05 20:29:40 sentinel systemd[1]: Started Journal Service.
Jun 05 20:29:39 sentinel systemd[1]: Queued start job for default target Multi-User System.
Jun 05 20:29:39 sentinel systemd[1]: systemd-journald.service: Deactivated successfully.
Jun 05 20:29:40 sentinel systemd[1]: Finished Bind mount or link '/persist/etc/machine-id' to '/etc/machine-id'.
Jun 05 20:29:40 sentinel systemd[1]: Finished Bind mount or link '/persist/etc/ssh/ssh_host_ed25519_key' to '/etc/ssh/ssh_host_ed25519_key'.
Jun 05 20:29:40 sentinel systemd[1]: Finished Bind mount or link '/persist/etc/ssh/ssh_host_ed25519_key.pub' to '/etc/ssh/ssh_host_ed25519_key.pub'.
Jun 05 20:29:40 sentinel systemd[1]: Mounting FUSE Control File System...
Jun 05 20:29:40 sentinel systemd-modules-load[737]: Inserted module 'bridge'
Jun 05 20:29:40 sentinel kernel: bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
Jun 05 20:29:40 sentinel systemd[1]: Mounting Kernel Configuration File System...
Jun 05 20:29:40 sentinel systemd[1]: Starting Create Static Device Nodes in /dev...
Jun 05 20:29:40 sentinel systemd[1]: Mounted FUSE Control File System.
Jun 05 20:29:40 sentinel systemd[1]: Mounted Kernel Configuration File System.
Jun 05 20:29:40 sentinel kernel: ACPI: bus type drm_connector registered
Jun 05 20:29:40 sentinel systemd[1]: modprobe@drm.service: Deactivated successfully.
Jun 05 20:29:40 sentinel systemd-modules-load[737]: Inserted module 'macvlan'
Jun 05 20:29:40 sentinel systemd[1]: Finished Load Kernel Module drm.
Jun 05 20:29:40 sentinel systemd-modules-load[737]: Inserted module 'tap'
Jun 05 20:29:40 sentinel kernel: tun: Universal TUN/TAP device driver, 1.6
| 18:38:10 |
| oddlama | most are :40 | 18:38:20 |
| oddlama | some are :38 or :39 | 18:38:24 |
| oddlama | Maybe this is when the journal from stage1 is loaded into to actual journal in stage2? | 18:39:01 |
| ElvishJerricco | tbh I don't really understand how the journal is handed over between stages | 18:39:53 |
| oddlama | Probably not relevant for this case anyway. Seems to me like networkd is stopped in stage1 and never exists in stage2, the log just seems to be carried over weirdly. | 18:41:12 |
| oddlama | Hmm your hunch was right, setting flushBeforeStage2 = true; works around the issue | 18:52:44 |
| ElvishJerricco | oddlama: interesting. Can you open an issue and include your configuration? | 18:53:27 |
| oddlama | Just noticed that the systemd-networkd.service: Deactivated successfully also happens in stage2 not stage1, the log order is just also wrong there :D | 19:09:29 |
