tribuchet: building on jamie Machine state will be reset. To keep it, pass --keep-machine-state start all VLans (finished: start all VLans, in 0.00 seconds) Initializing machine ID from random generator. Test will time out and terminate in 3600.0 seconds run the VM test script start all VMs a: systemd-nspawn running (pid 51) a: Waiting for journal at /build/vm-state-a/var/log/journal... b: systemd-nspawn running (pid 52) b: Waiting for journal at /build/vm-state-b/var/log/journal... (finished: start all VMs, in 0.00 seconds) a: waiting for unit postgresql.target nixos-nspawn(b): TAP vde-tap1 not found; container will be isolated from VDE nixos-nspawn(b): 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(a): TAP vde-tap1 not found; container will be isolated from VDE nixos-nspawn(a): 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 a on /build/vm-state-a. ░ Spawning container b on /build/vm-state-b. b # [279681.312371] b systemd-journald[58]: Journal started b # [279681.312498] b systemd-journald[58]: Runtime Journal (/run/log/journal/a2f349a92ae6486c9ceea50ac19053a4) is 8M, max 4G, 3.9G free. b # [279681.320842] b systemd[1]: Finished Apply Kernel Variables. b # [279681.332579] b systemd[1]: Finished Create Static Device Nodes in /dev gracefully. b # [279681.346267] b systemd[1]: Starting Flush Journal to Persistent Storage... b # [279681.379600] b systemd[1]: Starting Create Static Device Nodes in /dev... b # [279681.387154] b systemd-journald[58]: Time spent on flushing to /var/log/journal/a2f349a92ae6486c9ceea50ac19053a4 is 1.594ms for 6 entries. b # [279681.387154] b systemd-journald[58]: System Journal (/var/log/journal/a2f349a92ae6486c9ceea50ac19053a4) is 512B, max 4G, 3.9G free. b # [279681.396438] b systemd[1]: Finished Create Static Device Nodes in /dev. b # [279681.397202] b systemd[1]: Reached target Preparation for Local File Systems. b # [279681.397319] b systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys b # [279681.411953] b systemd[1]: Finished Flush Journal to Persistent Storage. a # [279681.312370] a systemd-journald[58]: Journal started a # [279681.312495] a systemd-journald[58]: Runtime Journal (/run/log/journal/b0b4a57ddfa04851becb12b5faab3584) is 8M, max 4G, 3.9G free. a # [279681.319554] a systemd[1]: Finished Apply Kernel Variables. a # [279681.330524] a systemd[1]: Finished Create Static Device Nodes in /dev gracefully. a # [279681.342960] a systemd[1]: Starting Flush Journal to Persistent Storage... a # [279681.343691] a systemd[1]: Starting Create Static Device Nodes in /dev... a # [279681.386467] a systemd-journald[58]: Time spent on flushing to /var/log/journal/b0b4a57ddfa04851becb12b5faab3584 is 1.599ms for 6 entries. a # [279681.386467] a systemd-journald[58]: System Journal (/var/log/journal/b0b4a57ddfa04851becb12b5faab3584) is 512B, max 4G, 3.9G free. a # [279681.393339] a systemd[1]: Finished Create Static Device Nodes in /dev. a # [279681.394214] a systemd[1]: Reached target Preparation for Local File Systems. a # [279681.394327] a systemd[1]: Rule-based Manager for Device Events and Files skipped, unmet condition check ConditionPathIsReadWrite=/sys a # [279681.410965] a systemd[1]: Finished Flush Journal to Persistent Storage. a # [279681.476247] a systemd[1]: Finished Firewall. b # [279681.469779] b systemd[1]: Finished Firewall. a # [279682.308380] a systemd[1]: Mounting /run/wrappers... a # [279682.347819] a systemd[1]: Mounted /run/wrappers. a # [279682.348682] a systemd[1]: Reached target Local File Systems. a # [279682.349419] a systemd[1]: Listening on Boot Loader Control Service Socket. a # [279682.350284] a systemd[1]: Starting Create SUID/SGID Wrappers... a # [279682.350315] a systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container a # [279682.351232] a systemd[1]: Starting Save Transient machine-id to Disk... a # [279682.352169] a systemd[1]: Starting Create System Files and Directories... a # [279682.371683] a systemd-tmpfiles[162]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted a # [279682.372141] a systemd-tmpfiles[162]: fchmod() of /var/log/journal failed: Operation not permitted a # [279682.372436] a systemd-tmpfiles[162]: fchmod() of /var/log/journal/b0b4a57ddfa04851becb12b5faab3584 failed: Operation not permitted a # [279682.372772] a systemd-tmpfiles[162]: fchmod() of /run/log/journal failed: Operation not permitted b # [279682.332761] b systemd[1]: Mounting /run/wrappers... b # [279682.362330] b systemd[1]: Mounted /run/wrappers. b # [279682.363498] b systemd[1]: Reached target Local File Systems. b # [279682.364648] b systemd[1]: Listening on Boot Loader Control Service Socket. b # [279682.365873] b systemd[1]: Starting Create SUID/SGID Wrappers... b # [279682.365920] b systemd[1]: Update Boot Loader Random Seed skipped, unmet condition check ConditionVirtualization=!container b # [279682.366862] b systemd[1]: Starting Save Transient machine-id to Disk... b # [279682.368026] b systemd[1]: Starting Create System Files and Directories... b # [279682.391270] b suid-sgid-wrappers-start[169]: chmod: changing permissions of '/run/wrappers/wrappers.nYccLhJY0d/chsh': Operation not permitted b # [279682.421017] b systemd-tmpfiles[162]: Cannot set file attributes for '/var/empty', value=0x00000010, mask=0x00000010, ignoring: Operation not permitted b # [279682.421422] b systemd-tmpfiles[162]: fchmod() of /var/log/journal failed: Operation not permitted b # [279682.421719] b systemd-tmpfiles[162]: fchmod() of /var/log/journal/a2f349a92ae6486c9ceea50ac19053a4 failed: Operation not permitted b # [279682.422057] b systemd-tmpfiles[162]: fchmod() of /run/log/journal failed: Operation not permitted a # [279682.378021] a suid-sgid-wrappers-start[170]: chmod: changing permissions of '/run/wrappers/wrappers.16DCYz7E70/chsh': Operation not permitted a # [279682.385949] a systemd[1]: Finished Create System Files and Directories. a # [279682.418374] a systemd[1]: etc-machine\x2did.mount: Deactivated successfully. a # [279682.428747] a systemd[1]: suid-sgid-wrappers.service: Main process exited, code=exited, status=1/FAILURE a # [279682.428818] a systemd[1]: suid-sgid-wrappers.service: Failed to read pids.max for control group /system.slice/suid-sgid-wrappers.service, ignoring: No data available a # [279682.428861] a systemd[1]: suid-sgid-wrappers.service: Failed to read pids.max for control group /system.slice/suid-sgid-wrappers.service, ignoring: No data available a # [279682.428892] a systemd[1]: suid-sgid-wrappers.service: Failed with result 'exit-code'. a # [279682.429061] a systemd[1]: Failed to start Create SUID/SGID Wrappers. a # [279682.429299] a systemd[1]: Finished Save Transient machine-id to Disk. a # [279682.431989] a systemd[1]: Starting Rebuild Journal Catalog... a # [279682.432852] a systemd[1]: Starting Record System Boot/Shutdown in UTMP... a # [279682.479145] a systemd[1]: Finished Record System Boot/Shutdown in UTMP. a # [279682.485768] a systemd[1]: Finished Rebuild Journal Catalog. a # [279682.487148] a systemd[1]: Starting Update is Completed... a # [279682.498517] a systemd[1]: Finished Update is Completed. a # [279682.498620] a systemd[1]: Reached target System Initialization. a # [279682.498713] a systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container a # [279682.498763] a systemd[1]: Started Daily Cleanup of Temporary Directories. a # [279682.498780] a systemd[1]: Reached target Timer Units. a # [279682.498890] a systemd[1]: Listening on D-Bus System Message Bus Socket. a # [279682.499115] a systemd[1]: Listening on Nix Daemon Socket. a # [279682.499216] a systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. a # [279682.499232] a systemd[1]: Reached target Socket Units. a # [279682.499260] a systemd[1]: Reached target Basic System. a # [279682.500460] a systemd[1]: Starting Re-link flakelet services at boot... a # [279682.501166] a systemd[1]: Starting Import lastlog data into lastlog2 database... a # [279682.502135] a systemd[1]: Starting Name Service Cache Daemon (nsncd)... a # [279682.502815] a systemd[1]: Starting resolvconf update... a # [279682.512622] a systemd[1]: Finished Re-link flakelet services at boot. a # [279682.515120] a systemd[1]: Starting Reconcile flakelet services with the host configuration... a # [279682.522862] a systemd[1]: Finished Import lastlog data into lastlog2 database. a # [279682.527821] a systemd[1]: Finished Reconcile flakelet services with the host configuration. b # [279682.427718] b systemd[1]: etc-machine\x2did.mount: Deactivated successfully. b # [279682.439105] b systemd[1]: suid-sgid-wrappers.service: Main process exited, code=exited, status=1/FAILURE b # [279682.439138] b systemd[1]: suid-sgid-wrappers.service: Failed to read pids.max for control group /system.slice/suid-sgid-wrappers.service, ignoring: No data available b # [279682.439157] b systemd[1]: suid-sgid-wrappers.service: Failed to read pids.max for control group /system.slice/suid-sgid-wrappers.service, ignoring: No data available b # [279682.439169] b systemd[1]: suid-sgid-wrappers.service: Failed with result 'exit-code'. b # [279682.439233] b systemd[1]: Failed to start Create SUID/SGID Wrappers. b # [279682.439388] b systemd[1]: Finished Save Transient machine-id to Disk. b # [279682.467556] b systemd[1]: Finished Create System Files and Directories. b # [279682.481515] b systemd[1]: Starting Rebuild Journal Catalog... b # [279682.482689] b systemd[1]: Starting Record System Boot/Shutdown in UTMP... b # [279682.499354] b systemd[1]: Finished Record System Boot/Shutdown in UTMP. b # [279682.503532] b systemd[1]: Finished Rebuild Journal Catalog. b # [279682.505359] b systemd[1]: Starting Update is Completed... b # [279682.517552] b systemd[1]: Finished Update is Completed. b # [279682.517781] b systemd[1]: Reached target System Initialization. b # [279682.517887] b systemd[1]: Discard unused filesystem blocks once a week skipped, unmet condition check ConditionVirtualization=!container b # [279682.517927] b systemd[1]: Started Daily Cleanup of Temporary Directories. b # [279682.517950] b systemd[1]: Reached target Timer Units. b # [279682.518127] b systemd[1]: Listening on D-Bus System Message Bus Socket. b # [279682.518387] b systemd[1]: Listening on Nix Daemon Socket. b # [279682.518563] b systemd[1]: Listening on Virtual Machine and Container Registration Service Socket. b # [279682.518585] b systemd[1]: Reached target Socket Units. b # [279682.518633] b systemd[1]: Reached target Basic System. b # [279682.520308] b systemd[1]: Starting Re-link flakelet services at boot... b # [279682.521319] b systemd[1]: Starting Import lastlog data into lastlog2 database... b # [279682.522777] b systemd[1]: Starting Name Service Cache Daemon (nsncd)... b # [279682.523860] b systemd[1]: Starting resolvconf update... b # [279682.534571] b systemd[1]: Finished Re-link flakelet services at boot. b # [279682.536062] b systemd[1]: Starting Reconcile flakelet services with the host configuration... b # [279682.542673] b systemd[1]: Finished Import lastlog data into lastlog2 database. b # [279682.546985] b systemd[1]: Finished Reconcile flakelet services with the host configuration. b # [279682.606943] b systemd[1]: nscd.service: Failed to read pids.max for control group /system.slice/nscd.service, ignoring: No data available b # [279682.607023] b systemd[1]: nscd.service: Deactivated successfully. b # [279682.624253] b systemd[1]: Stopped Name Service Cache Daemon (nsncd). b # [279682.627099] b systemd[1]: Finished resolvconf update. b # [279682.628554] b systemd[1]: Reached target Preparation for Network. b # [279682.630091] b systemd[1]: Starting Address configuration of eth1... b # [279682.631637] b systemd[1]: Starting Extra networking commands.... b # [279682.633183] b systemd[1]: Starting Name Service Cache Daemon (nsncd)... b # [279682.650589] b network-addresses-eth1-start[241]: adding address 192.168.1.2/24... done b # [279682.653714] b network-addresses-eth1-start[241]: adding address 2001:db8:1::2/64... done b # [279682.658310] b systemd[1]: Finished Address configuration of eth1. b # [279682.703380] b systemd[1]: Finished Extra networking commands.. b # [279682.703501] b systemd[1]: Reached target Network. b # [279682.704712] b systemd[1]: Starting PostgreSQL Server... a # [279682.584523] a systemd[1]: nscd.service: Failed to read pids.max for control group /system.slice/nscd.service, ignoring: No data available a # [279682.584557] a systemd[1]: nscd.service: Deactivated successfully. a # [279682.584677] a systemd[1]: Stopped Name Service Cache Daemon (nsncd). a # [279682.587353] a systemd[1]: Starting Name Service Cache Daemon (nsncd)... a # [279682.624243] a systemd[1]: Finished resolvconf update. a # [279682.624533] a systemd[1]: Reached target Preparation for Network. a # [279682.625846] a systemd[1]: Starting Address configuration of eth1... a # [279682.626951] a systemd[1]: Starting Extra networking commands.... a # [279682.647151] a network-addresses-eth1-start[243]: adding address 192.168.1.1/24... done a # [279682.651441] a network-addresses-eth1-start[243]: adding address 2001:db8:1::1/64... done a # [279682.657148] a systemd[1]: Finished Address configuration of eth1. a # [279682.698497] a systemd[1]: Finished Extra networking commands.. a # [279682.699197] a systemd[1]: Reached target Network. a # [279682.700764] a systemd[1]: Starting PostgreSQL Server... a # [279682.884989] a nsncd[239]: Oct 29 15:36:38.929 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" a # [279682.884920] a systemd[1]: Started Name Service Cache Daemon (nsncd). a # [279682.884992] a systemd[1]: Reached target Host and Network Name Lookups. a # [279682.885123] a systemd[1]: Reached target User and Group Name Lookups. a # [279682.886634] a systemd[1]: Starting User Login Management... a # [279682.887450] a systemd[1]: Starting Permit User Sessions... a # [279682.927736] a systemd[1]: Finished Permit User Sessions. a # [279682.928950] a systemd[1]: Started Console Getty. a # [279682.928976] a systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 a # [279682.928991] a systemd[1]: Reached target Login Prompts. b # [279682.882730] b nsncd[243]: Oct 29 15:36:38.927 INFO started, config: Config { ignored_request_types: {}, worker_count: 8, handoff_timeout: 10s }, path: "/var/run/nscd/socket" b # [279682.882792] b systemd[1]: Started Name Service Cache Daemon (nsncd). b # [279682.882894] b systemd[1]: Reached target Host and Network Name Lookups. b # [279682.883018] b systemd[1]: Reached target User and Group Name Lookups. b # [279682.885646] b systemd[1]: Starting User Login Management... b # [279682.887074] b systemd[1]: Starting Permit User Sessions... b # [279682.923530] b systemd[1]: Finished Permit User Sessions. b # [279682.926531] b systemd[1]: Started Console Getty. b # [279682.926587] b systemd[1]: Getty on tty1 skipped, unmet condition check ConditionPathExists=/dev/tty0 b # [279682.926622] b systemd[1]: Reached target Login Prompts. a # [279683.975284] a systemd-logind[315]: New seat seat0. a # [279683.976068] a systemd[1]: Started User Login Management. a # [279684.000138] a systemd[1]: Starting D-Bus System Message Bus... a # [279684.001344] a systemd[1]: Starting linger-users.service... a # [279684.024873] a systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available a # [279684.024924] a systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available a # [279684.024969] a systemd[1]: linger-users.service: Deactivated successfully. a # [279684.025130] a systemd[1]: Finished linger-users.service. a # [279684.111159] a postgresql-pre-start[330]: The files belonging to this database system will be owned by user "postgres". a # [279684.111159] a postgresql-pre-start[330]: This user must also own the server process. a # [279684.111930] a postgresql-pre-start[330]: The database cluster will be initialized with locale "en_US.UTF-8". a # [279684.111930] a postgresql-pre-start[330]: The default database encoding has accordingly been set to "UTF8". a # [279684.111930] a postgresql-pre-start[330]: The default text search configuration will be set to "english". a # [279684.111930] a postgresql-pre-start[330]: Data page checksums are enabled. a # [279684.111930] a postgresql-pre-start[330]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok a # [279684.112646] a postgresql-pre-start[330]: creating subdirectories ... ok a # [279684.112798] a postgresql-pre-start[330]: selecting dynamic shared memory implementation ... posix a # [279684.135700] a postgresql-pre-start[330]: selecting default "max_connections" ... 100 a # [279684.163605] a postgresql-pre-start[330]: selecting default "shared_buffers" ... 128MB b # [279683.969111] b systemd-logind[315]: New seat seat0. b # [279683.970109] b systemd[1]: Starting D-Bus System Message Bus... b # [279683.970312] b systemd[1]: Started User Login Management. b # [279683.971432] b systemd[1]: Starting linger-users.service... b # [279683.994609] b postgresql-pre-start[326]: The files belonging to this database system will be owned by user "postgres". b # [279683.994609] b postgresql-pre-start[326]: This user must also own the server process. b # [279683.995313] b postgresql-pre-start[326]: The database cluster will be initialized with locale "en_US.UTF-8". b # [279683.995313] b postgresql-pre-start[326]: The default database encoding has accordingly been set to "UTF8". b # [279683.995313] b postgresql-pre-start[326]: The default text search configuration will be set to "english". b # [279683.995313] b postgresql-pre-start[326]: Data page checksums are enabled. b # [279683.995313] b postgresql-pre-start[326]: fixing permissions on existing directory /var/lib/postgresql/18 ... ok b # [279683.996168] b postgresql-pre-start[326]: creating subdirectories ... ok b # [279683.996316] b postgresql-pre-start[326]: selecting dynamic shared memory implementation ... posix b # [279684.009409] b systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available b # [279684.009457] b systemd[1]: linger-users.service: Failed to read pids.max for control group /system.slice/linger-users.service, ignoring: No data available b # [279684.009488] b systemd[1]: linger-users.service: Deactivated successfully. b # [279684.009672] b systemd[1]: Finished linger-users.service. b # [279684.022590] b postgresql-pre-start[326]: selecting default "max_connections" ... 100 b # [279684.051434] b postgresql-pre-start[326]: selecting default "shared_buffers" ... 128MB b # [279684.364319] b dbus-broker-launch[327]: Looking up NSS user entry for 'systemd-timesync'... a # [279684.360337] a dbus-broker-launch[325]: Looking up NSS user entry for 'systemd-timesync'... a # [279684.364042] a dbus-broker-launch[325]: NSS returned no entry for 'systemd-timesync' a # [279684.364042] a dbus-broker-launch[325]: Invalid user-name in /nix/store/mvl79r6dv02smjnd8gvrxxy96a1ip98k-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" a # [279684.365414] a systemd[1]: Started D-Bus System Message Bus. a # [279684.373843] a dbus-broker-launch[325]: Ready a # [279684.486255] a postgresql-pre-start[330]: selecting default time zone ... UTC a # [279684.487282] a postgresql-pre-start[330]: creating configuration files ... ok a # [279684.618218] a postgresql-pre-start[330]: running bootstrap script ... ok b # [279684.365732] b dbus-broker-launch[327]: NSS returned no entry for 'systemd-timesync' b # [279684.365732] b dbus-broker-launch[327]: Invalid user-name in /nix/store/mvl79r6dv02smjnd8gvrxxy96a1ip98k-system-path/share/dbus-1/system.d/org.freedesktop.timesync1.conf +16: user="systemd-timesync" b # [279684.366798] b systemd[1]: Started D-Bus System Message Bus. b # [279684.373920] b dbus-broker-launch[327]: Ready b # [279684.400195] b postgresql-pre-start[326]: selecting default time zone ... UTC b # [279684.401186] b postgresql-pre-start[326]: creating configuration files ... ok b # [279684.527896] b postgresql-pre-start[326]: running bootstrap script ... ok b # [279684.867227] b postgresql-pre-start[326]: performing post-bootstrap initialization ... ok a # [279684.966245] a postgresql-pre-start[330]: performing post-bootstrap initialization ... ok b # [279685.224340] b postgresql-pre-start[326]: syncing data to disk ... ok b # [279685.224340] b postgresql-pre-start[326]: initdb: warning: enabling "trust" authentication for local connections b # [279685.224340] b postgresql-pre-start[326]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb. b # [279685.224340] b postgresql-pre-start[326]: Success. You can now start the database server using: b # [279685.224340] b postgresql-pre-start[326]: pg_ctl -D /var/lib/postgresql/18 -l logfile start a # [279685.322734] a postgresql-pre-start[330]: syncing data to disk ... ok a # [279685.322734] a postgresql-pre-start[330]: initdb: warning: enabling "trust" authentication for local connections a # [279685.322734] a postgresql-pre-start[330]: initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb. a # [279685.322734] a postgresql-pre-start[330]: Success. You can now start the database server using: a # [279685.322734] a postgresql-pre-start[330]: pg_ctl -D /var/lib/postgresql/18 -l logfile start b # [279686.294522] b postgres[344]: [344] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit b # [279686.296824] b postgres[344]: [344] LOG: listening on IPv6 address "::1", port 5432 b # [279686.296955] b postgres[344]: [344] LOG: listening on IPv4 address "127.0.0.1", port 5432 b # [279686.297427] b postgres[344]: [344] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432" b # [279686.303099] b postgres[353]: [353] LOG: database system was shut down at 2026-10-29 15:36:40 GMT b # [279686.307268] b postgres[344]: [344] LOG: database system is ready to accept connections b # [279686.307971] b systemd[1]: Started PostgreSQL Server. b # [279686.310329] b systemd[1]: Starting PostgreSQL Setup Scripts... b # [279686.385938] b systemd[1]: Finished PostgreSQL Setup Scripts. b # [279686.386605] b systemd[1]: Reached target PostgreSQL. b # [279686.386803] b systemd[1]: Reached target flakelet contract providers ready. b # [279686.388708] b systemd[1]: Starting Update flakelet service web... b # [279686.435635] b flakelet[362]: web: using prebuilt artifact /nix/store/hpzr1hm2j0h7mvfcs76fq9fz2z4nbvf4-flakelet-web b # [279686.436266] b flakelet[362]: web: requires.postgres: provisioning via /nix/store/znfschrqf30ml2wzf1zyxv8zpdrmrlxx-flakelet-postgres-provision/bin/flakelet-postgres-provision b # [279686.453211] b runuser[366]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279686.538294] b runuser[366]: pam_unix(runuser:session): session closed for user postgres b # [279686.540916] b flakelet[362]: web: activating generation 1 b # [279686.546919] b systemd[1]: Reload requested from client PID 369 ('systemctl') (unit flakelet-web.service)... b # [279686.547020] b systemd[1]: Reloading... a # [279686.396102] a postgres[344]: [344] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit a # [279686.397277] a postgres[344]: [344] LOG: listening on IPv6 address "::1", port 5432 a # [279686.397277] a postgres[344]: [344] LOG: listening on IPv4 address "127.0.0.1", port 5432 a # [279686.397791] a postgres[344]: [344] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432" a # [279686.402691] a postgres[353]: [353] LOG: database system was shut down at 2026-10-29 15:36:40 GMT a # [279686.406146] a postgres[344]: [344] LOG: database system is ready to accept connections a # [279686.406858] a systemd[1]: Started PostgreSQL Server. a # [279686.426092] a systemd[1]: Starting PostgreSQL Setup Scripts... a # [279686.459424] a systemd[1]: Finished PostgreSQL Setup Scripts. a # [279686.459725] a systemd[1]: Reached target PostgreSQL. a # [279686.459818] a systemd[1]: Reached target flakelet contract providers ready. a # [279686.460855] a systemd[1]: Starting Update flakelet service web... a # [279686.474222] a flakelet[362]: web: using prebuilt artifact /nix/store/hpzr1hm2j0h7mvfcs76fq9fz2z4nbvf4-flakelet-web a # [279686.474664] a flakelet[362]: web: requires.postgres: provisioning via /nix/store/znfschrqf30ml2wzf1zyxv8zpdrmrlxx-flakelet-postgres-provision/bin/flakelet-postgres-provision a # [279686.487943] a runuser[366]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) a # [279686.571509] a runuser[366]: pam_unix(runuser:session): session closed for user postgres a # [279686.573734] a flakelet[362]: web: activating generation 1 a # [279686.578710] a systemd[1]: Reload requested from client PID 369 ('systemctl') (unit flakelet-web.service)... a # [279686.578791] a systemd[1]: Reloading... b # [279686.850012] b systemd[1]: Reloading finished in 302 ms. b # [279687.021832] b systemd[1]: Reload requested from client PID 399 ('systemctl') (unit flakelet-web.service)... b # [279687.021902] b systemd[1]: Reloading... a # [279686.849285] a systemd[1]: Reloading finished in 269 ms. a # [279687.015828] a systemd[1]: Reload requested from client PID 399 ('systemctl') (unit flakelet-web.service)... a # [279687.015889] a systemd[1]: Reloading... a: (finished: waiting for unit postgresql.target, in 7.16 seconds) ??? Warning (UserWarning): wait_for_unit(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/nnab7wdwimd0gr2jj9xc8bi3rbkzkzjh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 a: waiting for unit web.service a: (finished: waiting for unit web.service, in 0.02 seconds) a: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d postgres -c 'SELECT 1 FROM pg_database WHERE datname='\''web'\''' | grep -q 1 b # [279687.290396] b systemd[1]: Reloading finished in 267 ms. b # [279687.424951] b systemd[1]: Starting web.service... b # [279687.458036] b systemd[1]: Started web.service. b # [279687.465316] b flakelet[362]: web: updated to generation 1 b # [279687.467248] b systemd[1]: Finished Update flakelet service web. b # [279687.467875] b systemd[1]: Reached target flakelet managed services. b # [279687.468108] b systemd[1]: Reached target Multi-User System. b # [279687.468405] b systemd[1]: Startup finished in 6.526s. a # [279687.286419] a systemd[1]: Reloading finished in 269 ms. a # [279687.422274] a systemd[1]: Starting web.service... a # [279687.457818] a systemd[1]: Started web.service. a # [279687.465819] a flakelet[362]: web: updated to generation 1 a # [279687.467756] a systemd[1]: Finished Update flakelet service web. a # [279687.468642] a systemd[1]: Reached target flakelet managed services. a # [279687.468908] a systemd[1]: Reached target Multi-User System. a # [279687.469199] a systemd[1]: Startup finished in 6.527s. a: (finished: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d postgres -c 'SELECT 1 FROM pg_database WHERE datname='\''web'\''' | grep -q 1, in 0.03 seconds) a: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'CREATE TABLE t(v text); INSERT INTO t VALUES ('\''payload'\'')' a: (finished: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'CREATE TABLE t(v text); INSERT INTO t VALUES ('\''payload'\'')', in 0.02 seconds) a: must succeed: flakelet export web --dry-run >&2 { "version": 1, "flakelet_version": "0.1.0", "name": "web", "source_host": "a", "created": 1793288203, "flake": "", "output": "flakelets.default", "flake_url": "prebuilt:web", "flake_rev": "", "settings_hash": "44136fa355b3678a1146ad16f7e8649e94fb4fc21fe77e8310c060f61caaff8a", "state": { "folders": [ { "path": "/var/lib/web", "user": "web", "group": null, "dynamic": false } ], "dump": null, "restore": null }, "exports": { "requires": { "postgres": { "database": "web" } } }, "consistency": "stopped" } a: (finished: must succeed: flakelet export web --dry-run >&2, in 0.01 seconds) a: must succeed: flakelet export web --to b > /tmp/shared/web.tar.zst web: stopping units requires.postgres: running /nix/store/yi51jng5aj5cn8g8jmgjrbqdarjgr1s0-flakelet-postgres-dump/bin/flakelet-postgres-dump web: archiving /var/lib/web a # [279687.639145] a runuser[436]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) a # [279687.652187] a runuser[436]: pam_unix(runuser:session): session closed for user postgres a # [279687.663086] a runuser[440]: pam_unix(runuser:session): session opened for user web(uid=996) by (uid=0) a # [279687.677730] a runuser[440]: pam_unix(runuser:session): session closed for user web a # [279687.710891] a systemd[1]: Stopping web.service... a # [279687.711298] a systemd[1]: web.service: Failed to read pids.max for control group /system.slice/web.service, ignoring: No data available a # [279687.711359] a systemd[1]: web.service: Deactivated successfully. a # [279687.711563] a systemd[1]: Stopped web.service. a # [279687.730149] a runuser[453]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) a # [279687.781218] a runuser[453]: pam_unix(runuser:session): session closed for user postgres a # [279687.827174] a systemd[1]: Reload requested from client PID 468 ('systemctl')... a # [279687.827246] a systemd[1]: Reloading... a # [279688.089715] a systemd[1]: Reloading finished in 261 ms. a # [279688.174940] a systemd[1]: Reload requested from client PID 497 ('systemctl')... a # [279688.174982] a systemd[1]: Reloading... web: disabled here, 'flakelet enable web' undoes that a: (finished: must succeed: flakelet export web --to b > /tmp/shared/web.tar.zst, in 0.83 seconds) a: must fail: systemctl is-active web.service a: (finished: must fail: systemctl is-active web.service, in 0.01 seconds) a: must succeed: tar --zstd -tf /tmp/shared/web.tar.zst | grep -q requires/postgres/db.pgdump a: (finished: must succeed: tar --zstd -tf /tmp/shared/web.tar.zst | grep -q requires/postgres/db.pgdump, in 0.01 seconds) b: waiting for unit postgresql.target b: (finished: waiting for unit postgresql.target, in 0.02 seconds) b: waiting for unit web.service b: (finished: waiting for unit web.service, in 0.02 seconds) ??? Warning (UserWarning): succeed(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/nnab7wdwimd0gr2jj9xc8bi3rbkzkzjh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 b: must succeed: flakelet import - < /tmp/shared/web.tar.zst >&2 ??? Warning (UserWarning): execute(): passing a bare int/float as a duration is deprecated. Use datetime.timedelta instead. File "/nix/store/nnab7wdwimd0gr2jj9xc8bi3rbkzkzjh-nixos-test-driver-1.1/lib/python3.14/site-packages/test_driver/duration.py", line 39 web: using prebuilt artifact /nix/store/hpzr1hm2j0h7mvfcs76fq9fz2z4nbvf4-flakelet-web a # [279688.422196] a systemd[1]: Reloading finished in 246 ms. b # [279688.612798] b systemd[1]: Stopping web.service... b # [279688.614433] b systemd[1]: web.service: Failed to read pids.max for control group /system.slice/web.service, ignoring: No data available b # [279688.614491] b systemd[1]: web.service: Deactivated successfully. b # [279688.614752] b systemd[1]: Stopped web.service. b # [279688.631089] b systemd[1]: Reload requested from client PID 448 ('systemctl')... b # [279688.631157] b systemd[1]: Reloading... b # [279688.892977] b systemd[1]: Reloading finished in 261 ms. b # [279688.991400] b systemd[1]: Reload requested from client PID 477 ('systemctl')... b # [279688.991441] b systemd[1]: Reloading... b # [279689.241289] b systemd[1]: Reloading finished in 249 ms. web: restoring /var/lib/web requires.postgres: running /nix/store/c9rf88nplna0k28pn24kwa7imva8halg-flakelet-postgres-restore/bin/flakelet-postgres-restore web: requires.postgres: provisioning via /nix/store/znfschrqf30ml2wzf1zyxv8zpdrmrlxx-flakelet-postgres-provision/bin/flakelet-postgres-provision web: activating generation 2 b # [279689.358646] b runuser[513]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279689.372784] b runuser[513]: pam_unix(runuser:session): session closed for user postgres b # [279689.377817] b runuser[516]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279689.391897] b runuser[516]: pam_unix(runuser:session): session closed for user postgres b # [279689.396441] b runuser[519]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279689.413991] b runuser[519]: pam_unix(runuser:session): session closed for user postgres b # [279689.432147] b runuser[525]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279689.444857] b runuser[525]: pam_unix(runuser:session): session closed for user postgres b # [279689.452268] b systemd[1]: Reload requested from client PID 528 ('systemctl')... b # [279689.452349] b systemd[1]: Reloading... b # [279689.730604] b systemd[1]: Reloading finished in 277 ms. b # [279689.823237] b systemd[1]: Reload requested from client PID 557 ('systemctl')... b # [279689.823277] b systemd[1]: Reloading... b # [279690.067185] b systemd[1]: Reloading finished in 243 ms. web: imported as generation 2 b: (finished: must succeed: flakelet import - < /tmp/shared/web.tar.zst >&2, in 1.61 seconds) b: must succeed: systemctl is-active web.service b: (finished: must succeed: systemctl is-active web.service, in 0.01 seconds) b: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT v FROM t' | grep -qx payload b: (finished: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT v FROM t' | grep -qx payload, in 0.02 seconds) b: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT tableowner FROM pg_tables WHERE tablename='\''t'\''' | grep -qx web b: (finished: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT tableowner FROM pg_tables WHERE tablename='\''t'\''' | grep -qx web, in 0.02 seconds) b: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d postgres -c 'SELECT shobj_description(oid, '\''pg_database'\'') FROM pg_database WHERE datname='\''web'\''' | grep -q flakelet b: (finished: must succeed: runuser -u postgres -- psql -qtAX -v ON_ERROR_STOP=1 -d postgres -c 'SELECT shobj_description(oid, '\''pg_database'\'') FROM pg_database WHERE datname='\''web'\''' | grep -q flakelet, in 0.02 seconds) b: must fail: flakelet import /tmp/shared/web.tar.zst >&2 web: using prebuilt artifact /nix/store/hpzr1hm2j0h7mvfcs76fq9fz2z4nbvf4-flakelet-web b # [279690.154123] b systemd[1]: Starting web.service... b # [279690.177950] b systemd[1]: Started web.service. b # [279690.211646] b runuser[591]: pam_unix(runuser:session): session opened for user web(uid=996) by (uid=0) b # [279690.223956] b runuser[591]: pam_unix(runuser:session): session closed for user web b # [279690.235766] b runuser[596]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279690.248250] b runuser[596]: pam_unix(runuser:session): session closed for user postgres b # [279690.258703] b runuser[601]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279690.270042] b runuser[601]: pam_unix(runuser:session): session closed for user postgres b # [279690.308510] b systemd[1]: Stopping web.service... b # [279690.310255] b systemd[1]: web.service: Failed to read pids.max for control group /system.slice/web.service, ignoring: No data available b # [279690.310343] b systemd[1]: web.service: Deactivated successfully. b # [279690.310688] b systemd[1]: Stopped web.service. b # [279690.327137] b systemd[1]: Reload requested from client PID 617 ('systemctl')... b # [279690.327207] b systemd[1]: Reloading... b # [279690.594481] b systemd[1]: Reloading finished in 266 ms. b # [279690.681297] b systemd[1]: Reload requested from client PID 646 ('systemctl')... b # [279690.681337] b systemd[1]: Reloading... web: restoring /var/lib/web requires.postgres: running /nix/store/c9rf88nplna0k28pn24kwa7imva8halg-flakelet-postgres-restore/bin/flakelet-postgres-restore error: /nix/store/c9rf88nplna0k28pn24kwa7imva8halg-flakelet-postgres-restore/bin/flakelet-postgres-restore /var/cache/flakelet/.tmpk5Kex9/requires/postgres/claim.json /var/cache/flakelet/.tmpk5Kex9/requires/postgres failed: flakelet-postgres-restore: database web is not empty, refusing b: (finished: must fail: flakelet import /tmp/shared/web.tar.zst >&2, in 0.82 seconds) b: must fail: systemctl is-active web.service b: (finished: must fail: systemctl is-active web.service, in 0.01 seconds) b: must succeed: flakelet import --replace /tmp/shared/web.tar.zst >&2 web: using prebuilt artifact /nix/store/hpzr1hm2j0h7mvfcs76fq9fz2z4nbvf4-flakelet-web b # [279690.935346] b systemd[1]: Reloading finished in 253 ms. b # [279691.053974] b runuser[682]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.067705] b runuser[682]: pam_unix(runuser:session): session closed for user postgres b # [279691.072585] b runuser[685]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.084796] b runuser[685]: pam_unix(runuser:session): session closed for user postgres b # [279691.139991] b systemd[1]: Reload requested from client PID 700 ('systemctl')... b # [279691.140039] b systemd[1]: Reloading... web: restoring /var/lib/web requires.postgres: running /nix/store/c9rf88nplna0k28pn24kwa7imva8halg-flakelet-postgres-restore/bin/flakelet-postgres-restore b # [279691.392008] b systemd[1]: Reloading finished in 251 ms. b # [279691.491623] b runuser[733]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.503279] b postgres[351]: [351] LOG: checkpoint starting: immediate force wait b # [279691.513556] b postgres[351]: [351] LOG: checkpoint complete: wrote 14 buffers (0.1%), wrote 3 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.004 s, total=0.011 s; sync files=14, longest=0.001 s, average=0.001 s; distance=4387 kB, estimate=4387 kB; lsn=0/1BAED90, redo lsn=0/1BAED38 b # [279691.532553] b runuser[733]: pam_unix(runuser:session): session closed for user postgres b # [279691.551525] b runuser[739]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.601571] b runuser[739]: pam_unix(runuser:session): session closed for user postgres b # [279691.608163] b runuser[742]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.624381] b runuser[742]: pam_unix(runuser:session): session closed for user postgres b # [279691.629447] b runuser[745]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.643117] b runuser[745]: pam_unix(runuser:session): session closed for user postgres web: requires.postgres: provisioning via /nix/store/znfschrqf30ml2wzf1zyxv8zpdrmrlxx-flakelet-postgres-provision/bin/flakelet-postgres-provision web: activating generation 3 b # [279691.660635] b runuser[751]: pam_unix(runuser:session): session opened for user postgres(uid=71) by (uid=0) b # [279691.673253] b runuser[751]: pam_unix(runuser:session): session closed for user postgres b # [279691.681377] b systemd[1]: Reload requested from client PID 754 ('systemctl')... b # [279691.681458] b systemd[1]: Reloading... b # [279691.979366] b systemd[1]: Reloading finished in 297 ms. b # [279692.069452] b systemd[1]: Reload requested from client PID 783 ('systemctl')... b # [279692.069491] b systemd[1]: Reloading... b # [279692.320273] b systemd[1]: Reloading finished in 250 ms. web: imported as generation 3 b: (finished: must succeed: flakelet import --replace /tmp/shared/web.tar.zst >&2, in 1.33 seconds) b: must succeed: systemctl is-active web.service b: (finished: must succeed: systemctl is-active web.service, in 0.01 seconds) b: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT v FROM t' | grep -qx payload b: (finished: must succeed: runuser -u web -- psql -qtAX -v ON_ERROR_STOP=1 -d web -c 'SELECT v FROM t' | grep -qx payload, in 0.02 seconds) (finished: run the VM test script, in 12.03 seconds) test script finished in 12.06s cleanup kill NspawnMachine (pid 51) kill NspawnMachine (pid 52) b # [279692.397349] b systemd[1]: Starting web.service... b # [279692.429528] b systemd[1]: Started web.service. b # [279692.463139] b runuser[817]: pam_unix(runuser:session): session opened for user web(uid=996) by (uid=0) b # [279692.474134] b runuser[817]: pam_unix(runuser:session): session closed for user web Container a terminated by signal KILL. Container b terminated by signal KILL. (finished: cleanup, in 0.28 seconds) additionally exposed symbols: a, b, 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