build01: building gqj19pgsvn7kjrz7iypixcrcgm4c0wxr-container-test-run-admin.drv Machine state will be reset. To keep it, pass --keep-machine-state start all VLans (finished: start all VLans, in 0.00 seconds) Test will time out and terminate in 3600.0 seconds run the VM test script additionally exposed symbols: client, server, vlan1, start_all, test_script, machines, machines_qemu, machines_nspawn, vlans, driver, log, os, create_machine, subtest, run_tests, join_all, retry, serial_stdout_off, serial_stdout_on, polling_condition, BaseMachine, QemuMachine, NspawnMachine, t, debug, dump_machine_ssh start all VMs client: systemd-nspawn running (pid 52) client: Waiting for journal at /build/vm-state-client/var/log/journal... server: systemd-nspawn running (pid 54) server: Waiting for journal at /build/vm-state-server/var/log/journal... (finished: start all VMs, in 0.00 seconds) nixos-nspawn(server): TAP vde-tap1 not found; container will be isolated from VDE nixos-nspawn(server): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths. nixos-nspawn(client): TAP vde-tap1 not found; container will be isolated from VDE nixos-nspawn(client): A common reason for this is that /dev/net is not available in the Nix sandbox. Try adding /dev/net to extra-sandbox-paths. Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file. Note: in a future version of systemd-nspawn the default set of permitted socket address families will be restricted to AF_INET, AF_INET6 and AF_UNIX. Use --restrict-address-families= to configure the set of permitted socket address families, or set RestrictAddressFamilies= in a .nspawn file. ░ Spawning container server on /build/vm-state-server. ░ Spawning container client on /build/vm-state-client. client # No journal files were found. client # No journal boot entry found for the specified boot (+0). server # No journal files were found. server # No journal boot entry found for the specified boot (+0). client # [ 595.438507] client systemd-journald[72]: Journal started client # [ 595.438558] client systemd-journald[72]: Runtime Journal (/run/log/journal/08e5586d38e94508b96fba877cd98810) is 8M, max 2.5G, 2.4G free. client # [ 595.448841] client systemd[1]: Finished Apply Kernel Variables. client # [ 595.462749] client systemd[1]: Finished Create Static Device Nodes in /dev gracefully. client # [ 595.476275] client systemd[1]: Starting Flush Journal to Persistent Storage... client # [ 595.477109] client systemd[1]: Starting Network Name Resolution... client # [ 595.477811] client systemd[1]: Starting Create Static Device Nodes in /dev... client # [ 595.484651] client systemd-journald[72]: Time spent on flushing to /var/log/journal/08e5586d38e94508b96fba877cd98810 is 1.057ms for 7 entries. client # [ 595.484651] client systemd-journald[72]: System Journal (/var/log/journal/08e5586d38e94508b96fba877cd98810) is 8M, max 4G, 3.9G free. client # [ 595.506379] client systemd[1]: Finished Create Static Device Nodes in /dev. client # [ 595.507001] client systemd[1]: Reached target Preparation for Local File Systems. client # [ 595.507106] client systemd[1]: Reached target Local File Systems. client # [ 595.507935] client systemd[1]: Listening on Boot Loader Control Service Socket. client # [ 595.507982] client systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container client # [ 595.508768] client systemd[1]: Starting Save Transient machine-id to Disk... client # [ 595.508804] client systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys client # [ 595.571502] client systemd[1]: Finished Firewall. client # [ 595.571664] client systemd[1]: Reached target Preparation for Network. client # [ 595.571874] client systemd[1]: Listening on Network Management Resolve Hook Socket. client # [ 595.573081] client systemd[1]: Starting Network Management... client # [ 595.645942] client systemd[1]: Finished Flush Journal to Persistent Storage. client # [ 595.647805] client systemd[1]: Starting Create System Files and Directories... client # [ 595.665151] client systemd-tmpfiles[179]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted client # [ 595.665355] client systemd-tmpfiles[179]: fchmod() of /var/log/journal failed: Operation not permitted client # [ 595.665494] client systemd-tmpfiles[179]: fchmod() of /var/log/journal/08e5586d38e94508b96fba877cd98810 failed: Operation not permitted client # [ 595.665712] client systemd-tmpfiles[179]: fchmod() of /run/log/journal failed: Operation not permitted client # [ 595.667142] client systemd[1]: Finished Create System Files and Directories. client # [ 595.668341] client systemd[1]: Starting Rebuild Journal Catalog... client # [ 595.669081] client systemd[1]: Starting Record System Boot/Shutdown in UTMP... client # [ 595.679676] client systemd[1]: Finished Record System Boot/Shutdown in UTMP. client # [ 595.686853] client systemd[1]: Finished Rebuild Journal Catalog. client # [ 595.687922] client systemd[1]: Starting Update is Completed... client # [ 595.697690] client systemd[1]: Finished Update is Completed. server # [ 595.437779] server systemd-journald[101]: Journal started server # [ 595.437838] server systemd-journald[101]: Runtime Journal (/run/log/journal/34d410b7121c47b2b827ba5ef967edb6) is 8M, max 2.5G, 2.4G free. server # [ 595.448815] server systemd[1]: Finished Apply Kernel Variables. server # [ 595.460627] server systemd[1]: Finished Create Static Device Nodes in /dev gracefully. server # [ 595.473759] server systemd[1]: Starting Flush Journal to Persistent Storage... server # [ 595.474591] server systemd[1]: Starting Network Name Resolution... server # [ 595.475273] server systemd[1]: Starting Create Static Device Nodes in /dev... server # [ 595.482470] server systemd-journald[101]: Time spent on flushing to /var/log/journal/34d410b7121c47b2b827ba5ef967edb6 is 1.082ms for 7 entries. server # [ 595.482470] server systemd-journald[101]: System Journal (/var/log/journal/34d410b7121c47b2b827ba5ef967edb6) is 8M, max 4G, 3.9G free. server # [ 595.505842] server systemd[1]: Finished Create Static Device Nodes in /dev. server # [ 595.506419] server systemd[1]: Reached target Preparation for Local File Systems. server # [ 595.506523] server systemd[1]: Reached target Local File Systems. server # [ 595.507389] server systemd[1]: Listening on Boot Loader Control Service Socket. server # [ 595.507433] server systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container server # [ 595.508329] server systemd[1]: Starting Save Transient machine-id to Disk... server # [ 595.508359] server systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys server # [ 595.576573] server systemd[1]: Finished Firewall. server # [ 595.576712] server systemd[1]: Reached target Preparation for Network. server # [ 595.576920] server systemd[1]: Listening on Network Management Resolve Hook Socket. server # [ 595.577860] server systemd[1]: Starting Network Management... server # [ 595.641178] server systemd[1]: Finished Flush Journal to Persistent Storage. server # [ 595.642894] server systemd[1]: Starting Create System Files and Directories... server # [ 595.657729] server systemd-tmpfiles[210]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted server # [ 595.657898] server systemd-tmpfiles[210]: fchmod() of /var/log/journal failed: Operation not permitted server # [ 595.658014] server systemd-tmpfiles[210]: fchmod() of /var/log/journal/34d410b7121c47b2b827ba5ef967edb6 failed: Operation not permitted server # [ 595.658177] server systemd-tmpfiles[210]: fchmod() of /run/log/journal failed: Operation not permitted server # [ 595.663475] server systemd[1]: Finished Create System Files and Directories. server # [ 595.665219] server systemd[1]: Starting Rebuild Journal Catalog... server # [ 595.665995] server systemd[1]: Starting Record System Boot/Shutdown in UTMP... server # [ 595.677216] server systemd[1]: Finished Record System Boot/Shutdown in UTMP. server # [ 595.684115] server systemd[1]: Finished Rebuild Journal Catalog. server # [ 595.685181] server systemd[1]: Starting Update is Completed... server # [ 595.695209] server systemd[1]: Finished Update is Completed. server # [ 596.328340] server systemd-networkd[206]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted server # [ 596.328436] server systemd-networkd[206]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted server # [ 596.337478] server systemd-networkd[206]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. server # [ 596.337647] server systemd-networkd[206]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. server # [ 596.337811] server systemd-networkd[206]: lo: Link UP server # [ 596.337815] server systemd-networkd[206]: lo: Gained carrier server # [ 596.338013] server systemd-networkd[206]: eth1: Configuring with /etc/systemd/network/40-eth1.network. server # [ 596.338365] server systemd[1]: Started Network Management. server # [ 596.380380] server systemd-networkd[206]: eth1: Link UP client # [ 596.316159] client systemd-networkd[175]: Failed to increase receive buffer size for general netlink socket, ignoring: Operation not permitted server # [ 596.380466] server systemd[1]: Starting Enable Persistent Storage in systemd-networkd... client # [ 596.316254] client systemd-networkd[175]: Failed to increase receive buffer size for nftables netlink socket, ignoring: Operation not permitted server # [ 596.380681] server systemd-networkd[206]: eth1: Gained carrier client # [ 596.325175] client systemd-networkd[175]: /etc/systemd/network/99-ethernet-default-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. server # [ 596.434441] server systemd[1]: Finished Enable Persistent Storage in systemd-networkd. client # [ 596.325346] client systemd-networkd[175]: /etc/systemd/network/99-wireless-client-dhcp.network: No valid settings found in the [Match] section, ignoring file. To match all interfaces, add Name=* in the [Match] section. client # [ 596.325506] client systemd-networkd[175]: lo: Link UP client # [ 596.325510] client systemd-networkd[175]: lo: Gained carrier client # [ 596.325707] client systemd-networkd[175]: eth1: Configuring with /etc/systemd/network/40-eth1.network. client # [ 596.326180] client systemd-networkd[175]: eth1: Link UP client # [ 596.326490] client systemd-networkd[175]: eth1: Gained carrier client # [ 596.327478] client systemd[1]: Started Network Management. client # [ 596.328603] client systemd[1]: Starting Enable Persistent Storage in systemd-networkd... client # [ 596.387460] client systemd[1]: Finished Enable Persistent Storage in systemd-networkd. server # [ 596.746244] server systemd-resolved[139]: Positive Trust Anchors: server # [ 596.746255] server systemd-resolved[139]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d server # [ 596.746258] server systemd-resolved[139]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16 client # [ 596.748639] client systemd-resolved[112]: Positive Trust Anchors: client # [ 596.748649] client systemd-resolved[112]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d client # [ 596.748653] client systemd-resolved[112]: . IN DS 38696 8 2 683d2d0acb8c9b712a1948b27f741219298d0a450d612c483af444a4c0fb2b16 client # [ 596.748687] client systemd-resolved[112]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test client # [ 596.768125] client systemd-resolved[112]: Using system hostname 'client'. client # [ 596.769318] client systemd[1]: Started Network Name Resolution. client # [ 596.769386] client systemd[1]: Reached target Network. client # [ 596.769449] client systemd[1]: Reached target System Initialization. client # [ 596.769497] client systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container client # [ 596.769523] client systemd[1]: Started Daily Cleanup of Temporary Directories. client # [ 596.769543] client systemd[1]: Reached target Timer Units. client # [ 596.769657] client systemd[1]: Listening on D-Bus System Message Bus Socket. client # [ 597.436193] client systemd-networkd[175]: eth1: Gained IPv6LL client # [ 597.483337] client systemd[1]: Listening on Nix Daemon Socket. client # [ 597.483526] client systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. client # [ 597.483551] client systemd[1]: Reached target Socket Units. client # [ 597.483601] client systemd[1]: Reached target Basic System. client # [ 597.485113] client systemd[1]: Starting Import lastlog data into lastlog2 database... client # [ 597.486063] client systemd[1]: Starting Name Service Cache Daemon (nsncd)... client # [ 597.487345] client systemd[1]: Starting D-Bus System Message Bus... client # [ 597.531090] client systemd[1]: Finished Import lastlog data into lastlog2 database. client # [ 597.696234] client systemd[1]: Started Name Service Cache Daemon (nsncd). client # [ 597.696304] client systemd[1]: Reached target Host and Network Name Lookups. client # [ 597.696367] client systemd[1]: Reached target User and Group Name Lookups. client # [ 597.696568] client nsncd[191]: Oct 16 09:33:22.668 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" client # [ 597.697957] client systemd[1]: Starting User Login Management... client # [ 597.698675] client systemd[1]: Starting Permit User Sessions... server # [ 596.746292] server systemd-resolved[139]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 170.0.0.192.in-addr.arpa 171.0.0.192.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa ipv4only.arpa resolver.arpa corp home internal intranet lan local private test server # [ 596.766112] server systemd-resolved[139]: Using system hostname 'server'. server # [ 596.767405] server systemd[1]: Started Network Name Resolution. server # [ 596.767486] server systemd[1]: Reached target Network. server # [ 596.767549] server systemd[1]: Reached target System Initialization. server # [ 596.767598] server systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container server # [ 596.767624] server systemd[1]: Started Daily Cleanup of Temporary Directories. server # [ 596.767641] server systemd[1]: Reached target Timer Units. server # [ 596.767755] server systemd[1]: Listening on D-Bus System Message Bus Socket. server # [ 597.468195] server systemd-networkd[206]: eth1: Gained IPv6LL server # [ 597.483774] server systemd[1]: Listening on Nix Daemon Socket. server # [ 597.486626] server systemd[1]: Listening on OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Export). server # [ 597.489196] server systemd[1]: Listening on OpenSSH Server Socket (systemd-ssh-generator, AF_UNIX Local). server # [ 597.490467] server systemd[1]: Listening on SSH Socket. server # [ 597.490714] server systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. server # [ 597.490766] server systemd[1]: Reached target Socket Units. server # [ 597.490865] server systemd[1]: Reached target Basic System. server # [ 597.512605] server systemd[1]: Starting Import lastlog data into lastlog2 database... server # [ 597.514296] server systemd[1]: Starting Name Service Cache Daemon (nsncd)... server # [ 597.514350] server systemd[1]: SSH Host Keys Generation skipped, no trigger condition checks were met. server # [ 597.517782] server systemd[1]: Starting D-Bus System Message Bus... server # [ 597.533012] server systemd[1]: Finished Import lastlog data into lastlog2 database. server # [ 597.709752] server nsncd[222]: Oct 16 09:33:22.681 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" server # [ 597.709819] server systemd[1]: Started Name Service Cache Daemon (nsncd). server # [ 597.709938] server systemd[1]: Reached target Host and Network Name Lookups. server # [ 597.710065] server systemd[1]: Reached target User and Group Name Lookups. server # [ 597.740398] server systemd[1]: Starting User Login Management... client # [ 597.746491] client systemd[1]: Finished Permit User Sessions. server # [ 597.741224] server systemd[1]: Starting Permit User Sessions... client # [ 597.747588] client systemd[1]: Started Console Getty. server # [ 597.750358] server systemd[1]: Finished Permit User Sessions. client # [ 597.747636] client systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 server # [ 597.751341] server systemd[1]: Started Console Getty. client # [ 597.747657] client systemd[1]: Reached target Login Prompts. server # [ 597.751393] server systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 client # [ 597.860157] client dbus-broker-launch[192]: Looking up NSS user entry for 'systemd-timesync'... client # [ 597.861010] client dbus-broker-launch[192]: NSS returned no entry for 'systemd-timesync' client # [ 597.861010] client dbus-broker-launch[192]: Invalid user-name in /nix/store/3b7ivjy4avg8mhi9dg4k18x5vz316ar1-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" client # [ 597.861429] client systemd[1]: Started D-Bus System Message Bus. client # [ 597.868320] client dbus-broker-launch[192]: Ready server # [ 597.751416] server systemd[1]: Reached target Login Prompts. server # [ 597.863319] server dbus-broker-launch[223]: Looking up NSS user entry for 'systemd-timesync'... server # [ 597.864134] server dbus-broker-launch[223]: NSS returned no entry for 'systemd-timesync' server # [ 597.864134] server dbus-broker-launch[223]: Invalid user-name in /nix/store/fcv7s1kgqsb52z4a6rwfmvbwvv0z99y2-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" server # [ 597.864538] server systemd[1]: Started D-Bus System Message Bus. server # [ 597.871205] server dbus-broker-launch[223]: Ready client # [ 598.679073] client systemd-logind[207]: New seat seat0. server # [ 598.679430] server systemd-logind[238]: New seat seat0. client # [ 598.679248] client systemd[1]: Started User Login Management. server # [ 598.679651] server systemd[1]: Started User Login Management. client # [ 598.680398] client systemd[1]: Starting linger-users.service... server # [ 598.681864] server systemd[1]: Starting linger-users.service... client # [ 598.732338] client systemd[1]: linger-users.service: Deactivated successfully. server # [ 598.731793] server systemd[1]: linger-users.service: Deactivated successfully. client # [ 598.732423] client systemd[1]: Finished linger-users.service. server # [ 598.732032] server systemd[1]: Finished linger-users.service. client # [ 598.732847] client systemd[1]: Reached target Multi-User System. server # [ 598.732467] server systemd[1]: Reached target Multi-User System. client: waiting for unit network-online.target client: (finished: waiting for unit network-online.target, in 0.02 seconds) server: waiting for unit network-online.target server: (finished: waiting for unit network-online.target, in 0.01 seconds) client: must succeed: ssh -F /dev/null -i /etc/private-test-key -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes root@server true &>/dev/null server # [ 603.796703] server systemd[1]: etc-machine\x2did.mount: Deactivated successfully. server # [ 603.832261] server systemd[1]: Finished Save Transient machine-id to Disk. server # [ 603.837503] server systemd[1]: Startup finished in 8.979s. server # [ 603.953151] server systemd[1]: Reached target Network is Online. server # [ 603.997425] server systemd[1]: Created slice Slice /system/sshd. server # [ 603.997501] server systemd[1]: SSH Host Keys Generation skipped, no trigger condition checks were met. server # [ 603.998452] server systemd[1]: Started SSH per-connection Daemon ([2001:db8:1::1]:47650). client # [ 603.796824] client systemd[1]: etc-machine\x2did.mount: Deactivated successfully. client # [ 603.832269] client systemd[1]: Finished Save Transient machine-id to Disk. client # [ 603.832454] client systemd[1]: Startup finished in 9.040s. client # [ 603.941685] client systemd[1]: Reached target Network is Online. client: (finished: must succeed: ssh -F /dev/null -i /etc/private-test-key -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes root@server true &>/dev/null, in 0.15 seconds) (finished: run the VM test script, in 9.84 seconds) test script finished in 9.90s cleanup kill NspawnMachine (pid 52) kill NspawnMachine (pid 54) Container client terminated by signal KILL. server # [ 604.120347] server sshd-session[255]: Accepted publickey for root from 2001:db8:1::1 port 47650 ssh2: ED25519 SHA256:8t391Em0YyXoWjQ3FBfwMyyV52RJVlM39qcyv1jpWsQ server # [ 604.134036] server sshd-session[259]: Received disconnect from 2001:db8:1::1 port 47650:11: disconnected by user server # [ 604.134206] server sshd-session[259]: Disconnected from user root 2001:db8:1::1 port 47650 server # [ 604.135251] server systemd[1]: sshd@0-1-2001:db8:1::2:22-2001:db8:1::1:47650.service: Deactivated successfully. server # [ 604.312763] server systemd-networkd[206]: eth1: Link DOWN server # [ 604.312789] server systemd-networkd[206]: eth1: Lost carrier server # [ 604.344742] server systemd-networkd[206]: eth1: Lost IPv6LL address fe80::a422:55ff:fe08:b94c. (finished: cleanup, in 0.33 seconds) Container server terminated by signal KILL.